condition_variable deadlock

asyncThreadPoolTest.cpp

#define dbgprint(...) async_mem_log.print(__VA_ARGS__)
#include "utilUtils.h"
#include "utilRand.h"
#include "utilTime.h"
void asyncThreadPoolTest()
{
	static auto one_ms = std::chrono::milliseconds(1);
	int threads = 6;
	std::vector< std::thread > workers;
	int queued_tasks = 0;
	std::mutex queue_mutex;
	std::condition_variable condition;
	std::condition_variable done_condition;
	int running_tasks = 0;
	int delay;

	for (int i = 0; i < threads; ++i) {
		workers.emplace_back(std::thread([&queued_tasks, &queue_mutex, &running_tasks, &condition, &done_condition, &delay]
		{
			for (;;)
			{
				std::unique_lock<std::mutex> lock(queue_mutex);
				if (1) {
					dbgprint("worker waiting");
					condition.wait(lock, [&queued_tasks]() {
						return queued_tasks != 0;
					});
					dbgprint("worker wakeup queued_tasks=%d", queued_tasks);
				} else {
					while (!queued_tasks) {
						dbgprint("worker waiting");
						condition.wait(lock);
						dbgprint("worker wakeup queued_tasks=%d", queued_tasks);
					}
				}
				--queued_tasks;
				lock.unlock();
				dbgprint("worker running task");

				// dummy work task
				{
					U32 a = 1, b = 1, c = 0;
					for (int ii = 0; ii < delay; ii++) {
						c = a + b; a = b; b = c;
					}
				}

				dbgprint("worker locking mutex");
				lock.lock();
				running_tasks--;
				dbgprint("worker running_tasks = %d", running_tasks);
				if (1) { // very rarely deadlocks on PS4 (need guard in wait()); slightly more efficient
					lock.unlock();
					done_condition.notify_one();
				} else { // doesn't seem to deadlock, but no good reason, so probably just rarer
					done_condition.notify_one();
					lock.unlock();
				}
			}
		}));
	}

	int idx = 0;
	U32 seed = 0x12345678;
	U64 start = timeGetMS();
	U64 last_start = timeGetMS();
	while (true) {
		delay = 60000 + randSeededInt(&seed, 60000); // failed on: 67290, 73862, 97648, 100154, 111772, 113960
		//delay = 1000 + randSeededInt(&seed, 1000);
		dbgprint("Using delay %d", delay);
		dbgprint("enqueue locking mutex");
		
		std::unique_lock<std::mutex> lock(queue_mutex);
		running_tasks = queued_tasks = threads;
		dbgprint("enqueue running_tasks = %d", running_tasks);
		lock.unlock();
		
		condition.notify_all();
		
		dbgprint("wait locking mutex");
		lock.lock();
		if (0) { // deadlock versions
			if (1) { // deadlocks
				dbgprint("wait waiting");
				done_condition.wait(lock,
					[&running_tasks]
				{
					bool ret = running_tasks == 0;
					dbgprint("wait wakeup running_tasks = %d", running_tasks);
					return ret;
				});
			} else { // deadlock about 5x less often
				while (running_tasks) {
					dbgprint("wait waiting");
					done_condition.wait(lock);
					dbgprint("wait wakeup running_tasks = %d", running_tasks);
				}
			}
		} else { // with hack to prevent
			if (1) {
				dbgprint("wait waiting");
				while (running_tasks) {
					done_condition.wait_for(lock, one_ms,
						[&running_tasks]
					{
						bool ret = running_tasks == 0;
						dbgprint("wait wakeup running_tasks = %d", running_tasks);
						return ret;
					});
					if (running_tasks)
						dbgprint("wait spurious wakeup running_tasks = %d", running_tasks);
				}
			} else {
				while (running_tasks) {
					dbgprint("wait waiting");
					done_condition.wait_for(lock, one_ms);
					dbgprint("wait wakeup running_tasks = %d", running_tasks);
				}
			}
		}
		lock.unlock();
		dbgprint("wait done");

		++idx;
		if (idx % 1000 == 0) {
			U64 now = timeGetMS();
			printf("%d tests, %1.0f tests/sec, %1.0f total tests/sec\n", idx, 1000.f * 1000.f / (now - last_start), idx * 1000.f / (now - start) );
			last_start = now;
		}
	}
}

log.txt

