Intermittent hang/deadlock in .net core 5.0 RC1 while debugging

[joakimriedel]

Description

After upgrading our web application from 3.1 to 5.0 RC1, I get intermittent hangs/deadlocks while debugging. At first, I thought it was a problem specific to Visual Studio 16.8 preview 3 (https://developercommunity.visualstudio.com/content/problem/1187332/debugger-hangs-sporadically-in-visual-studio-2019.html), but I have now verified that the issue is the same when debugging through Visual Studio Code which makes me think this is related to the 5.0 RC1 runtime and not the IDE.

I have not been able to reproduce this when running the project without debugging (ctrl-f5) - only when debugging (f5).

Unfortunately I cannot reliably reproduce this, it seems to be timing related and more often happens when loading pages in the application that fires a lot of different connections to the server. The application also heavily uses EF Core and SignalR Core.

Configuration

.NET Core 5.0 RC1
Win10 build 2004
Threadripper CPU

Regression?

Yes. This never occurred in net core 3.1.

Other information

I find it very hard to debug this issue. It only happens when starting the project in the debugger. But since it totally hangs the debugger, I am unable to break into the application. I cannot attach another debugger, then I get the error "another debugger is already attached".

Some characteristics:

When it happens, the diagnostics logger stops updating

I cannot break or terminate the debugger

The IIS worker process is idle.

The output window stops logging any more entries. The last entry is at random, I cannot see any pattern in that the hang would happen after a certain kind of event.

The only way to get back control is to kill the IIS worker process manually through task manager.

I have followed the steps to generate a dotnet-dump, but do not know how to analyze it.

How can I go forward to resolve this? I can reproduce but not choose when to reproduce. Sometimes it hangs on first load, sometimes I have to click around in the application for a few minutes to reproduce.

Tagging subscribers to this area: @tommcdon
See info in area-owners.md if you want to be subscribed.

[joakimriedel]

Found the dotnet-trace tool and ran it for a few seconds on the hung process. It is not totally dead, it seems to be doing some GC-related things frequently seen in perfview:

Can I use the dotnet-trace tool with some arguments to better find out what's happening behind the scenes?

[joakimriedel]

Some more debugging. If I start with ctrl-f5 (no debugger) and later...

1. attach a native debugger such as WinDbg: does not reproduce
2. attach a managed debugger from Visual Studio: reproduce
3. first attach a native debugger (WinDbg) and then detach, and then a managed debugger (Visual Studio): does not reproduce

The third could be a red herring since it's an intermittent issue, but seems consistent. Also worth noting in the third case that the diagnostics tool in VS reports 1,3 gb of memory after I have been using a native debugger but only ~700 mb when I use a managed debugger.

[tommcdon]

@hoyosjs

[tommcdon]

@joakimriedel would it be possible to send us a dump of the debuggee, devenv, and mvsmon at the point of the hang? To securely share files, please open a VS Feedback Item and send us a link to it.
@caslan FYI

[joakimriedel]

@tommcdon please see the original VS Feedback Item in the first issue post above: https://developercommunity.visualstudio.com/content/problem/1187332/debugger-hangs-sporadically-in-visual-studio-2019.html

[joakimriedel]

Btw, it was another red herring about the breakpoints mentioned in the VS Feedback Item. This will reproduce without first setting any breakpoints in the code.

[joakimriedel]

@tommcdon I just found something! The frequency of this error happening depends on the amount of LogLevel I set. Using all "Debug" it reproduces almost instantly on first load of the application.

If I set all LogLevels to "Warning" (almost none or little log items) I cannot seem to reproduce.

Does this give you any pointers on where the problem might lie?

[josalem]

I have followed the steps to generate a dotnet-dump, but do not know how to analyze it.

@joakimriedel, if you collected a dump using dotnet-dump, you can use the dotnet-dump analyze verb to inspect it. If you run dotnet-dump analyze /path/to/dump and then enter the command clrstack -f -all it should dump the callstacks of all the threads in the process. It will include function names from your app, so if they're sensitive be sure to read the data and remove anything you need to before sharing here.

[joakimriedel]

@josalem very interesting, thanks for the tip! all threads but these three are in either System.Threading.Monitor.ObjWait or System.Threading.WaitHandle.WaitOneCore

thread A

OS Thread Id: 0x757c
        Child SP               IP Call Site
000000010A158B38                  [HelperMethodFrame_PROTECTOBJ: 000000010a158b38] System.Diagnostics.Debugger.CustomNotification(System.Diagnostics.ICustomDebuggerNotification)
000000010A158C50 00007FF8E50B75BB System.Private.CoreLib.dll!System.Diagnostics.Debugger.NotifyOfCrossThreadDependencySlow() + 27 [/_/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Debugger.cs @ 35]
... 150+ deep call stack

thread B

OS Thread Id: 0x45a8
        Child SP               IP Call Site
000000010D2499C8                  [HelperMethodFrame_2OBJ: 000000010d2499c8] System.Diagnostics.Debugger.Log(Int32, System.String, System.String)
000000010D249D00 00007FF8E50B2065 System.Private.CoreLib.dll!System.Diagnostics.DebugProvider.WriteCore(System.String) + 133 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/DebugProvider.Windows.cs @ 62]
000000010D249D70 00007FF8E50B1EA6 System.Private.CoreLib.dll!System.Diagnostics.DebugProvider.Write(System.String) + 134 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/DebugProvider.cs @ 64]
... 140+ deep call stack

