Merge pull request #506 from kanoi/master

optional lock reporting in the API and klondike work redesign

API-README

@@ -437,6 +437,12 @@ The list of requests - a (*) means it requires privileged access - and replies:
                                AVA+BTB opt=freq val=256 to 1024 - chip frequency
                                BTB opt=millivolts val=1000 to 1400 - corevoltage
 
+ lockstats     none           There is no reply section just the STATUS section
+                              stating the results of the request
+                              A warning reply means lock stats are not compiled
+                              into cgminer
+                              The API writes all the lock stats to stderr
+
 When you enable, disable or restart a GPU, PGA or ASC, you will also get
 Thread messages in the cgminer status window
 
@@ -491,6 +497,13 @@ miner.php - an example web page to access the API
 Feature Changelog for external applications using the API:
 
 
+API V1.31 (cgminer v3.6.3)
+
+Added API command:
+ 'lockstats' - display cgminer dev lock stats if compiled in
+
+---------
+
 API V1.30 (cgminer v3.4.3)
 
 Added API command:

api.c

@@ -136,7 +136,7 @@ static const char SEPARATOR = '|';
 #define SEPSTR "|"
 static const char GPUSEP = ',';
 
-static const char *APIVERSION = "1.30";
+static const char *APIVERSION = "1.31";
 static const char *DEAD = "Dead";
 #if defined(HAVE_OPENCL) || defined(HAVE_AN_FPGA) || defined(HAVE_AN_ASIC)
 static const char *SICK = "Sick";
@@ -425,6 +425,8 @@ static const char *JSON_PARAMETER = "parameter";
 
 #define MSG_INVNEG 121
 #define MSG_SETQUOTA 122