+		[208]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680df368 "Using delay 111772" }	UtilMemLog::Line
+		[209]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680df478 "enqueue locking mutex" }	UtilMemLog::Line
+		[210]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680df588 "enqueue running_tasks = 1" }	UtilMemLog::Line
+		[211]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680df698 "enqueue locking mutex" }	UtilMemLog::Line
+		[212]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680df7a8 "enqueue running_tasks = 2" }	UtilMemLog::Line
+		[213]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680df8b8 "enqueue locking mutex" }	UtilMemLog::Line
+		[214]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680df9c8 "enqueue running_tasks = 3" }	UtilMemLog::Line
+		[215]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680dfad8 "enqueue locking mutex" }	UtilMemLog::Line
+		[216]	{ timestamp=186656 thread_id=36533512512 line=0x00000000680dfbe8 "worker wakeup return 1" }	UtilMemLog::Line
+		[217]	{ timestamp=186656 thread_id=36533515968 line=0x00000000680dfcf8 "worker wakeup return 1" }	UtilMemLog::Line
+		[218]	{ timestamp=186656 thread_id=36533515968 line=0x00000000680dfe08 "worker running task" }	UtilMemLog::Line
+		[219]	{ timestamp=186656 thread_id=36533512512 line=0x00000000680dff18 "worker running task" }	UtilMemLog::Line
+		[220]	{ timestamp=186656 thread_id=36533510208 line=0x00000000680e0028 "worker wakeup return 1" }	UtilMemLog::Line
+		[221]	{ timestamp=186656 thread_id=36533510208 line=0x00000000680e0138 "worker running task" }	UtilMemLog::Line
+		[222]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680e0248 "enqueue running_tasks = 4" }	UtilMemLog::Line
+		[223]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680e0358 "enqueue locking mutex" }	UtilMemLog::Line
+		[224]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680e0468 "enqueue running_tasks = 5" }	UtilMemLog::Line
+		[225]	{ timestamp=186656 thread_id=36533503296 line=0x00000000680e0578 "enqueue locking mutex" }	UtilMemLog::Line
+		[226]	{ timestamp=186657 thread_id=36533513664 line=0x00000000680e0688 "worker wakeup return 1" }	UtilMemLog::Line
+		[227]	{ timestamp=186657 thread_id=36533513664 line=0x00000000680e0798 "worker running task" }	UtilMemLog::Line
+		[228]	{ timestamp=186657 thread_id=36533514816 line=0x00000000680e08a8 "worker wakeup return 1" }	UtilMemLog::Line
+		[229]	{ timestamp=186657 thread_id=36533514816 line=0x00000000680e09b8 "worker running task" }	UtilMemLog::Line
+		[230]	{ timestamp=186657 thread_id=36533503296 line=0x00000000680e0ac8 "enqueue running_tasks = 6" }	UtilMemLog::Line
+		[231]	{ timestamp=186657 thread_id=36533503296 line=0x00000000680e0bd8 "wait locking mutex" }	UtilMemLog::Line
+		[232]	{ timestamp=186657 thread_id=36533503296 line=0x00000000680e0ce8 "wait waiting" }	UtilMemLog::Line
+		[233]	{ timestamp=186657 thread_id=36533503296 line=0x00000000680e0df8 "wait wakeup running_tasks = 6" }	UtilMemLog::Line
+		[234]	{ timestamp=186657 thread_id=36533511360 line=0x00000000680e0f08 "worker wakeup return 1" }	UtilMemLog::Line
+		[235]	{ timestamp=186657 thread_id=36533511360 line=0x00000000680e1018 "worker running task" }	UtilMemLog::Line
+		[236]	{ timestamp=186657 thread_id=36533510208 line=0x00000000680e1128 "worker locking mutex" }	UtilMemLog::Line
+		[237]	{ timestamp=186657 thread_id=36533510208 line=0x00000000680e1238 "worker running_tasks = 5" }	UtilMemLog::Line
+		[238]	{ timestamp=186657 thread_id=36533510208 line=0x00000000680e1348 "worker waiting" }	UtilMemLog::Line
+		[239]	{ timestamp=186657 thread_id=36533510208 line=0x00000000680e1458 "worker wakeup return 0" }	UtilMemLog::Line
+		[240]	{ timestamp=186657 thread_id=36533503296 line=0x00000000680e1568 "wait wakeup running_tasks = 5" }	UtilMemLog::Line
+		[241]	{ timestamp=186657 thread_id=36533514816 line=0x00000000680e1678 "worker locking mutex" }	UtilMemLog::Line
+		[242]	{ timestamp=186657 thread_id=36533514816 line=0x00000000680e1788 "worker running_tasks = 4" }	UtilMemLog::Line
+		[243]	{ timestamp=186657 thread_id=36533513664 line=0x00000000680e1898 "worker locking mutex" }	UtilMemLog::Line
+		[244]	{ timestamp=186657 thread_id=36533512512 line=0x00000000680e19a8 "worker locking mutex" }	UtilMemLog::Line
+		[245]	{ timestamp=186657 thread_id=36533515968 line=0x00000000680e1ab8 "worker locking mutex" }	UtilMemLog::Line
+		[246]	{ timestamp=186657 thread_id=36533513664 line=0x00000000680e1bc8 "worker running_tasks = 3" }	UtilMemLog::Line
+		[247]	{ timestamp=186657 thread_id=36533514816 line=0x00000000680e1cd8 "worker waiting" }	UtilMemLog::Line
+		[248]	{ timestamp=186657 thread_id=36533514816 line=0x00000000680e1de8 "worker wakeup return 0" }	UtilMemLog::Line
+		[249]	{ timestamp=186657 thread_id=36533511360 line=0x00000000680e1ef8 "worker locking mutex" }	UtilMemLog::Line
+		[250]	{ timestamp=186657 thread_id=36533503296 line=0x00000000680e2008 "wait wakeup running_tasks = 3" }	UtilMemLog::Line
+		[251]	{ timestamp=186657 thread_id=36533515968 line=0x00000000680e2118 "worker running_tasks = 2" }	UtilMemLog::Line
+		[252]	{ timestamp=186657 thread_id=36533512512 line=0x00000000680e2228 "worker running_tasks = 1" }	UtilMemLog::Line
+		[253]	{ timestamp=186657 thread_id=36533503296 line=0x00000000680e2338 "wait wakeup running_tasks = 1" }	UtilMemLog::Line
+		[254]	{ timestamp=186657 thread_id=36533513664 line=0x00000000680e2448 "worker waiting" }	UtilMemLog::Line
+		[255]	{ timestamp=186657 thread_id=36533513664 line=0x00000000680e2558 "worker wakeup return 0" }	UtilMemLog::Line
+		[0]	{ timestamp=186657 thread_id=36533515968 line=0x00000000680d1668 "worker waiting" }	UtilMemLog::Line
+		[1]	{ timestamp=186657 thread_id=36533515968 line=0x00000000680d1778 "worker wakeup return 0" }	UtilMemLog::Line
+		[2]	{ timestamp=186657 thread_id=36533511360 line=0x00000000680d1888 "worker running_tasks = 0" }	UtilMemLog::Line
+		[3]	{ timestamp=186657 thread_id=36533511360 line=0x00000000680d1998 "worker waiting" }	UtilMemLog::Line
+		[4]	{ timestamp=186657 thread_id=36533511360 line=0x00000000680d1aa8 "worker wakeup return 0" }	UtilMemLog::Line
+		[5]	{ timestamp=186657 thread_id=36533512512 line=0x00000000680d1bb8 "worker waiting" }	UtilMemLog::Line
+		[6]	{ timestamp=186657 thread_id=36533512512 line=0x00000000680d1cc8 "worker wakeup return 0" }	UtilMemLog::Line

