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.
https://bugs.winehq.org/show_bug.cgi?id=48112
François Gouget fgouget@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Keywords| |source
--- Comment #1 from François Gouget fgouget@codeweavers.com --- A more in-depth analysis of the WineTest logs shows that the first timeout message does not always show up while the httpapi:httpapi test is running.
These are all the logs where the "wait timed out in thread" error showed up. Except where otherwise noted, these are all from WineTest runs. Now I wonder if they are all blocked by a thread that got an seh.
58251/1/6/log: Running: httpapi:httpapi (217 of 665) -> Blocked by a thread that got an seh
58326/1/3/log: Running: httpapi:httpapi (217 of 665) -> Blocked by a thread that got an seh
58342/1/1/log: Before the first test 58342/1/2/log: Running: quartz:waveparser (25 of 25) -> strmbase/transform patch
58503/1/3/log: Running: httpapi:httpapi (217 of 665) 58772/1/1/log: Running: httpapi:httpapi (217 of 666) 58772/1/4/log: Running: httpapi:httpapi (217 of 666) 58772/1/5/log: Running: ieframe:intshcut (219 of 666) 58937/1/6/log: Running: httpapi:httpapi (217 of 667) 58975/1/2/log: Running: quartz:filesource (454 of 667) 58975/1/4/log: Running: httpapi:httpapi (217 of 667) 59224/1/3/log: Running: httpapi:httpapi (217 of 665) 59344/1/5/log: Running: httpapi:httpapi (217 of 665) 59344/1/6/log: Running: httpapi:httpapi (217 of 665) 59603/1/3/log: Running: httpapi:httpapi (217 of 665) 59603/1/5/log: Running: httpapi:httpapi (217 of 665)
59857/1/1/log: Running: winhttp:url (619 of 665) -> Blocked by thread 0000!
59857/1/2/log: Running: httpapi:httpapi (217 of 665) 59857/1/6/log: Running: httpapi:httpapi (217 of 665) -> Both blocked by a thread that got an seh
59959/1/2/log: Running: httpapi:httpapi (221 of 669) 60105/1/3/log: Running: httpapi:httpapi (221 of 669)
60225/1/6/log: Running: httpapi:httpapi (222 of 670) -> Both blocked by a thread that got an seh
https://bugs.winehq.org/show_bug.cgi?id=48112
--- Comment #2 from François Gouget fgouget@codeweavers.com --- The "Running: " lines are not in sync with the error lines and tend to arrive late. So these error messages could just as well be triggered by the next test to start.
https://bugs.winehq.org/show_bug.cgi?id=48112
--- Comment #3 from François Gouget fgouget@codeweavers.com --- I think the thread getting blocked is one of explorer.exe's threads.
https://bugs.winehq.org/show_bug.cgi?id=48112
François Gouget fgouget@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Summary|The tests trigger heap and |The tests (httpapi:httpapi) |loader critical section |trigger heap and loader |lockups |critical section lockups Keywords| |testcase
https://bugs.winehq.org/show_bug.cgi?id=48112
François Gouget fgouget@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Depends on| |51496
--- Comment #4 from François Gouget fgouget@codeweavers.com --- riched20:editor has been found to cause similar symptoms recently see bug 51496).
In the riched20:editor case the issue was an infinite loop that overflowed the stack and triggered a telltale "virtual_setup_exception stack overflow" error message. But what ties it to this issue is that the crash happened while explorer.exe was holding the heap critical section, resulting in the same error messages as in this bug.
Once bug 51496 is fixed this issue should be reinvestigated to see if there are still critical section errors in the WineTest logs and, if so, to check if the virtual_setup_exception error is present too.
https://bugs.winehq.org/show_bug.cgi?id=48112 Bug 48112 depends on bug 51496, which changed state.
Bug 51496 Summary: On KDE riched20:editor triggers a clipboard infinite loop, crashing explorer.exe https://bugs.winehq.org/show_bug.cgi?id=51496
What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution|--- |FIXED
https://bugs.winehq.org/show_bug.cgi?id=48112
François Gouget fgouget@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution|--- |WORKSFORME
--- Comment #5 from François Gouget fgouget@codeweavers.com --- Bug 48278 also reports critical section deadlocks involving the "main process heap section" and "loader_section" so it may be related.
But more importantly the Wine tests no longer have critical section timeouts (also those are now reported as failures by the TestBot). It's not clear when this was fixed but I'm closing this bug.
https://bugs.winehq.org/show_bug.cgi?id=48112
Gijs Vermeulen gijsvrm@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED
--- Comment #6 from Gijs Vermeulen gijsvrm@gmail.com --- Closing WORKSFORME.
-
WineHQ Bugzilla