+#define MSG_LOCKOK 123
+#define MSG_LOCKDIS 124
 
 enum code_severity {
 	SEVERITY_ERR,
@@ -629,6 +631,8 @@ struct CODES {
  { SEVERITY_SUCC,  MSG_ASCSETOK, PARAM_BOTH,	"ASC %d set OK" },
  { SEVERITY_ERR,   MSG_ASCSETERR, PARAM_BOTH,	"ASC %d set failed: %s" },
 #endif
+ { SEVERITY_SUCC,  MSG_LOCKOK,	PARAM_NONE,	"Lock stats created" },
+ { SEVERITY_WARN,  MSG_LOCKDIS,	PARAM_NONE,	"Lock stats not enabled" },
  { SEVERITY_FAIL, 0, 0, NULL }
 };
 
@@ -1426,6 +1430,399 @@ static void message(struct io_data *io_data, int messageid, int paramid, char *p
 		io_add(io_data, JSON_CLOSE);
 }
 
+#if LOCK_TRACKING
+
+#define LOCK_FMT_FFL " - called from %s %s():%d"
+
+#define LOCKMSG(fmt, ...)	fprintf(stderr, "APILOCK: " fmt "\n", ##__VA_ARGS__)
+#define LOCKMSGMORE(fmt, ...)	fprintf(stderr, "          " fmt "\n", ##__VA_ARGS__)
+#define LOCKMSGFFL(fmt, ...) fprintf(stderr, "APILOCK: " fmt LOCK_FMT_FFL "\n", ##__VA_ARGS__, file, func, linenum)
+#define LOCKMSGFLUSH() fflush(stderr)
+
+typedef struct lockstat {
+	uint64_t lock_id;
+	const char *file;
+	const char *func;
+	int linenum;
+	struct timeval tv;
+} LOCKSTAT;
+
+typedef struct lockline {
+	struct lockline *prev;
+	struct lockstat *stat;
+	struct lockline *next;
+} LOCKLINE;
+
+typedef struct lockinfo {
+	void *lock;
+	enum cglock_typ typ;
+	const char *file;
+	const char *func;
+	int linenum;
+	uint64_t gets;
+	uint64_t gots;
+	uint64_t tries;
+	uint64_t dids;
+	uint64_t didnts; // should be tries - dids
+	uint64_t unlocks;
+	LOCKSTAT lastgot;
+	LOCKLINE *lockgets;
+	LOCKLINE *locktries;
+} LOCKINFO;
+
+typedef struct locklist {
+	LOCKINFO *info;
+	struct locklist *next;
+} LOCKLIST;
+
+static uint64_t lock_id = 1;
+
+static LOCKLIST *lockhead;
+
+static void lockmsgnow()
+{
+	struct timeval now;
+	struct tm *tm;
+	time_t dt;
+
+	cgtime(&now);
+
+	dt = now.tv_sec;
+	tm = localtime(&dt);
+
+	LOCKMSG("%d-%02d-%02d %02d:%02d:%02d",
+		tm->tm_year + 1900,
+		tm->tm_mon + 1,
+		tm->tm_mday,
+		tm->tm_hour,
+		tm->tm_min,
+		tm->tm_sec);
+}
+
+static LOCKLIST *newlock(void *lock, enum cglock_typ typ, const char *file, const char *func, const int linenum)
+{
+	LOCKLIST *list;
+
+	list = calloc(1, sizeof(*list));
+	if (!list)
+		quithere(1, "OOM list");
+	list->info = calloc(1, sizeof(*(list->info)));
+	if (!list->info)
+		quithere(1, "OOM info");
+	list->next = lockhead;
+	lockhead = list;
+
+	list->info->lock = lock;
+	list->info->typ = typ;
+	list->info->file = file;
+	list->info->func = func;
+	list->info->linenum = linenum;
+
+	return list;
+}
+
+static LOCKINFO *findlock(void *lock, enum cglock_typ typ, const char *file, const char *func, const int linenum)
+{
+	LOCKLIST *look;
+
+	look = lockhead;
+	while (look) {
+		if (look->info->lock == lock)
+			break;
+		look = look->next;
+	}
+
+	if (!look)
+		look = newlock(lock, typ, file, func, linenum);
+
+	return look->info;
+}
+
+static void addgettry(LOCKINFO *info, uint64_t id, const char *file, const char *func, const int linenum, bool get)
+{
+	LOCKSTAT *stat;
+	LOCKLINE *line;
+
+	stat = calloc(1, sizeof(*stat));
+	if (!stat)
+		quithere(1, "OOM stat");
+	line = calloc(1, sizeof(*line));
+	if (!line)
+		quithere(1, "OOM line");
+
+	if (get)
+		info->gets++;
+	else
+		info->tries++;
+
+	stat->lock_id = id;
+	stat->file = file;
+	stat->func = func;
+	stat->linenum = linenum;
+	cgtime(&stat->tv);
+
+	line->stat = stat;
+
+	if (get) {
+		line->next = info->lockgets;
+		if (info->lockgets)
+			info->lockgets->prev = line;
+		info->lockgets = line;
+	} else {
+		line->next = info->locktries;
+		if (info->locktries)
+			info->locktries->prev = line;
+		info->locktries = line;
+	}
+}
+
+static void markgotdid(LOCKINFO *info, uint64_t id, const char *file, const char *func, const int linenum, bool got, int ret)
+{
+	LOCKLINE *line;
+
+	if (got)
+		info->gots++;
+	else {
+		if (ret == 0)
+			info->dids++;
+		else
+			info->didnts++;
+	}
+
+	if (got || ret == 0) {
+		info->lastgot.lock_id = id;
+		info->lastgot.file = file;
+		info->lastgot.func = func;
+		info->lastgot.linenum = linenum;
+		cgtime(&info->lastgot.tv);
+	}
+
+	if (got)
+		line = info->lockgets;
+	else
+		line = info->locktries;
+	while (line) {
+		if (line->stat->lock_id == id)
+			break;
+		line = line->next;
+	}
+
+	if (!line) {
+		lockmsgnow();
+		LOCKMSGFFL("ERROR attempt to mark a lock as '%s' that wasn't '%s' id=%"PRIu64,
+				got ? "got" : "did/didnt", got ? "get" : "try", id);
+	}
+
+	// Unlink it
+	if (line->prev)
+		line->prev->next = line->next;
+	if (line->next)
+		line->next->prev = line->prev;
+
+	if (got) {
+		if (info->lockgets == line)
+			info->lockgets = line->next;
+	} else {
+		if (info->locktries == line)
+			info->locktries = line->next;
+	}
+
+	free(line->stat);
+	free(line);
+}
+
+// Yes this uses locks also ... ;/
+static void locklock()
+{
+	if (unlikely(pthread_mutex_lock(&lockstat_lock)))
+		quithere(1, "WTF MUTEX ERROR ON LOCK! errno=%d", errno);
+}
+
+static void lockunlock()
+{
+	if (unlikely(pthread_mutex_unlock(&lockstat_lock)))
+		quithere(1, "WTF MUTEX ERROR ON UNLOCK! errno=%d", errno);
+}
+
+uint64_t api_getlock(void *lock, const char *file, const char *func, const int linenum)
+{
+	LOCKINFO *info;
+	uint64_t id;
+
+	locklock();
+
+	info = findlock(lock, CGLOCK_UNKNOWN, file, func, linenum);
+	id = lock_id++;
+	addgettry(info, id, file, func, linenum, true);
+
+	lockunlock();
+
+	return id;
+}
+
+void api_gotlock(uint64_t id, void *lock, const char *file, const char *func, const int linenum)
+{
+	LOCKINFO *info;
+
+	locklock();
+
+	info = findlock(lock, CGLOCK_UNKNOWN, file, func, linenum);
+	markgotdid(info, id, file, func, linenum, true, 0);
+
+	lockunlock();
+}
+
+uint64_t api_trylock(void *lock, const char *file, const char *func, const int linenum)
+{
+	LOCKINFO *info;
+	uint64_t id;
+
+	info = findlock(lock, CGLOCK_UNKNOWN, file, func, linenum);
+	id = lock_id++;
+	addgettry(info, id, file, func, linenum, false);
+
+	return id;
+}
+
+void api_didlock(uint64_t id, int ret, void *lock, const char *file, const char *func, const int linenum)
+{
+	LOCKINFO *info;
+
+	locklock();
+
+	info = findlock(lock, CGLOCK_UNKNOWN, file, func, linenum);
+	markgotdid(info, id, file, func, linenum, false, ret);
+
+	lockunlock();
+}
+
+void api_gunlock(void *lock, const char *file, const char *func, const int linenum)
+{
+	LOCKINFO *info;
+
+	locklock();
+
+	info = findlock(lock, CGLOCK_UNKNOWN, file, func, linenum);
+	info->unlocks++;
+
+	lockunlock();
+}
+
+void api_initlock(void *lock, enum cglock_typ typ, const char *file, const char *func, const int linenum)
+{
+	locklock();
+
+	findlock(lock, typ, file, func, linenum);
+
+	lockunlock();
+}
+
+void dsp_det(char *msg, LOCKSTAT *stat)
+{
+	struct tm *tm;
+	time_t dt;
+
+	dt = stat->tv.tv_sec;
+	tm = localtime(&dt);
+
+	LOCKMSGMORE("%s id=%"PRIu64" by %s %s():%d at %d-%02d-%02d %02d:%02d:%02d",
+			msg,
+			stat->lock_id,
+			stat->file,
+			stat->func,
+			stat->linenum,
+			tm->tm_year + 1900,
+			tm->tm_mon + 1,
+			tm->tm_mday,
+			tm->tm_hour,
+			tm->tm_min,
+			tm->tm_sec);
+}
+
+void dsp_lock(LOCKINFO *info)
+{
+	LOCKLINE *line;
+	char *status;
+
+	LOCKMSG("Lock %p created by %s %s():%d",
+		info->lock,
+		info->file,
+		info->func,
+		info->linenum);
+	LOCKMSGMORE("gets:%"PRIu64" gots:%"PRIu64" tries:%"PRIu64
+		    " dids:%"PRIu64" didnts:%"PRIu64" unlocks:%"PRIu64,
+			info->gets,
+			info->gots,
+			info->tries,
+			info->dids,
+			info->didnts,
+			info->unlocks);
+
+	if (info->gots > 0 || info->dids > 0) {
+		if (info->unlocks < info->gots + info->dids)
+			status = "Last got/did still HELD";
+		else
+			status = "Last got/did (idle)";
+
+		dsp_det(status, &(info->lastgot));
+	} else
+		LOCKMSGMORE("... unused ...");
+
+	if (info->lockgets) {
+		LOCKMSGMORE("BLOCKED gets (%"PRIu64")", info->gets - info->gots);
+		line = info->lockgets;
+		while (line) {
+			dsp_det("", line->stat);
+			line = line->next;
+		}
+	} else
+		LOCKMSGMORE("no blocked gets");
+
+	if (info->locktries) {
+		LOCKMSGMORE("BLOCKED tries (%"PRIu64")", info->tries - info->dids - info->didnts);
+		line = info->lockgets;
+		while (line) {
+			dsp_det("", line->stat);
+			line = line->next;
+		}
+	} else
+		LOCKMSGMORE("no blocked tries");
+}
+
+void show_locks()
+{
+	LOCKLIST *list;
+
+	locklock();
+
+	lockmsgnow();
+
+	list = lockhead;
+	if (!list)
+		LOCKMSG("no locks?!?\n");
+	else {
+		while (list) {
+			dsp_lock(list->info);
+			list = list->next;
+		}
+	}
+
+	LOCKMSGFLUSH();
+
+	lockunlock();
+}
+#endif
+
+static void lockstats(struct io_data *io_data, __maybe_unused SOCKETTYPE c, __maybe_unused char *param, bool isjson, __maybe_unused char group)
+{
+#if LOCK_TRACKING
+	show_locks();
+	message(io_data, MSG_LOCKOK, 0, NULL, isjson);
+#else
+	message(io_data, MSG_LOCKDIS, 0, NULL, isjson);
+#endif
+}
+
 static void apiversion(struct io_data *io_data, __maybe_unused SOCKETTYPE c, __maybe_unused char *param, bool isjson, __maybe_unused char group)
 {
 	struct api_data *root = NULL;
@@ -3872,6 +4269,7 @@ struct CMDS {
 	{ "ascset",		ascset,		true },
 #endif
 	{ "asccount",		asccount,	false },
+	{ "lockstats",		lockstats,	true },
 	{ NULL,			NULL,		false }
 };
 

cgminer.c

@@ -208,6 +208,10 @@ static int new_devices;
 static int new_threads;
 int hotplug_time = 5;
 
+#if LOCK_TRACKING
+pthread_mutex_t lockstat_lock;
+#endif
+
 #ifdef USE_USBUTILS
 pthread_mutex_t cgusb_lock;
 pthread_mutex_t cgusbres_lock;
@@ -7836,6 +7840,12 @@ int main(int argc, char *argv[])
 	if (unlikely(curl_global_init(CURL_GLOBAL_ALL)))
 		quit(1, "Failed to curl_global_init");
 
+#if LOCK_TRACKING
+	// Must be first
+	if (unlikely(pthread_mutex_init(&lockstat_lock, NULL)))
+		quithere(1, "Failed to pthread_mutex_init lockstat_lock errno=%d", errno);
+#endif
+
 	initial_args = malloc(sizeof(char *) * (argc + 1));
 	for  (i = 0; i < argc; i++)
 		initial_args[i] = strdup(argv[i]);

driver-klondike.c

@@ -44,6 +44,14 @@
 #define MAX_WORK_COUNT		4	// for now, must be binary multiple and match firmware
 #define TACH_FACTOR		87890	// fan rpm divisor
 
+/*
+ *  Work older than 5s will already be completed
+ *  FYI it must not be possible to complete 256 work
+ *  items this quickly on a single device -
+ *  thus limited to 219.9GH/s per device
+ */
+#define OLD_WORK_MS ((int)(5 * 1000))
+
 struct device_drv klondike_drv;
 
 typedef struct klondike_header {
@@ -183,6 +191,9 @@ struct klondike_info {
 	double nonce_total;
 	double nonce_min;
 	double nonce_max;
+
+	int wque_size;
+	int wque_cleared;
 };
 
 static KLIST *new_klist_set(struct cgpu_info *klncgpu)
@@ -464,7 +475,9 @@ static bool klondike_get_stats(struct cgpu_info *klncgpu)
 		kitem = SendCmdGetReply(klncgpu, &kline, 0);
 		if (kitem != NULL) {
 			wr_lock(&(klninfo->stat_lock));
-			memcpy((void *)(&(klninfo->status[dev])), (void *)kitem, sizeof(*kitem));
+			memcpy((void *)(&(klninfo->status[dev])),
+				(void *)kitem,
+				sizeof(klninfo->status[dev]));
 			wr_unlock(&(klninfo->stat_lock));
 			release_kitem(klncgpu, kitem);
 			kitem = NULL;
@@ -533,7 +546,7 @@ static bool klondike_init(struct cgpu_info *klncgpu)
 		kline.cfg.dev = dev;
 		kitem = SendCmdGetReply(klncgpu, &kline, size);
 		if (kitem != NULL) {
-			memcpy((void *)&(klninfo->cfg[dev]), kitem, sizeof(*kitem));
+			memcpy((void *)&(klninfo->cfg[dev]), kitem, sizeof(klninfo->cfg[dev]));
 			applog(LOG_WARNING, "Klondike config (%d: Clk: %d, T:%.0lf, C:%.0lf, F:%d)",
 				dev, K_HASHCLOCK(klninfo->cfg[dev].kline.cfg.hashclock),
 				cvtKlnToC(klninfo->cfg[dev].kline.cfg.temptarget),
@@ -613,10 +626,11 @@ static bool klondike_detect_one(struct libusb_device *dev, struct usb_find_devic
 						klncgpu->device_path,
 						recd);
 			} else if (kitem.kline.hd.cmd == 'I' && kitem.kline.hd.dev == 0) {
-display_kline(klncgpu, &kitem.kline);
+				display_kline(klncgpu, &kitem.kline);
-				applog(LOG_DEBUG, "%s (%s) detect successful",
+				applog(LOG_DEBUG, "%s (%s) detect successful (%d attempt%s)",
 						  klncgpu->drv->dname,
-						  klncgpu->device_path);
+						  klncgpu->device_path,
+						  attempts, attempts == 1 ? "" : "s");
 				if (!add_cgpu(klncgpu))
 					break;
 				update_usb_stats(klncgpu);
@@ -661,8 +675,10 @@ static void klondike_check_nonce(struct cgpu_info *klncgpu, KLIST *kitem)
 	applog(LOG_DEBUG, "Klondike FOUND NONCE (%02x:%08x)",
 			  kline->wr.workid, (unsigned int)nonce);
 
+	cgtime(&tv_now);
 	HASH_ITER(hh, klncgpu->queued_work, work, tmp) {
-		if (work->queued && (work->subid == (kline->wr.dev*256 + kline->wr.workid))) {
+		if (work->queued && ms_tdiff(&tv_now, &(work->tv_stamp)) < OLD_WORK_MS &&
+		    (work->subid == (kline->wr.dev*256 + kline->wr.workid))) {
 
 			wr_lock(&(klninfo->stat_lock));
 			klninfo->devinfo[kline->wr.dev].noncecount++;
@@ -810,7 +826,9 @@ static void klondike_flush_work(struct cgpu_info *klncgpu)
 		kitem = SendCmdGetReply(klncgpu, &kline, KSENDHD(0));
 		if (kitem != NULL) {
 			wr_lock(&(klninfo->stat_lock));
-			memcpy((void *)&(klninfo->status[dev]), kitem, sizeof(*kitem));
+			memcpy((void *)&(klninfo->status[dev]),
+				kitem,
+				sizeof(klninfo->status[dev]));
 			wr_unlock(&(klninfo->stat_lock));
 			release_kitem(klncgpu, kitem);
 			kitem = NULL;
@@ -890,6 +908,8 @@ static bool klondike_send_work(struct cgpu_info *klncgpu, int dev, struct work *
 	struct klondike_info *klninfo = (struct klondike_info *)(klncgpu->device_data);
 	struct work *tmp;
 	KLINE kline;
+	struct timeval tv_old;
+	int wque_size, wque_cleared;
 
 	if (klncgpu->usbinfo.nodev)
 		return false;
@@ -900,6 +920,7 @@ static bool klondike_send_work(struct cgpu_info *klncgpu, int dev, struct work *
 	memcpy(kline.wt.merkle, work->data + MERKLE_OFFSET, MERKLE_BYTES);
 	kline.wt.workid = (uint8_t)(klninfo->devinfo[dev].nextworkid++ & 0xFF);
 	work->subid = dev*256 + kline.wt.workid;
+	cgtime(&work->tv_stamp);
 
 	if (opt_log_level <= LOG_DEBUG) {
 		char *hexdata = bin2hex((void *)&kline.wt, sizeof(kline.wt));
@@ -911,16 +932,29 @@ static bool klondike_send_work(struct cgpu_info *klncgpu, int dev, struct work *
 	KLIST *kitem = SendCmdGetReply(klncgpu, &kline, sizeof(kline.wt));
 	if (kitem != NULL) {
 		wr_lock(&(klninfo->stat_lock));
-		memcpy((void *)&(klninfo->status[dev]), kitem, sizeof(*kitem));
+		memcpy((void *)&(klninfo->status[dev]), kitem, sizeof(klninfo->status[dev]));
 		wr_unlock(&(klninfo->stat_lock));
 		release_kitem(klncgpu, kitem);
 		kitem = NULL;
 
 		// remove old work
+		wque_size = 0;
+		wque_cleared = 0;
+		cgtime(&tv_old);
 		HASH_ITER(hh, klncgpu->queued_work, work, tmp) {
-		if (work->queued && (work->subid == (int)(dev*256 + ((klninfo->devinfo[dev].nextworkid-2*MAX_WORK_COUNT) & 0xFF))))
+			if (work->queued) {
-			work_completed(klncgpu, work);
+				if (ms_tdiff(&tv_old, &(work->tv_stamp)) > OLD_WORK_MS) {
+					work_completed(klncgpu, work);
+					wque_cleared++;
+				}
+				else
+					wque_size++;
+			}
 		}
+		wr_lock(&(klninfo->stat_lock));
+		klninfo->wque_size = wque_size;
+		klninfo->wque_cleared = wque_cleared;
+		wr_unlock(&(klninfo->stat_lock));
 		return true;
 	}
 	return false;
@@ -1102,6 +1136,9 @@ static struct api_data *klondike_api_stats(struct cgpu_info *klncgpu)
 		avg = klninfo->nonce_total / klninfo->nonce_count;
 	root = api_add_diff(root, "KQue Nonce Avg", &avg, true);
 
+	root = api_add_int(root, "WQue Size", &(klninfo->wque_size), true);
+	root = api_add_int(root, "WQue Cleared", &(klninfo->wque_cleared), true);
+
 	rd_unlock(&(klninfo->stat_lock));
 
 	return root;

miner.h

@@ -737,74 +737,143 @@ endian_flip128(void __maybe_unused *dest_p, const void __maybe_unused *src_p)
 
 extern void _quit(int status);
 
-#define mutex_lock(_lock) _mutex_lock(_lock, __FILE__, __func__, __LINE__) 
+/*
-#define mutex_unlock_noyield(_lock) _mutex_unlock_noyield(_lock, __FILE__, __func__, __LINE__) 
+ * Set this to non-zero to enable lock tracking
-#define wr_lock(_lock) _wr_lock(_lock, __FILE__, __func__, __LINE__) 
+ * Use the API lockstats command to see the locking status on stderr
-#define rd_lock(_lock) _rd_lock(_lock, __FILE__, __func__, __LINE__) 
+ *  i.e. in your log file if you 2> log.log - but not on the screen
-#define rw_unlock(_lock) _rw_unlock(_lock, __FILE__, __func__, __LINE__) 
+ * API lockstats is privilidged but will always exist and will return
-#define mutex_init(_lock) _mutex_init(_lock, __FILE__, __func__, __LINE__) 
+ *	success if LOCK_TRACKING is enabled and warning if disabled
-#define rwlock_init(_lock) _rwlock_init(_lock, __FILE__, __func__, __LINE__) 
+ * In production code, this should never be enabled since it will slow down all locking
+ * So, e.g. use it to track down a deadlock - after a reproducable deadlock occurs
+ * ... Of course if the API code itself deadlocks, it wont help :)
+ */
+#define LOCK_TRACKING 0
+
+#if LOCK_TRACKING
+enum cglock_typ {
+	CGLOCK_MUTEX,
+	CGLOCK_RW,
+	CGLOCK_UNKNOWN
+};
+
+extern uint64_t api_getlock(void *lock, const char *file, const char *func, const int line);
+extern void api_gotlock(uint64_t id, void *lock, const char *file, const char *func, const int line);
+extern uint64_t api_trylock(void *lock, const char *file, const char *func, const int line);
+extern void api_didlock(uint64_t id, int ret, void *lock, const char *file, const char *func, const int line);
+extern void api_gunlock(void *lock, const char *file, const char *func, const int line);
+extern void api_initlock(void *lock, enum cglock_typ typ, const char *file, const char *func, const int line);
+
+#define GETLOCK(_lock, _file, _func, _line) uint64_t _id1 = api_getlock((void *)(_lock), _file, _func, _line)
+#define GOTLOCK(_lock, _file, _func, _line) api_gotlock(_id1, (void *)(_lock), _file, _func, _line)
+#define TRYLOCK(_lock, _file, _func, _line) uint64_t _id2 = api_trylock((void *)(_lock), _file, _func, _line)
+#define DIDLOCK(_ret, _lock, _file, _func, _line) api_didlock(_id2, _ret, (void *)(_lock), _file, _func, _line)
+#define GUNLOCK(_lock, _file, _func, _line) api_gunlock((void *)(_lock), _file, _func, _line)
+#define INITLOCK(_lock, _typ, _file, _func, _line) api_initlock((void *)(_lock), _typ, _file, _func, _line)
+#else
+#define GETLOCK(_lock, _file, _func, _line)
+#define GOTLOCK(_lock, _file, _func, _line)
+#define TRYLOCK(_lock, _file, _func, _line)
+#define DIDLOCK(_ret, _lock, _file, _func, _line)
+#define GUNLOCK(_lock, _file, _func, _line)
+#define INITLOCK(_typ, _lock, _file, _func, _line)
+#endif
+
+#define mutex_lock(_lock) _mutex_lock(_lock, __FILE__, __func__, __LINE__)
+#define mutex_unlock_noyield(_lock) _mutex_unlock_noyield(_lock, __FILE__, __func__, __LINE__)
+#define mutex_unlock(_lock) _mutex_unlock(_lock, __FILE__, __func__, __LINE__)
+#define mutex_trylock(_lock) _mutex_trylock(_lock, __FILE__, __func__, __LINE__)
+#define wr_lock(_lock) _wr_lock(_lock, __FILE__, __func__, __LINE__)
+#define rd_lock(_lock) _rd_lock(_lock, __FILE__, __func__, __LINE__)
+#define rw_unlock(_lock) _rw_unlock(_lock, __FILE__, __func__, __LINE__)
+#define rd_unlock_noyield(_lock) _rd_unlock_noyield(_lock, __FILE__, __func__, __LINE__)
+#define wr_unlock_noyield(_lock) _wr_unlock_noyield(_lock, __FILE__, __func__, __LINE__)
+#define rd_unlock(_lock) _rd_unlock(_lock, __FILE__, __func__, __LINE__)
+#define wr_unlock(_lock) _wr_unlock(_lock, __FILE__, __func__, __LINE__)
+#define mutex_init(_lock) _mutex_init(_lock, __FILE__, __func__, __LINE__)
+#define rwlock_init(_lock) _rwlock_init(_lock, __FILE__, __func__, __LINE__)
+#define cglock_init(_lock) _cglock_init(_lock, __FILE__, __func__, __LINE__)
+#define cg_rlock(_lock) _cg_rlock(_lock, __FILE__, __func__, __LINE__)
+#define cg_ilock(_lock) _cg_ilock(_lock, __FILE__, __func__, __LINE__)
+#define cg_ulock(_lock) _cg_ulock(_lock, __FILE__, __func__, __LINE__)
+#define cg_wlock(_lock) _cg_wlock(_lock, __FILE__, __func__, __LINE__)
+#define cg_dwlock(_lock) _cg_dwlock(_lock, __FILE__, __func__, __LINE__)
+#define cg_dwilock(_lock) _cg_dwilock(_lock, __FILE__, __func__, __LINE__)
+#define cg_dlock(_lock) _cg_dlock(_lock, __FILE__, __func__, __LINE__)
+#define cg_runlock(_lock) _cg_runlock(_lock, __FILE__, __func__, __LINE__)
+#define cg_ruwlock(_lock) _cg_ruwlock(_lock, __FILE__, __func__, __LINE__)
+#define cg_wunlock(_lock) _cg_wunlock(_lock, __FILE__, __func__, __LINE__)
 
 static inline void _mutex_lock(pthread_mutex_t *lock, const char *file, const char *func, const int line)
 {
+	GETLOCK(lock, file, func, line);
 	if (unlikely(pthread_mutex_lock(lock)))
 		quitfrom(1, file, func, line, "WTF MUTEX ERROR ON LOCK! errno=%d", errno);
+	GOTLOCK(lock, file, func, line);
 }
 
 static inline void _mutex_unlock_noyield(pthread_mutex_t *lock, const char *file, const char *func, const int line)
 {
 	if (unlikely(pthread_mutex_unlock(lock)))
 		quitfrom(1, file, func, line, "WTF MUTEX ERROR ON UNLOCK! errno=%d", errno);
+	GUNLOCK(lock, file, func, line);
 }
 
-static inline void mutex_unlock(pthread_mutex_t *lock)
+static inline void _mutex_unlock(pthread_mutex_t *lock, const char *file, const char *func, const int line)
 {
-	mutex_unlock_noyield(lock);
+	_mutex_unlock_noyield(lock, file, func, line);
 	sched_yield();
 }
 
-static inline int mutex_trylock(pthread_mutex_t *lock)
+static inline int _mutex_trylock(pthread_mutex_t *lock, __maybe_unused const char *file, __maybe_unused const char *func, __maybe_unused const int line)
 {
-	return pthread_mutex_trylock(lock);
+	TRYLOCK(lock, file, func, line);
+	int ret = pthread_mutex_trylock(lock);
+	DIDLOCK(ret, lock, file, func, line);
+	return ret;
 }
 
 static inline void _wr_lock(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
+	GETLOCK(lock, file, func, line);
 	if (unlikely(pthread_rwlock_wrlock(lock)))
 		quitfrom(1, file, func, line, "WTF WRLOCK ERROR ON LOCK! errno=%d", errno);
+	GOTLOCK(lock, file, func, line);
 }
 
 static inline void _rd_lock(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
+	GETLOCK(lock, file, func, line);
 	if (unlikely(pthread_rwlock_rdlock(lock)))
 		quitfrom(1, file, func, line, "WTF RDLOCK ERROR ON LOCK! errno=%d", errno);
+	GOTLOCK(lock, file, func, line);
 }
 
 static inline void _rw_unlock(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
 	if (unlikely(pthread_rwlock_unlock(lock)))
 		quitfrom(1, file, func, line, "WTF RWLOCK ERROR ON UNLOCK! errno=%d", errno);
+	GUNLOCK(lock, file, func, line);
 }
 
-static inline void rd_unlock_noyield(pthread_rwlock_t *lock)
+static inline void _rd_unlock_noyield(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
-	rw_unlock(lock);
+	_rw_unlock(lock, file, func, line);
 }
 
-static inline void wr_unlock_noyield(pthread_rwlock_t *lock)
+static inline void _wr_unlock_noyield(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
-	rw_unlock(lock);
+	_rw_unlock(lock, file, func, line);
 }
 
-static inline void rd_unlock(pthread_rwlock_t *lock)
+static inline void _rd_unlock(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
-	rw_unlock(lock);
+	_rw_unlock(lock, file, func, line);
 	sched_yield();
 }
 
-static inline void wr_unlock(pthread_rwlock_t *lock)
+static inline void _wr_unlock(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
-	rw_unlock(lock);
+	_rw_unlock(lock, file, func, line);
 	sched_yield();
 }
 
@@ -812,86 +881,88 @@ static inline void _mutex_init(pthread_mutex_t *lock, const char *file, const ch
 {
 	if (unlikely(pthread_mutex_init(lock, NULL)))
 		quitfrom(1, file, func, line, "Failed to pthread_mutex_init errno=%d", errno);
+	INITLOCK(lock, CGLOCK_MUTEX, file, func, line);
 }
 
 static inline void _rwlock_init(pthread_rwlock_t *lock, const char *file, const char *func, const int line)
 {
 	if (unlikely(pthread_rwlock_init(lock, NULL)))
 		quitfrom(1, file, func, line, "Failed to pthread_rwlock_init errno=%d", errno);
+	INITLOCK(lock, CGLOCK_RW, file, func, line);
 }
 
-static inline void cglock_init(cglock_t *lock)
+static inline void _cglock_init(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	mutex_init(&lock->mutex);
+	_mutex_init(&lock->mutex, file, func, line);
-	rwlock_init(&lock->rwlock);
+	_rwlock_init(&lock->rwlock, file, func, line);
 }
 
 /* Read lock variant of cglock. Cannot be promoted. */
-static inline void cg_rlock(cglock_t *lock)
+static inline void _cg_rlock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	mutex_lock(&lock->mutex);
+	_mutex_lock(&lock->mutex, file, func, line);
-	rd_lock(&lock->rwlock);
+	_rd_lock(&lock->rwlock, file, func, line);
-	mutex_unlock_noyield(&lock->mutex);
+	_mutex_unlock_noyield(&lock->mutex, file, func, line);
 }
 
 /* Intermediate variant of cglock - behaves as a read lock but can be promoted
  * to a write lock or demoted to read lock. */
-static inline void cg_ilock(cglock_t *lock)
+static inline void _cg_ilock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	mutex_lock(&lock->mutex);
+	_mutex_lock(&lock->mutex, file, func, line);
 }
 
 /* Upgrade intermediate variant to a write lock */
-static inline void cg_ulock(cglock_t *lock)
+static inline void _cg_ulock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	wr_lock(&lock->rwlock);
+	_wr_lock(&lock->rwlock, file, func, line);
 }
 
 /* Write lock variant of cglock */
-static inline void cg_wlock(cglock_t *lock)
+static inline void _cg_wlock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	mutex_lock(&lock->mutex);
+	_mutex_lock(&lock->mutex, file, func, line);
-	wr_lock(&lock->rwlock);
+	_wr_lock(&lock->rwlock, file, func, line);
 }
 
 /* Downgrade write variant to a read lock */
-static inline void cg_dwlock(cglock_t *lock)
+static inline void _cg_dwlock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	wr_unlock_noyield(&lock->rwlock);
+	_wr_unlock_noyield(&lock->rwlock, file, func, line);
-	rd_lock(&lock->rwlock);
+	_rd_lock(&lock->rwlock, file, func, line);
-	mutex_unlock_noyield(&lock->mutex);
+	_mutex_unlock_noyield(&lock->mutex, file, func, line);
 }
 
 /* Demote a write variant to an intermediate variant */
-static inline void cg_dwilock(cglock_t *lock)
+static inline void _cg_dwilock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	wr_unlock(&lock->rwlock);
+	_wr_unlock(&lock->rwlock, file, func, line);
 }
 
 /* Downgrade intermediate variant to a read lock */
-static inline void cg_dlock(cglock_t *lock)
+static inline void _cg_dlock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	rd_lock(&lock->rwlock);
+	_rd_lock(&lock->rwlock, file, func, line);
-	mutex_unlock_noyield(&lock->mutex);
+	_mutex_unlock_noyield(&lock->mutex, file, func, line);
 }
 
-static inline void cg_runlock(cglock_t *lock)
+static inline void _cg_runlock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	rd_unlock(&lock->rwlock);
+	_rd_unlock(&lock->rwlock, file, func, line);
 }
 
 /* This drops the read lock and grabs a write lock. It does NOT protect data
  * between the two locks! */
-static inline void cg_ruwlock(cglock_t *lock)
+static inline void _cg_ruwlock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	rd_unlock_noyield(&lock->rwlock);
+	_rd_unlock_noyield(&lock->rwlock, file, func, line);
-	cg_wlock(lock);
+	_cg_wlock(lock, file, func, line);
 }
 
-static inline void cg_wunlock(cglock_t *lock)
+static inline void _cg_wunlock(cglock_t *lock, const char *file, const char *func, const int line)
 {
-	wr_unlock_noyield(&lock->rwlock);
+	_wr_unlock_noyield(&lock->rwlock, file, func, line);
-	mutex_unlock(&lock->mutex);
+	_mutex_unlock(&lock->mutex, file, func, line);
 }
 
 struct pool;
@@ -942,6 +1013,10 @@ extern bool opt_bfl_noncerange;
 #endif
 extern int swork_id;
 
+#if LOCK_TRACKING
+extern pthread_mutex_t lockstat_lock;
+#endif
+
 extern pthread_rwlock_t netacc_lock;
 
 extern const uint32_t sha256_init_state[];
@@ -1329,6 +1404,8 @@ struct work {
 	int		subid;
 	// Allow devices to flag work for their own purposes
 	bool		devflag;
+	// Allow devices to timestamp work for their own purposes
+	struct timeval	tv_stamp;
 
 	struct timeval	tv_getwork;
 	struct timeval	tv_getwork_reply;