log2.txt

+		[87]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad72d8 "Using delay 72777" }	UtilMemLog::Line
+		[88]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad73e8 "enqueue locking mutex" }	UtilMemLog::Line
+		[89]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad74f8 "enqueue running_tasks = 6" }	UtilMemLog::Line
+		[90]	{ timestamp=1258675 thread_id=36533349824 line=0x0000000020ad7608 "worker running task" }	UtilMemLog::Line
+		[91]	{ timestamp=1258675 thread_id=36533346368 line=0x0000000020ad7718 "worker wakeup queued_tasks=5" }	UtilMemLog::Line
+		[92]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad7828 "wait locking mutex" }	UtilMemLog::Line
+		[93]	{ timestamp=1258675 thread_id=36533346368 line=0x0000000020ad7938 "worker running task" }	UtilMemLog::Line
+		[94]	{ timestamp=1258675 thread_id=36533350976 line=0x0000000020ad7a48 "worker wakeup queued_tasks=4" }	UtilMemLog::Line
+		[95]	{ timestamp=1258675 thread_id=36533350976 line=0x0000000020ad7b58 "worker running task" }	UtilMemLog::Line
+		[96]	{ timestamp=1258675 thread_id=36533348672 line=0x0000000020ad7c68 "worker wakeup queued_tasks=3" }	UtilMemLog::Line
+		[97]	{ timestamp=1258675 thread_id=36533348672 line=0x0000000020ad7d78 "worker running task" }	UtilMemLog::Line
+		[98]	{ timestamp=1258675 thread_id=36533347520 line=0x0000000020ad7e88 "worker wakeup queued_tasks=2" }	UtilMemLog::Line
+		[99]	{ timestamp=1258675 thread_id=36533347520 line=0x0000000020ad7f98 "worker running task" }	UtilMemLog::Line
+		[100]	{ timestamp=1258675 thread_id=36533352128 line=0x0000000020ad80a8 "worker wakeup queued_tasks=1" }	UtilMemLog::Line
+		[101]	{ timestamp=1258675 thread_id=36533352128 line=0x0000000020ad81b8 "worker running task" }	UtilMemLog::Line
+		[102]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad82c8 "wait waiting" }	UtilMemLog::Line
+		[103]	{ timestamp=1258675 thread_id=36533349824 line=0x0000000020ad83d8 "worker locking mutex" }	UtilMemLog::Line
+		[104]	{ timestamp=1258675 thread_id=36533349824 line=0x0000000020ad84e8 "worker running_tasks = 5" }	UtilMemLog::Line
+		[105]	{ timestamp=1258675 thread_id=36533349824 line=0x0000000020ad85f8 "worker waiting" }	UtilMemLog::Line
+		[106]	{ timestamp=1258675 thread_id=36533348672 line=0x0000000020ad8708 "worker locking mutex" }	UtilMemLog::Line
+		[107]	{ timestamp=1258675 thread_id=36533348672 line=0x0000000020ad8818 "worker running_tasks = 4" }	UtilMemLog::Line
+		[108]	{ timestamp=1258675 thread_id=36533348672 line=0x0000000020ad8928 "worker waiting" }	UtilMemLog::Line
+		[109]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad8a38 "wait wakeup running_tasks = 4" }	UtilMemLog::Line
+		[110]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad8b48 "wait waiting" }	UtilMemLog::Line
+		[111]	{ timestamp=1258675 thread_id=36533347520 line=0x0000000020ad8c58 "worker locking mutex" }	UtilMemLog::Line
+		[112]	{ timestamp=1258675 thread_id=36533347520 line=0x0000000020ad8d68 "worker running_tasks = 3" }	UtilMemLog::Line
+		[113]	{ timestamp=1258675 thread_id=36533346368 line=0x0000000020ad8e78 "worker locking mutex" }	UtilMemLog::Line
+		[114]	{ timestamp=1258675 thread_id=36533346368 line=0x0000000020ad8f88 "worker running_tasks = 2" }	UtilMemLog::Line
+		[115]	{ timestamp=1258675 thread_id=36533352128 line=0x0000000020ad9098 "worker locking mutex" }	UtilMemLog::Line
+		[116]	{ timestamp=1258675 thread_id=36533352128 line=0x0000000020ad91a8 "worker running_tasks = 1" }	UtilMemLog::Line
+		[117]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad92b8 "wait wakeup running_tasks = 1" }	UtilMemLog::Line
+		[118]	{ timestamp=1258675 thread_id=36533339456 line=0x0000000020ad93c8 "wait waiting" }	UtilMemLog::Line
+		[119]	{ timestamp=1258675 thread_id=36533350976 line=0x0000000020ad94d8 "worker locking mutex" }	UtilMemLog::Line
+		[120]	{ timestamp=1258675 thread_id=36533350976 line=0x0000000020ad95e8 "worker running_tasks = 0" }	UtilMemLog::Line
+		[121]	{ timestamp=1258675 thread_id=36533352128 line=0x0000000020ad96f8 "worker waiting" }	UtilMemLog::Line
+		[122]	{ timestamp=1258675 thread_id=36533350976 line=0x0000000020ad9808 "worker waiting" }	UtilMemLog::Line
+		[123]	{ timestamp=1258675 thread_id=36533346368 line=0x0000000020ad9918 "worker waiting" }	UtilMemLog::Line
+		[124]	{ timestamp=1258675 thread_id=36533347520 line=0x0000000020ad9a28 "worker waiting" }	UtilMemLog::Line