https://bugs.winehq.org/show_bug.cgi?id=48847
Bug ID: 48847 Summary: dotnet471: often gets a critical section timeout Product: Wine Version: 5.5 Hardware: x86 OS: Linux Status: NEW Severity: normal Priority: P2 Component: -unknown Assignee: wine-bugs@winehq.org Reporter: austinenglish@gmail.com Distribution: ---
Created attachment 66764 --> https://bugs.winehq.org/attachment.cgi?id=66764 bt all
I've been seeing this when running winetricks-test, for dotnet46* and dotnet471. This info is for dotnet471.
austin@laptop ~ $ grep 'wait timed out' /tmp/out.txt | sort -u 0048:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 0048, blocked by 006e, retrying (60 sec) 006e:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 006e, blocked by 0174, retrying (60 sec) 00ad:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 00ad, blocked by 006e, retrying (60 sec) 00bb:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 00bb, blocked by 0174, retrying (60 sec) 00e2:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 00e2, blocked by 006e, retrying (60 sec) 0114:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 0114, blocked by 0174, retrying (60 sec) 0166:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 0166, blocked by 006e, retrying (60 sec) 0169:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 0169, blocked by 006e, retrying (60 sec) 016c:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 016c, blocked by 0174, retrying (60 sec) 0193:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 0193, blocked by 006e, retrying (60 sec)
winedbg bt all is attached.
https://bugs.winehq.org/show_bug.cgi?id=48847
Anastasius Focht focht@gmx.net changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |focht@gmx.net Keywords| |dotnet, Installer
--- Comment #1 from Anastasius Focht focht@gmx.net --- Hello Austin,
the 'bt all' doesn't seem to match your console output. There are way too many differences in the thread ids. Even if thread 006e has died while owning lock(s), many other threads blocked by it don't appear in winedbg list.
Please provide console and winedbg logs from the same run. Include 'info process' and 'info thread' output as well.
Your 'bt all' shows it's already happening at .NET Framework 4.5 verb. Does testing 'winetricks -q dotnet45' exhibit the same problems?
--- snip --- Backtracing for thread 0009 in process 0008 (Y:\dotnet45\dotnetfx45_full_x86_x64.exe): --- snip ---
Also try to make a "lightweight" trace log if possible:
--- snip --- $ WINEDEBUG=+timestamp,+pid,+seh,+process,+loaddll ... >>log.txt 2>&1 --- snip ---
Relay logs would be rather huge and make the issue potentially disappear.
FYI I can't reproduce it here with Wine 5.5. It successfully installed ten consecutive times, each with clean 64-bit WINEPREFIX.
Regards
https://bugs.winehq.org/show_bug.cgi?id=48847
Austin English austinenglish@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Attachment #66764|0 |1 is obsolete| |
--- Comment #2 from Austin English austinenglish@gmail.com --- Created attachment 66784 --> https://bugs.winehq.org/attachment.cgi?id=66784 terminal output (try 2)
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #3 from Austin English austinenglish@gmail.com --- Created attachment 66785 --> https://bugs.winehq.org/attachment.cgi?id=66785 bt all
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #4 from Austin English austinenglish@gmail.com --- Created attachment 66786 --> https://bugs.winehq.org/attachment.cgi?id=66786 info process/thread
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #5 from Austin English austinenglish@gmail.com --- I wasn't able to reproduce in 25 tries with WINEDEBUG set, but was able to get the output/winedbg info from another deadlock.
Note that I've seen similar in dotnet461 (usually when running winetricks' tests), but I'm hoping they're the same root issue.
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #6 from Anastasius Focht focht@gmx.net --- Hello Austin,
--- snip --- Wine-dbg>info process pid threads executable (all id:s are in hex) 0000019d 1 'winedbg.exe' 0000001b 4 'explorer.exe' 0000000e 10 'services.exe' 000000d8 4 _ 'mscorsvw.exe' 000000c7 5 _ 'rpcss.exe' 000000c0 7 _ 'svchost.exe' 00000020 5 _ 'winedevice.exe' 00000019 3 _ 'plugplay.exe' 00000011 4 _ 'winedevice.exe' 00000008 1 'NDP461-KB3102436-x86-x64-AllOS-ENU.exe' 0000002e 5 _ 'Setup.exe' 0000003c 2 _ 'msiexec.exe' 00000059 14 _ 'ngen.exe' 0000017d 5 _ 'mscorsvw.exe' 00000179 6 _ 'mscorsvw.exe' 000000a6 12 _ 'mscorsvw.exe'
Wine-dbg>info thread process tid prio (all id:s are in hex) 00000008 NDP461-KB3102436-x86-x64-AllOS-ENU.exe 00000009 0 ... 00000059 ngen.exe 0000018e 0 0000014b 0 00000137 0 0000011b 0 00000117 0 00000102 0 00000100 0 000000a7 0 00000132 0 00000116 0 0000010e 0 0000010b 0 00000108 0 0000005a 0 --- snip ---
--- snip --- ... 0105:err:ole:ifproxy_release_public_refs IRemUnknown_RemRelease failed with error 0x800706be 0105:err:ole:ifproxy_release_public_refs IRemUnknown_RemRelease failed with error 0x800706be 0105:err:ole:ifproxy_release_public_refs IRemUnknown_RemRelease failed with error 0x800706be 0105:err:ole:ifproxy_release_public_refs IRemUnknown_RemRelease failed with error 0x800706be 0105:err:ole:ifproxy_release_public_refs IRemUnknown_RemRelease failed with error 0x800706be ... 0105:fixme:ole:NdrClearOutParameters (01BEF664,008FAC56,01BEFD9C): stub 0105:err:seh:setup_exception_record stack overflow 756 bytes in thread 0105 eip 1008f936 esp 01af103c stack 0x1af0000-0x1af1000-0x1bf0000 00a7:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 00a7, blocked by 0105, retrying (60 sec) 0100:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 0100, blocked by 0105, retrying (60 sec) 0132:err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process heap section" wait timed out in thread 0132, blocked by 0105, retrying (60 sec) 0108:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 0108, blocked by 0132, retrying (60 sec) 014b:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 014b, blocked by 0132, retrying (60 sec) 011b:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 011b, blocked by 0132, retrying (60 sec) 0137:err:ntdll:RtlpWaitForCriticalSection section 0x7bd2c220 "loader.c: loader_section" wait timed out in thread 0137, blocked by 0132, retrying (60 sec) ... --- snip ---
Thread 0105 seems to be the culprit here. It was likely belonging to ngen client (010x tid range). Happened maybe during update of GAC ('ngen update' / 'ngen executeQueuedItems').
If that's the case you could try to force run GAC update continuously (loop) after installation and see if it breaks at some point (tee + grep for exception/timeout patterns in output).
--- snip --- # 32-bit assemblies $ wine "c:\windows\Microsoft.NET\Framework\v4.0.30319\ngen.exe" update
# 64-bit assemblies $ wine "c:\windows\Microsoft.NET\Framework64\v4.0.30319\ngen.exe" update --- snip ---
Regards
https://bugs.winehq.org/show_bug.cgi?id=48847
Igor Zinovyev zinigor+winehq@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |zinigor+winehq@gmail.com
--- Comment #7 from Igor Zinovyev zinigor+winehq@gmail.com --- The GOG Galaxy application seems to be affected by this bug as well. Since this entry seems to be quite specific to the dotnet installation, should I add the trace here, or create a separate report?
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #8 from Austin English austinenglish@gmail.com --- (In reply to Anastasius Focht from comment #1)
FYI I can't reproduce it here with Wine 5.5. It successfully installed ten consecutive times, each with clean 64-bit WINEPREFIX.
FWIW, with winetricks-test, it's relatively reliable.
Running dotnet471 in a loop of 1000 last night, didn't fail until iteration #107.
winedbg hung when I tried to dump info. Not sure if it was machine state or a wine regression, I'm retrying with WINEDEBUG set (and will try other wine versions if needed).
https://bugs.winehq.org/show_bug.cgi?id=48847
Alexandr Oleynikov sashok.olen@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |sashok.olen@gmail.com
--- Comment #9 from Alexandr Oleynikov sashok.olen@gmail.com --- I've noticed that this issue happens more commonly on slow machines. Perhaps it would be easier to reproduce this by introducing some kind of a hard load on the system?
https://bugs.winehq.org/show_bug.cgi?id=48847
Forest forestix@sonic.net changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |forestix@sonic.net
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #10 from Austin English austinenglish@gmail.com --- Still in wine-6.6.
https://bugs.winehq.org/show_bug.cgi?id=48847
ax 34noff otaku@rambler.ru changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |otaku@rambler.ru
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #11 from ax 34noff otaku@rambler.ru --- It looks like a regression, i didn't have such problem with Wine 5.7 from Lutris.
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #12 from Austin English austinenglish@gmail.com --- (In reply to ax 34noff from comment #11)
It looks like a regression, i didn't have such problem with Wine 5.7 from Lutris.
It definitely is a regression. It's not very clear what caused it though, as there have been several dotnet regressions (some fixed, some not) over the last year.
At this point, it would likely require bisecting + cherry picking multiple fixes, and is not for the faint of heart..
https://bugs.winehq.org/show_bug.cgi?id=48847
m0rvj johnpgoodman@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |johnpgoodman@gmail.com
--- Comment #13 from m0rvj johnpgoodman@gmail.com --- If someone can explain to me how to automate the testing, I'd be minded to give it a go... I've done plenty of regression testing so I know how to do the bisect etc. The bit I'd need advice on is how to test whether the dotnet installation succeeded?
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #14 from Austin English austinenglish@gmail.com --- (In reply to m0rvj from comment #13)
If someone can explain to me how to automate the testing, I'd be minded to give it a go... I've done plenty of regression testing so I know how to do the bisect etc. The bit I'd need advice on is how to test whether the dotnet installation succeeded?
`winetricks --verify dotnet471` will reproduce it, rarely, when run in a loop (be sure to cleanup between runs). I more often see it when running winetricks's unit tests, see https://github.com/Winetricks/winetricks#tests
But again, it's not consistent, and what causes it to fail is unclear. In addition, native .net in general has had several intermixed regressions that will make this a challenge to accurately bisect.
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #15 from m0rvj johnpgoodman@gmail.com --- Would a debug log help? If so which options are needed? WINEDEBUG=+seh
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #16 from Austin English austinenglish@gmail.com --- I retested with 7.6, now that 52722 is fixed. Reproduced it on the 9th try. Unfortunately didn't get a good backtrace (bug 52790/pebkac). I'll upload the lightweight (WINEDEBUG=+timestamp,+pid,+seh,+process,+loaddll) log.
Will try again..
https://bugs.winehq.org/show_bug.cgi?id=48847
--- Comment #17 from Austin English austinenglish@gmail.com --- Created attachment 72176 --> https://bugs.winehq.org/attachment.cgi?id=72176 WINEDEBUG=+timestamp,+pid,+seh,+process,+loaddll, wine-7.6