thread C

OS Thread Id: 0x5dc4
        Child SP               IP Call Site
000000012497E5C0                  [InlinedCallFrame: 000000012497e5c0] System.Data.SqlClient.dll!System.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(System.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
000000012497E5C0                  [InlinedCallFrame: 000000012497e5c0] System.Data.SqlClient.dll!System.Data.SqlClient.SNINativeMethodWrapper.SNIReadSyncOverAsync(System.Data.SqlClient.SNIHandle, IntPtr ByRef, Int32)
... 30+ deep call stack

My amateur guess is that these three threads are deadlocking each other somehow. I made two dumps of the hung process a minute apart, and it showed the same three threads with the same call stack.

This actually strengthens the observation I had above that modifying the LogLevel will increase the likelihood of reproducing the error.

ping @tommcdon

[tommcdon]

@joakimriedel thank you for sending the VS feedback item our way. It looks like there may be a thread suspension related issue here that I am hoping @kouvel or @noahfalk can take a look at. It appears that the debugger is requesting debugger suspension but we are not able to synchronize for the debugger. If this a regression between P8 and RC1, then the stack below might be interesting. Out of curiosity, can you try disabling Tiered compilation by setting COMPLUS_TieredCompilation=0?

0:181> !ThreadState 1029228
    Debug Suspend Pending
    Legal to Join
    Background
    CLR Owns
    In Multi Threaded Apartment
    Fully initialized
    Thread Pool Worker Thread
0:181> k
 # Child-SP          RetAddr           Call Site
00 00000035`1154f118 00007ff9`b1ff619d ntdll!ZwWaitForAlertByThreadId+0x14 [minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 3891] 
01 00000035`1154f120 00007ff9`b1ff6052 ntdll!RtlpWaitOnAddressWithTimeout+0x81 [minkernel\ntos\rtl\waitaddr.c @ 851] 
02 00000035`1154f150 00007ff9`b1ff5e6d ntdll!RtlpWaitOnAddress+0xae [minkernel\ntos\rtl\waitaddr.c @ 1094] 
03 00000035`1154f1c0 00007ff9`b1fd15b4 ntdll!RtlpWaitOnCriticalSection+0xfd [minkernel\ntos\rtl\resource.c @ 1610] 
04 00000035`1154f2a0 00007ff9`b1fd13e2 ntdll!RtlpEnterCriticalSectionContended+0x1c4 [minkernel\ntos\rtl\resource.c @ 2317] 
05 00000035`1154f300 00007ff9`6379d80a ntdll!RtlEnterCriticalSection+0x42 [minkernel\ntos\rtl\resource.c @ 1923] 
06 00000035`1154f330 00007ff9`6376742f coreclr!CrstBase::Enter+0x5a [F:\workspace\_work\1\s\src\coreclr\src\vm\crst.cpp @ 330] 
07 (Inline Function) --------`-------- coreclr!Thread::HasThreadStateOpportunistic+0xc [F:\workspace\_work\1\s\src\coreclr\src\vm\threads.h @ 1290] 
08 (Inline Function) --------`-------- coreclr!CrstBase::CrstAndForbidSuspendForDebuggerHolder::{ctor}+0x50 [F:\workspace\_work\1\s\src\coreclr\src\vm\crst.cpp @ 823] 
09 00000035`1154f360 00007ff9`637c7830 coreclr!MethodDescBackpatchInfoTracker::ConditionalLockHolderForGCCoop::ConditionalLockHolderForGCCoop+0x67 [F:\workspace\_work\1\s\src\coreclr\src\vm\methoddescbackpatchinfo.h @ 134] 
0a 00000035`1154f3a0 00007ff9`63773078 coreclr!TieredCompilationManager::DeactivateTieringDelay+0x1d0 [F:\workspace\_work\1\s\src\coreclr\src\vm\tieredcompilation.cpp @ 451] 
0b 00000035`1154f710 00007ff9`637d978c coreclr!ThreadpoolMgr::AsyncTimerCallbackCompletion+0x38 [F:\workspace\_work\1\s\src\coreclr\src\vm\win32threadpool.cpp @ 4740] 
0c 00000035`1154f740 00007ff9`637778ac coreclr!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x15c [F:\workspace\_work\1\s\src\coreclr\src\vm\threadpoolrequest.cpp @ 482] 
0d (Inline Function) --------`-------- coreclr!ThreadpoolMgr::ExecuteWorkRequest+0x1cf [F:\workspace\_work\1\s\src\coreclr\src\vm\win32threadpool.cpp @ 1552] 
0e 00000035`1154f7e0 00007ff9`b1636fd4 coreclr!ThreadpoolMgr::WorkerThreadStart+0x33c [F:\workspace\_work\1\s\src\coreclr\src\vm\win32threadpool.cpp @ 1977] 
0f 00000035`1154f930 00007ff9`b1ffcec1 kernel32!BaseThreadInitThunk+0x14 [clientcore\base\win32\client\thread.c @ 64] 
10 00000035`1154f960 00000000`00000000 ntdll!RtlUserThreadStart+0x21 [minkernel\ntdll\rtlstrt.c @ 1153]