https://bugs.winehq.org/show_bug.cgi?id=48112
Bug ID: 48112 Summary: The tests trigger heap and loader critical section lockups Product: Wine Version: unspecified Hardware: x86 OS: Linux Status: NEW Severity: normal Priority: P2 Component: kernel32 Assignee: wine-bugs@winehq.org Reporter: fgouget@codeweavers.com Distribution: ---
The log of *some* WineTest runs contains critical section errors like the following:
Running: httpapi:httpapi (222 of 670) [...] 01d8:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap. c: main process heap section" wait timed out in thread 01d8, blocked by 01d4, retrying (60 sec) 01f8:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap. c: main process heap section" wait timed out in thread 01f8, blocked by 01d4, retrying (60 sec) 0201:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 0201, blocked by 01d4, retrying (60 sec) 01d9:err:ntdll:RtlpWaitForCriticalSection section 0x7be970a0 "../../../wine/dlls/ntdll/loader.c: loader_section" wait timed out in thread 01d9, blocked by 0201, retrying (60 sec) 01d7:err:ntdll:RtlpWaitForCriticalSection section 0x7be970a0 "../../../wine/dlls/ntdll/loader.c: loader_section" wait timed out in thread 01d7, blocked by 0201, retrying (60 sec) 01f7:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 01f7, blocked by 01d4, retrying (60 sec) 01d8:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 01d8, blocked by 01d4, retrying (60 sec) 01f8:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 01f8, blocked by 01d4, retrying (60 sec) 0201:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 0201, blocked by 01d4, retrying (60 sec) 01d9:err:ntdll:RtlpWaitForCriticalSection section 0x7be970a0 "../../../wine/dlls/ntdll/loader.c: loader_section" wait timed out in thread 01d9, blocked by 0201, retrying (60 sec) 01d7:err:ntdll:RtlpWaitForCriticalSection section 0x7be970a0 "../../../wine/dlls/ntdll/loader.c: loader_section" wait timed out in thread 01d7, blocked by 0201, retrying (60 sec) Running: ieframe:ie (223 of 670) Running: ieframe:intshcut (224 of 670) 01dc:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 01dc, blocked by 01d4, retrying (60 sec) 01da:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 01da, blocked by 01d4, retrying (60 sec) [... and more later on, all the way to...] Running: wtsapi32:wtsapi (665 of 670) 01dc:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "../../../wine/dlls/ntdll/heap.c: main process heap section" wait timed out in thread 01dc, blocked by 01d4, retrying (60 sec) [...]
It's always either the heap critical section or the loader one. Unfortunately the ERR() message does not show the process id so it's impossible to know which process got stuck. We can rule out httpapi:httpapi and the tests that ran before because the WineTest report indicates that they ran for less than 1 second:
gdiplus:region:01ae done (0) in 0s gdiplus:stringformat:01b4 done (0) in 0s hid:device:01b7 done (0) in 1s hlink:browse_ctx:01b9 done (0) in 0s hlink:hlink:0118 done (0) in 0s hnetcfg:policy:0112 done (0) in 0s httpapi:httpapi:014f done (0) in 1s
* The lockups seem to continue until the end of the log. So they could be happening in either WineTest.exe, or one of Wine's internal processes: explorer.exe, plugplay.exe, services.exe or winedevice.exe. * httpapi:httpapi is always where the lockups appear first. * Since the initial timeout is 5 seconds, it could in fact be caused by a test that ran up to 5 seconds before httpapi:httpapi. Unfortunately the WineTest report has a 1 second granularity so it's hard to know how many tests ran in 5 seconds. * When the lockups occur WineTest takes 2 to 5 minutes longer to run. So they slow the tests down somehow.