[Bug 42470] New: Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

Bug ID: 42470
           Summary: Frequent critical section timeouts in winetricks
                    dotnet46
           Product: Wine
           Version: 2.2
          Hardware: x86
                OS: Linux
            Status: NEW
          Keywords: download, Installer
          Severity: normal
          Priority: P2
         Component: -unknown
          Assignee: [e-mail]
          Reporter: [e-mail]
      Distribution: Gentoo

Created attachment 57323
  --> https://bugs.winehq.org/attachment.cgi?id=57323
bt all

I've been seeing this for a few weeks, but I haven't been able to isolate the
cause. It's causing me a lot of grief with winetricks-test.

I'll attach the output of bt all for two separate runs. Unfortunately it seems
I didn't put the deadlocked thread in my original bt all output, but I'll
include it anyway. My most recent run was:

err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process
heap section" wait timed out in thread 0040, blocked by 0041, retrying (60 sec)

(also in the attachment).

The issue is very reliably reproduced on my machine, if further logs/debugging
is needed.

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #1 from Austin English  ---
Created attachment 57324
  --> https://bugs.winehq.org/attachment.cgi?id=57324
bt all 2

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #2 from Dmitry Timoshkov  ---
There are suspicious stalls at msvcrt.dll unloading code, does using native
msvcrt help?

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #3 from Austin English  ---
(In reply to Dmitry Timoshkov from comment #2)
> There are suspicious stalls at msvcrt.dll unloading code, does using native
> msvcrt help?

It seems to, yes*

*There seems to be a separate regression causing mscorsvw.exe (from .Net 2.0)
to sometimes hang. It's most notable when running winetricks-test dotnet. I'm
attempting a bisect now (running it in a loop 10 times), to see if I can
pinpoint the cause of that. It's notable that this hang occurs after doing
`winetricks vcrun6 msvcrt=native`.

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #4 from Austin English  ---
(In reply to Austin English from comment #3)
> (In reply to Dmitry Timoshkov from comment #2)
> > There are suspicious stalls at msvcrt.dll unloading code, does using native
> > msvcrt help?
>
> It seems to, yes*
>
> *There seems to be a separate regression causing mscorsvw.exe (from .Net
> 2.0) to sometimes hang. It's most notable when running winetricks-test
> dotnet. I'm attempting a bisect now (running it in a loop 10 times), to see
> if I can pinpoint the cause of that. It's notable that this hang occurs
> after doing `winetricks vcrun6 msvcrt=native`.

I was able to get another critical section timeout, with native msvcrt:
err:ntdll:RtlpWaitForCriticalSection section 0x110060 "heap.c: main process
heap section" wait timed out in thread 0064, blocked by 0000, retrying (60 sec)

Backtracing for thread 0064 in process 0063
(y:\fde9932b682c120f5eb56655bd58\update\update.exe):
Backtrace:
=>0 0xf77e9c79 __kernel_vsyscall+0x9() in [vdso].so (0x00000000)
  1 0xf74cecb7 syscall+0x26() in libc.so.6 (0x00000000)
  2 0x7bc3cf9e RtlpWaitForCriticalSection+0x19d(crit=<couldn't compute
location>) [/home/austin/wine-git/dlls/ntdll/critsection.c:69] in ntdll
(0x0033fa38)
  3 0x7bc3d924 RtlEnterCriticalSection+0x53(crit=<couldn't compute location>)
[/home/austin/wine-git/dlls/ntdll/critsection.c:566] in ntdll (0x0033fa78)
  4 0x7bc506ef RtlFreeHeap+0x17e(heap=<couldn't compute location>,
flags=<couldn't compute location>, ptr=<couldn't compute location>)
[/home/austin/wine-git/dlls/ntdll/heap.c:1759] in ntdll (0x0033faf8)
  5 0x7bc3cd2b RtlDeleteCriticalSection+0x5a(crit=<couldn't compute location>)
[/home/austin/wine-git/dlls/ntdll/critsection.c:404] in ntdll (0x0033fb48)
  6 0x78003c4a in msvcrt (+0x3c49) (0x0033fb98)
  7 0x7bc56d27 MODULE_InitDLL+0x106(wm=<is not available>, reason=<is not
available>, lpReserved=0x1) [/home/austin/wine-git/dlls/ntdll/loader.c:1120] in
ntdll (0x0033fcf8)
  8 0x7bc5780a process_detach+0x49()
[/home/austin/wine-git/dlls/ntdll/loader.c:1297] in ntdll (0x0033fd28)
  9 0x7bc57891 LdrShutdownProcess+0x50()
[/home/austin/wine-git/dlls/ntdll/loader.c:2738] in ntdll (0x0033fd38)
  10 0x7bc578e6 RtlExitUserProcess+0x45(status=<couldn't compute location>)
[/home/austin/wine-git/dlls/ntdll/loader.c:2750] in ntdll (0x0033fd68)
  11 0x7b460902 ExitProcess+0x11() in kernel32 (0x0033fd8c)
  12 0x00000643 (0x0033fd8c)
  13 0x780039b1 in msvcrt (+0x39b0) (0x0033fe40)
  14 0x7b4608ec call_process_entry+0xb() in kernel32 (0x0033fe58)
  15 0x7b461944 start_process+0x73(entry=<couldn't compute location>)
[/home/austin/wine-git/dlls/kernel32/process.c:1116] in kernel32 (0x0033fe98)
  16 0x7bc80a20 call_thread_func_wrapper+0xb() in ntdll (0x0033feb8)
  17 0x7bc8398f call_thread_func+0xce(entry=0x7b4618d0, arg=0x106a581,
frame=0x33ffc8) [/home/austin/wine-git/dlls/ntdll/signal_i386.c:2759] in ntdll
(0x0033ffa8)
  18 0x7bc809fe call_thread_entry_point+0x11() in ntdll (0x0033ffc8)
  19 0x7bc54783 start_process+0x12(arg=0xffdeaf64)
[/home/austin/wine-git/dlls/ntdll/loader.c:3054] in ntdll (0x0033ffe8)
  20 0xf761294d wine_call_on_stack+0x1c() in libwine.so.1 (0x00000000)
  21 0xf7612ac0 wine_switch_to_stack+0x1f(func=0x7bc54770, arg=0xffdeaf64,
stack=0x340000) [/home/austin/wine-git/libs/wine/port.c:77] in libwine.so.1
(0xffdeaf38)
  22 0x7bc5a53e LdrInitializeThunk+0x24d(kernel_start=<couldn't compute
location>, unknown2=<couldn't compute location>, unknown3=<couldn't compute
location>, unknown4=<couldn't compute location>)
[/home/austin/wine-git/dlls/ntdll/loader.c:3115] in ntdll (0xffdeaf88)
  23 0x7b467992 __wine_kernel_init+0x951()
[/home/austin/wine-git/dlls/kernel32/process.c:1310] in kernel32 (0xffdec0f8)
  24 0x7bc5b383 __wine_process_init+0x162()
[/home/austin/wine-git/dlls/ntdll/loader.c:3324] in ntdll (0xffdec178)
  25 0xf7610cfb wine_init+0x2ba(argc=0x4, argv=0xffdec6c4, error="",
error_size=0x400) [/home/austin/wine-git/libs/wine/loader.c:956] in
libwine.so.1 (0xffdec1c8)
  26 0x7c000ac2 main+0x81(argc=<is not available>, argv=<is not available>)
[/home/austin/wine-git/loader/main.c:254] in <wine-loader> (0xffdec618)
  27 0xf74065ce __libc_start_main+0xdd() in libc.so.6 (0x00000000)

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #5 from Austin English  ---
Created attachment 57390
  --> https://bugs.winehq.org/attachment.cgi?id=57390
bt all (with native msvcrt)

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #6 from Dmitry Timoshkov  ---
Created attachment 57444
  --> https://bugs.winehq.org/attachment.cgi?id=57444
hack

Something like the attached hack may help.

A little bit of a background:
from the attached backtrace it looks like the deadlock happens during process
exit when one of the threads that held the process heap lock has been killed,
and the msvcrt's PROCESS_DETACH handler calls RtlDeleteCriticalSection()
which hangs when it calls RtlFreeHeap() for the critical section's DebugInfo.

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

Austin English  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Blocks|                            |42542

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #7 from Austin English  ---
(In reply to Dmitry Timoshkov from comment #6)
> Created attachment 57444 [details]
> hack
>
> Something like the attached hack may help.
>
> A little bit of a background:
> from the attached backtrace it looks like the deadlock happens during process
> exit when one of the threads that held the process heap lock has been killed,
> and the msvcrt's PROCESS_DETACH handler calls RtlDeleteCriticalSection()
> which hangs when it calls RtlFreeHeap() for the critical section's DebugInfo.

Hi Dmitry,

Sorry for the delay. I made a note to test this and promptly forgot about it
for several months :(.

In any case, it doesn't seem to help. I was able to get a crash on my first
attempt with this patch. Later attempts ran further, so it doesn't seem to make
it any worse either..

This was without native msvcrt. I'll try that next.

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #8 from Austin English  ---
Occurred on try 2 with patch + native msvcrt :/

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #9 from Dmitry Timoshkov  ---
Created attachment 62014
  --> https://bugs.winehq.org/attachment.cgi?id=62014
hack2

Please try the attached patch. With it I can't reproduce the hangs or
deadlocks while installing dotnet452 10 times in a row using i7 with 8 cores.

Just for the record main offenders are clr.dll and mscoree.dll, and the
deadlocks happen only during the dotnet40 installation:

009d:err:ntdll:RtlpWaitForCriticalSection process
L"C:\windows\Microsoft.NET\Framework\v4.0.30319\mscorsvw.exe" is shutting
down, current_dll L"clr.dll", returning STATUS_SUCCESS
009d:err:ntdll:RtlpWaitForCriticalSection process
L"C:\windows\Microsoft.NET\Framework\v4.0.30319\mscorsvw.exe" is shutting
down, current_dll L"clr.dll", returning STATUS_SUCCESS
009d:err:ntdll:RtlpWaitForCriticalSection process
L"C:\windows\Microsoft.NET\Framework\v4.0.30319\mscorsvw.exe" is shutting
down, current_dll L"mscoree.dll", returning STATUS_SUCCESS
009d:err:ntdll:RtlpWaitForCriticalSection process
L"C:\windows\Microsoft.NET\Framework\v4.0.30319\mscorsvw.exe" is shutting
down, current_dll L"mscoree.dll", returning STATUS_SUCCESS

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #10 from Dmitry Timoshkov  ---
I sent a test case along with a fix to wine-devel:
https://www.winehq.org/pipermail/wine-devel/2018-August/130236.html
https://www.winehq.org/pipermail/wine-devel/2018-August/130237.html

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #11 from Austin English  ---
(In reply to Dmitry Timoshkov from comment #10)
> I sent a test case along with a fix to wine-devel:
> https://www.winehq.org/pipermail/wine-devel/2018-August/130236.html
> https://www.winehq.org/pipermail/wine-devel/2018-August/130237.html

Excellent, thanks Dmitry!

I've been running hack2 in a loop for dotnet46 (no native msvcrt), and at 16
successes so far, so looking very good!

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #12 from Austin English  ---
(In reply to Austin English from comment #11)
> (In reply to Dmitry Timoshkov from comment #10)
> > I sent a test case along with a fix to wine-devel:
> > https://www.winehq.org/pipermail/wine-devel/2018-August/130236.html
> > https://www.winehq.org/pipermail/wine-devel/2018-August/130237.html
>
> Excellent, thanks Dmitry!
>
> I've been running hack2 in a loop for dotnet46 (no native msvcrt), and at 16
> successes so far, so looking very good!

Ran 50 times in a loop overnight without issue.

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

Dmitry Timoshkov  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
      Fixed by SHA1|                            |7def0f200f117a5a72ce454004a
                   |                            |c4fd600ef8a4b
         Resolution|---                         |FIXED

--- Comment #13 from Dmitry Timoshkov  ---
(In reply to Dmitry Timoshkov from comment #10)
> I sent a test case along with a fix to wine-devel:
> https://www.winehq.org/pipermail/wine-devel/2018-August/130236.html
> https://www.winehq.org/pipermail/wine-devel/2018-August/130237.html

The fix was committed as 7def0f200f117a5a72ce454004ac4fd600ef8a4b.

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

--- Comment #14 from Austin English  ---
(In reply to Dmitry Timoshkov from comment #13)
> (In reply to Dmitry Timoshkov from comment #10)
> > I sent a test case along with a fix to wine-devel:
> > https://www.winehq.org/pipermail/wine-devel/2018-August/130236.html
> > https://www.winehq.org/pipermail/wine-devel/2018-August/130237.html
>
> The fix was committed as 7def0f200f117a5a72ce454004ac4fd600ef8a4b.

Thanks again Dmitry!

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

Nikolay Sivov  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
          Component|-unknown                    |ntdll

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

Alexandre Julliard  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED

--- Comment #15 from Alexandre Julliard  ---
Closing bugs fixed in 3.14.

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

Michael Stefaniuc  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
   Target Milestone|---                         |3.0.x

[Bug 42470] Frequent critical section timeouts in winetricks dotnet46

https://bugs.winehq.org/show_bug.cgi?id=42470

Michael Stefaniuc  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
   Target Milestone|3.0.x                       |---

--- Comment #16 from Michael Stefaniuc  ---
Removing the 3.0.x milestone from bug fixes included in 3.0.4.