ghost
commented
3 years ago Tagging subscribers to this area: @dotnet/gc
See info in area-owners.md if you want to be subscribed.
| Description: | ### Description Performance issues observed in a web application when one of API end point starting responding slow due to slow file share dependency. But it triggered unexpected behavior which we have not seen before, i.e. 503, time out (Redis) exceptions & intermittent hangs. Primarily due to GC Thread is blocked by another thread. ### Configuration - Web Application hosted on Windows Server 2016 using IIS - Targeting Framework 4.7.1 - Server GC (Output of !eeheap 4.8.4180.0 free Server mode with 8 gc heaps) - Host has 8 cores, and 16 GB Memory, Process memory max utilization is around 4 GB. There are other .NET Framework process running on host, and did not observe any issues. ### Analysis To do further analysis, I took to two memory dumps (10 seconds apart) on one of the host for the affected process. Below command was used. ~~~ procdump -ma -s 10 -n 2 -64 -accepteula process-id ~~~ #### DebugDiag Analysis Report - DebugDiag produces the output, seen below in screen shot, as almost every thread in the process is waiting on Thread 41 to finish its work. Stack trace of Thread 41 is show below. - About 24% threads are waiting in Monitor.Wait are actually waiting to re-acquire a lock which they released, which I do not understand how. It is related to StackExchange.Redis library, I should file issue in that repo, but I would love to get more information as I feel like it can be related.   ### Stack Trace of Thread 41 - Which happens to be doing the work for APM Agent.  **Complete CLR STACK of Thread 41 - via WinDbg** I can not make much sense of it, does this tell us that it blocked GC thread but why/how? thirdparty-APM is dll of third party APM platform. ~~~ Thread 41 Current frame: ntdll!NtGetContextThread+0x14 Child-SP RetAddr Caller, Callee 000000f5a067e870 00007ffaf8a0f97a KERNELBASE!GetThreadContext+0xa, calling ntdll!NtGetContextThread 000000f5a067e8a0 00007ffaeda429d5 clr!Thread::SuspendThread+0x112, calling kernel32!GetThreadContextStub 000000f5a067e8d0 00007ffaf89e8d23 KERNELBASE!WaitForMultipleObjectsEx+0x1f3, calling ntdll!RtlActivateActivationContextUnsafeFast 000000f5a067e990 00007ffad3924cdf thirdparty-APM!updateManagedThreadPoolMetrics+0x3cf32f, calling thirdparty-APM!updateManagedThreadPoolMetrics+0x3cf2d0 000000f5a067e9e0 00007ffaf9ef3889 SYMSRV: BYINDEX: 0x10 c:\symcache*http://msdl.microsoft.com/download/symbols combase.pdb A9A6647FB7664D5CAE48BB37C377F3801 SYMSRV: PATH: c:\symcache\combase.pdb\A9A6647FB7664D5CAE48BB37C377F3801\combase.pdb SYMSRV: RESULT: 0x00000000 DBGHELP: combase - private symbols & lines c:\symcache\combase.pdb\A9A6647FB7664D5CAE48BB37C377F3801\combase.pdb combase!CObjectContext::QIHelper+0x109, calling ntdll!LdrpDispatchUserCallTarget 000000f5a067ea10 00007ffaedbd5553 clr!SafeQueryInterface+0xe3 000000f5a067ea50 00007ffaedbc8977 clr!SafeReleasePreemp+0x87 000000f5a067ea90 00007ffaf9ef277c combase!CObjectContext::GetCurrentThreadType+0x1c, calling combase!IsApartmentInitialized 000000f5a067eac0 00007ffaedbca34b clr!GetCurrentThreadTypeNT5+0xcd, calling clr!SafeReleasePreemp 000000f5a067eae0 00007ffafc4b81a0 ntdll!RtlSetLastWin32Error+0x40, calling ntdll!_security_check_cookie 000000f5a067eb30 00007ffaedbd2928 clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x99, calling kernel32!SetLastErrorStub 000000f5a067eb50 00007ffaeda1bf50 clr!ThreadStateNCStackHolder::~ThreadStateNCStackHolder+0x1c, calling clr!GetThread 000000f5a067eb60 00007ffaed9fb506 clr!Thread::GetFinalApartment+0x1a, calling clr!Thread::GetApartment 000000f5a067eb90 00007ffaedbd279d clr!Thread::DoAppropriateWaitWorker+0x26c, calling clr!ThreadStateNCStackHolder::~ThreadStateNCStackHolder 000000f5a067ebe0 00007ffaed9f6a6d clr!SafeHandle::Release+0xa5, calling clr!_security_check_cookie 000000f5a067ec90 00007ffaed9f563e clr!GCCoop::GCCoop+0xe, calling clr!GetThread 000000f5a067ecc0 00007ffaeda35c8f clr!ReleaseSafeHandle+0x27, calling clr!SafeHandle::Release 000000f5a067ed10 00007ffaeda35c2c clr!WaitHandleNative::CorWaitOneNative+0x1ec, calling clr!HelperMethodFrameRestoreState 000000f5a067ed90 00007ffaf89f255a KERNELBASE!ResetEvent+0xa, calling ntdll!NtClearEvent 000000f5a067eda0 00007ffaed9f5133 clr!CrstBase::Enter+0x7f, calling ntdll!RtlTryEnterCriticalSection 000000f5a067edc0 00007ffaf89f255a KERNELBASE!ResetEvent+0xa, calling ntdll!NtClearEvent 000000f5a067edf0 00007ffaeda39759 clr!CLREventBase::Reset+0x29, calling kernel32!ResetEvent 000000f5a067ee20 00007ffaede7227b clr!Thread::UserSuspendThread+0xc1, calling clr!Thread::SuspendThread 000000f5a067ee60 00007ffaedf9288e clr!ThreadIsRunning+0x31, calling clr!Thread::HasValidThreadHandle 000000f5a067ee90 00007ffaedf927a6 clr!ThreadNative::Suspend+0x116, calling clr!Thread::UserSuspendThread 000000f5a067eec0 00007ffaedb7f800 clr!ThreadNative::GetThreadState+0x1e0, calling clr!HelperMethodFrameRestoreState 000000f5a067eed0 00007ffaed9f4e65 clr!JIT_InitPInvokeFrame+0x15, calling clr!GetThread 000000f5a067efb0 00007ffa8ed6aa71 (MethodDesc 00007ffa8e842838 +0x11 System.Threading.WaitHandle.WaitOne(System.TimeSpan)) 000000f5a067efd0 00007ffa8ed69507 (MethodDesc 00007ffa8e959bb8 +0x27 mscorlib.dll!Unknown), calling (MethodDesc 00007ffa8e696460 +0 mscorlib.dll!Unknown) 000000f5a067efe8 00007ffaedf92717 clr!ThreadNative::Suspend+0x87, calling clr!LazyMachStateCaptureState 000000f5a067f000 00007ffa8ed6ac5b (MethodDesc 00007ffa8e964740 +0xb mscorlib.dll!Unknown), calling (MethodDesc 00007ffa8e5f84d8 +0 mscorlib.dll!Unknown) 000000f5a067f030 00007ffa8f306720 (MethodDesc 00007ffa8e959a58 +0x70 mscorlib.dll!Unknown), calling (MethodDesc 00007ffa8e964790 +0 mscorlib.dll!Unknown) 000000f5a067f050 00007ffa8f2fcbd8 (MethodDesc 00007ffa8e959a48 +0x98 mscorlib.dll!Unknown), calling 00007ffa8e454740 000000f5a067f090 00007ffa8e9d109a (MethodDesc 00007ffa8e959a38 +0x46a mscorlib.dll!Unknown), calling (MethodDesc 00007ffa8e959a58 +0 mscorlib.dll!Unknown) 000000f5a067f0b0 00007ffad3baa845 thirdparty-APM!updateManagedThreadPoolMetrics+0x654e95, calling thirdparty-APM!updateManagedThreadPoolMetrics+0x6511d0 000000f5a067f1a0 00007ffa8e9ced52 (MethodDesc 00007ffa8e699118 +0x2c2 mscorlib.dll!Unknown), calling (MethodDesc 00007ffa8e959a38 +0 mscorlib.dll!Unknown) 000000f5a067f210 00007ffa8e9ce686 (MethodDesc 00007ffa8ea48300 +0x46 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int32, Int64, Int32)) 000000f5a067f230 00007ffaed9f83fe clr!SystemDomain::GetAppDomainAtId+0x43, calling clr!AppDomain::CanThreadEnter 000000f5a067f270 00007ffaed9f2483 clr!UM2MThunk_WrapperHelper+0x43 000000f5a067f290 00007ffaed9fa54c clr!Thread::EnterContextRestricted+0x19c, calling clr!ClrFlsIncrementValue 000000f5a067f2b0 00007ffaedb7c16a clr!UM2MThunk_Wrapper+0x60, calling clr!UM2MThunk_WrapperHelper 000000f5a067f2d0 00007ffaed9f83fe clr!SystemDomain::GetAppDomainAtId+0x43, calling clr!AppDomain::CanThreadEnter 000000f5a067f300 00007ffaed9fa9d0 clr!Thread::DoADCallBack+0x136 000000f5a067f320 00007ffad356e4a2 thirdparty-APM!updateManagedThreadPoolMetrics+0x18af2, calling ntdll!LdrpDispatchUserCallTarget 000000f5a067f330 00007ffa8e9dac5c (MethodDesc 00007ffa8e93ebe8 +0xc mscorlib.dll!Unknown), calling (MethodDesc 00007ffa8e93ec28 +0 mscorlib.dll!Unknown) 000000f5a067f360 00007ffa8e9d132b (MethodDesc 00007ffa8e959a38 +0x6fb mscorlib.dll!Unknown), calling thirdparty-APM!updateManagedThreadPoolMetrics+0x18ab0 000000f5a067f3c8 00007ffa8e9d132b (MethodDesc 00007ffa8e959a38 +0x6fb mscorlib.dll!Unknown), calling thirdparty-APM!updateManagedThreadPoolMetrics+0x18ab0 000000f5a067f470 00007ffa8e9cefa6 (MethodDesc 00007ffa8e699118 +0x516 mscorlib.dll!Unknown), calling (MethodDesc 00007ffa8e699118 +0x655 mscorlib.dll!Unknown) 000000f5a067f4c0 00007ffaedb7c0e4 clr!UM2MDoADCallBack+0xb3, calling clr!Thread::DoADCallBack 000000f5a067f500 00007ffad3eee0e4 thirdparty-APM!updateManagedThreadPoolMetrics+0x998734, calling kernel32!HeapFreeStub 000000f5a067f540 00007ffaed9f242d clr!UMThunkStub+0x26d, calling clr!UM2MDoADCallBack 000000f5a067f5d0 00007ffad36014e8 thirdparty-APM!updateManagedThreadPoolMetrics+0xabb38, calling ntdll!LdrpDispatchUserCallTarget 000000f5a067f610 00007ffad360165e thirdparty-APM!updateManagedThreadPoolMetrics+0xabcae, calling thirdparty-APM!updateManagedThreadPoolMetrics+0xabb10 000000f5a067f6d0 00007ffad36370f7 thirdparty-APM!updateManagedThreadPoolMetrics+0xe1747, calling thirdparty-APM!updateManagedThreadPoolMetrics+0xe1020 000000f5a067f700 00007ffad36026b2 thirdparty-APM!updateManagedThreadPoolMetrics+0xacd02, calling thirdparty-APM!updateManagedThreadPoolMetrics+0xabb50 000000f5a067f7e0 00007ffad35b5c20 thirdparty-APM!updateManagedThreadPoolMetrics+0x60270, calling ntdll!LdrpDispatchUserCallTarget 000000f5a067f8a0 00007ffad358f467 thirdparty-APM!updateManagedThreadPoolMetrics+0x39ab7, calling ntdll!LdrpDispatchUserCallTarget 000000f5a067f900 00007ffafc4b81a0 ntdll!RtlSetLastWin32Error+0x40, calling ntdll!_security_check_cookie 000000f5a067f920 00007ffad3ef1933 thirdparty-APM!updateManagedThreadPoolMetrics+0x99bf83, calling thirdparty-APM!updateManagedThreadPoolMetrics+0x99b750 000000f5a067f950 00007ffad3c627e6 thirdparty-APM!updateManagedThreadPoolMetrics+0x70ce36, calling kernel32!TlsSetValueStub 000000f5a067f980 00007ffad3ebe880 thirdparty-APM!updateManagedThreadPoolMetrics+0x968ed0, calling ntdll!LdrpDispatchUserCallTarget 000000f5a067f9b0 00007ffafa4b84d4 kernel32!BaseThreadInitThunk+0x14, calling ntdll!LdrpDispatchUserCallTarget 000000f5a067f9e0 00007ffafc51e871 ntdll!RtlUserThreadStart+0x21, calling ntdll!LdrpDispatchUserCallTarget ~~~ #### WinDbg Analysis I am newbie to WinDbg. But I was able to verify some basics diagnostics to rule out. But there are lot interesting details which I do not fully understand. - !VerifyHeap - No Corruption Found - !GCHandleLeaks - No Handle Leak Detected - !dlk No Dead Lock Detected - using sosex.dll extension - No Out of Memory Exception **Note:** Below are details from one of the memory dump, other memory dump also report very similar stats. ##### Thread Pool Details ~~~ CPU utilization: 6% Worker Thread: Total: 496 Running: 165 Idle: 331 MaxLimit: 1000 MinLimit: 496 Work Request in Queue: 141 Unknown Function: 00007ffae3b519d0 Context: 00000296f1755900 Unknown Function: 00007ffae3b519d0 Context: 00000296fd9b7718 Unknown Function: 00007ffae3b519d0 Context: 00000296f175a130 ---removed entries -------------------------------------- Number of Timers: 0 -------------------------------------- Completion Port Thread:Total: 2 Free: 2 MaxFree: 16 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 496 ~~~ ##### GC Handles ~~~ Total 57233 objects Handles: Strong Handles: 8789 Pinned Handles: 49 Async Pinned Handles: 59 Ref Count Handles: 11 Weak Long Handles: 15004 Weak Short Handles: 33241 SizedRef Handles: 80 ~~~ DotMemory Finalizable Objects - Which seems to match GC Handles - Is it because GC thread is blocked?  ##### !Threads  I tried to see what Thread 41 Stack Trace can tell me, but I can not make much sense of it? #### !dumpheap -live -thinlock **Note:** All thin lock objects of same size which 24. Which is free object according to Maoni Stephens "You can not lock a free object." I am using WinDbg Preview - Debugger engine version: 10.0.20153.1000 Debugger client version: 1.0.2007.06001 ~~~ removed ... 00000295c8a7c530 0000029241e30610 24 ThinLock owner 2c (00000296d1268f60) Recursive 0 00000295c8a7c918 0000029241e30610 24 ThinLock owner 6e (00000296d59d2c70) Recursive 0 00000295c8a7cd90 0000029241e30610 24 ThinLock owner 6e (00000296d59d2c70) Recursive 0 Found 7190 objects. ~~~ ##### 0:041> !SyncBlk Note: This also produces interesting, I believe these are coming from Bundling, but I am failing to conclude that this is the root cause? Help ~~~ Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner 735 00000296ecbb30b8 1 1 00000296d15566c0 1370 227 0000029245808468 System.Web.DirectoryMonitor 1125 00000296e8630bc8 3 1 00000296d64f1780 e70 207 00000293c4548c38 log4net.Appender.RollingFileAppender 1852 00000296eca2ed78 3 1 00000296ed3fd5f0 2a04 424 000002944afd2168 System.Web.CachedPathData 2293 00000296ec4857d8 11 1 00000296ed4089a0 904 448 0000029547c603c8 System.Web.CachedPathData 2414 00000296d7ee8398 15 1 00000296ecad0580 2bd4 384 00000294c9f64768 System.Web.CachedPathData 2869 00000296f3e8be88 5 1 00000296ecaa1780 1704 224 00000292c8cd8838 System.Web.CachedPathData 2999 00000296e37ad368 21 1 00000296e3a37770 3a68 442 00000295c862d098 System.Web.CachedPathData ----------------------------- Total 3099 CCW 11 RCW 12 ComClassFactory 0 Free 921 ~~~ I will appreciate any help in that regard to find the root cause. Kindly let me know if you need more information or what further analysis can be done on these memory dumps. Since latency, 503, Redis Timeout errors were observed only when File Share was responding slow, so I have not done further traces on production. |
|---|---|
| Author: | marafiq |
| Assignees: | - |
| Labels: | `area-GC-coreclr`, `tenet-performance`, `untriaged` |
| Milestone: | - |
mangod9
marafiq
discostu105
georgschausberger
Maoni0
AaronRobinsonMSFT
Description
Performance issues observed in a web application when one of API end point starting responding slow due to slow file share dependency. But it triggered unexpected behavior which we have not seen before, i.e. 503, time out (Redis) exceptions & intermittent hangs. Primarily due to GC Thread is blocked by another thread.
Configuration
Analysis
To do further analysis, I took to two memory dumps (10 seconds apart) on one of the host for the affected process. Below command was used.
DebugDiag Analysis Report
Stack Trace of Thread 41 - Which happens to be doing the work for APM Agent.
Complete CLR STACK of Thread 41 - via WinDbg I can not make much sense of it, does this tell us that it blocked GC thread but why/how? thirdparty-APM is dll of third party APM platform.
WinDbg Analysis
I am newbie to WinDbg. But I was able to verify some basics diagnostics to rule out. But there are lot interesting details which I do not fully understand.
Thread Pool Details
GC Handles
DotMemory Finalizable Objects - Which seems to match GC Handles - Is it because GC thread is blocked?
!Threads
I tried to see what Thread 41 Stack Trace can tell me, but I can not make much sense of it?
!dumpheap -live -thinlock
Note: All thin lock objects of same size which 24. Which is free object according to Maoni Stephens "You can not lock a free object." I am using WinDbg Preview - Debugger engine version: 10.0.20153.1000 Debugger client version: 1.0.2007.06001
0:041> !SyncBlk
Note: This also produces interesting, I believe these are coming from Bundling, but I am failing to conclude that this is the root cause? Help
I will appreciate any help in that regard to find the root cause. Kindly let me know if you need more information or what further analysis can be done on these memory dumps. Since latency, 503, Redis Timeout errors were observed only when File Share was responding slow, so I have not done further traces on production.