GCFrame 中的高线程数导致 CPU 使用率高答案

【问题标题】：High thread count stuck in GCFrame causes high CPU usageGCFrame 中的高线程数导致 CPU 使用率高
【发布时间】：2017-10-09 07:04:27
【问题描述】：

我们有一个使用 Kestrel 来处理 HTTP 请求的应用程序。过去我们遇到过一些问题，高负载导致线程池产生数千个线程，此时我们会出现锁护航症状。大多数时候，线程会在我们代码中的某处Monitor.Enter() 开始相互阻塞，从而导致延迟和更多的争用，直到应用程序由于上下文切换而无法响应，CPU 使用率为 100%。在我们重新启动应用程序之前，问题不会消失。

但是，我们已经消除了大多数锁并实施了一种限制机制，因此我们不允许超过 1000 个线程进入应用程序。我们使用System.Threading.Semaphore 类来只允许一定数量的线程继续。这解决了我们的锁争用问题，但可能引入了一个新问题：

我们仍然会遇到 100% CPU 使用率和高线程数（500-1000 个线程）的情况，尽管这次线程没有在 Monitor.Enter() 上被阻塞。相反，当我们进行线程转储（使用Microsoft.Diagnostics.Runtime.ClrRuntime）时，我们会看到以下调用堆栈（用于数百个线程）：

thread id = 892
  GCFrame
  GCFrame
  HelperMethodFrame
  System.Threading.TimerQueueTimer.Fire()
  System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
  System.Threading.ThreadPoolWorkQueue.Dispatch()
  DebuggerU2MCatchHandlerFrame

在这种情况下，问题会导致应用程序变得无响应，但在大多数情况下，它会在几分钟后自行解决。有时需要几个小时。

这样的调用堆栈是什么意思？这是 Kestrel 的一个已知问题，还是 Kestrel 和 Semaphore 的某种组合导致了这种情况？

更新：内存转储显示调用堆栈中的HelperMethodFrame 毕竟可能是对Monitor.Enter() 的调用。但是，我们仍然无法确定这是在我们的代码中还是在 Kestrel 或其他库中。当我们之前遇到锁车队问题时，我们会在调用堆栈中看到我们的代码。现在它似乎是在 TimerQueueTimer 内部的 Monitor.Enter() 调用，而不是我们在代码中使用的。内存转储如下所示：

.NET 堆栈跟踪：

Child SP               IP Call Site
0000005a92b5e438 00007ff8a11c0c6a [GCFrame: 0000005a92b5e438] 
0000005a92b5e660 00007ff8a11c0c6a [GCFrame: 0000005a92b5e660] 
0000005a92b5e698 00007ff8a11c0c6a [HelperMethodFrame: 0000005a92b5e698] System.Threading.Monitor.Enter(System.Object)
0000005a92b5e790 00007ff88f30096b System.Threading.TimerQueueTimer.Fire()
0000005a92b5e7e0 00007ff88f2e1a1d System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
0000005a92b5e820 00007ff88f2e1f70 System.Threading.ThreadPoolWorkQueue.Dispatch()
0000005a92b5ed48 00007ff890413753 [DebuggerU2MCatchHandlerFrame: 0000005a92b5ed48]

完整的堆栈跟踪：

 # Child-SP          RetAddr           : Args to Child                                                           : Call Site
00 0000005a`9cf5e9a8 00007ff8`9e6513ed : 00000000`00000000 00000000`00000001 00000000`00000001 00000000`00000000 : ntdll!ZwWaitForMultipleObjects+0xa
01 0000005a`9cf5e9b0 00007ff8`904e92aa : 0000005a`9cf5ef48 00007ff5`fffce000 0000005a`00000000 00000000`00000000 : KERNELBASE!WaitForMultipleObjectsEx+0xe1
02 0000005a`9cf5ec90 00007ff8`904e91bf : 00000000`00000001 00000000`00000000 0000005a`66b48e20 00000000`ffffffff : clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x62
03 0000005a`9cf5ecf0 00007ff8`904e8fb1 : 0000005a`66b48e20 00000000`00000001 00000000`00000018 00007ff8`00000000 : clr!Thread::DoAppropriateWaitWorker+0x243
04 0000005a`9cf5edf0 00007ff8`90731267 : 00000000`00000000 00007ff8`00000001 0000004f`a419c548 0000004f`a419c548 : clr!Thread::DoAppropriateWait+0x7d
05 0000005a`9cf5ee70 00007ff8`90834a56 : 0000005a`5aec0308 0000005a`9cf5f0d0 00000000`00000000 0000005a`66b48e20 : clr!CLREventBase::WaitEx+0x28e6b7
06 0000005a`9cf5ef00 00007ff8`9083495a : 0000005a`5aec0308 0000005a`66b48e20 00000000`00000000 00000050`22945ab8 : clr!AwareLock::EnterEpilogHelper+0xca
07 0000005a`9cf5efc0 00007ff8`90763c8c : 0000005a`66b48e20 0000005a`5aec0308 0000005a`5aec0308 00000000`002d0d01 : clr!AwareLock::EnterEpilog+0x62
08 0000005a`9cf5f020 00007ff8`908347ed : 00000000`00000000 0000005a`9cf5f0d0 0000005a`5aec0308 0000005a`5aec0301 : clr!AwareLock::Enter+0x24390c
09 0000005a`9cf5f050 00007ff8`908338a5 : 00000050`22945ab8 0000005a`9cf5f201 0000005a`66b48e20 00007ff8`90419050 : clr!AwareLock::Contention+0x2fd
0a 0000005a`9cf5f110 00007ff8`8f30096b : 0000005a`5aec0308 0000005a`9cf5f2d0 0000005a`9cf5f560 00000000`00000000 : clr!JITutil_MonContention+0xc5
0b 0000005a`9cf5f2a0 00007ff8`8f2e1a1d : 00000051`a2bb6bb0 00007ff8`90417d0e 00000050`229491d8 0000005a`9cf5f330 : mscorlib_ni+0x49096b
0c 0000005a`9cf5f2f0 00007ff8`8f2e1f70 : 00000000`00000000 0000005a`9cf5f3a8 00000000`00000001 0000005a`9cf5f370 : mscorlib_ni+0x471a1d
0d 0000005a`9cf5f330 00007ff8`90413753 : 00000000`00000004 00000000`00000000 0000005a`9cf5f600 0000005a`9cf5f688 : mscorlib_ni+0x471f70
0e 0000005a`9cf5f3d0 00007ff8`9041361c : 00000050`22945ab8 00000000`00000000 0000005a`9cf5f640 0000005a`9cf5f6c8 : clr!CallDescrWorkerInternal+0x83
0f 0000005a`9cf5f410 00007ff8`904144d3 : 00000000`00000000 00000000`00000004 0000005a`9cf5f858 0000005a`9cf5f688 : clr!CallDescrWorkerWithHandler+0x4e
10 0000005a`9cf5f450 00007ff8`9041b73d : 0000005a`9cf5fb70 0000005a`9cf5fb20 0000005a`9cf5fb70 00000000`00000001 : clr!MethodDescCallSite::CallTargetWorker+0x2af
11 0000005a`9cf5f5e0 00007ff8`90416810 : 00000000`00000007 00007ff8`00000000 ffffffff`fffffffe 0000005a`66b48e20 : clr!QueueUserWorkItemManagedCallback+0x2a
12 0000005a`9cf5f6d0 00007ff8`904167c0 : 00670061`00500064 00000000`00730065 ffffffff`fffffffe 0000005a`66b48e20 : clr!ManagedThreadBase_DispatchInner+0x29
13 0000005a`9cf5f710 00007ff8`90416705 : ffffffff`ffffffff 00007ff8`90414051 0000005a`9cf5f7b8 00000000`ffffffff : clr!ManagedThreadBase_DispatchMiddle+0x6c
14 0000005a`9cf5f810 00007ff8`90416947 : ffffffff`ffffffff 0000005a`66b48e20 0000005a`66b48e20 00000000`00000001 : clr!ManagedThreadBase_DispatchOuter+0x75
15 0000005a`9cf5f8a0 00007ff8`9041b6a2 : 0000005a`9cf5f988 00000000`00000000 00000000`00000001 00007ff8`9e651118 : clr!ManagedThreadBase_FullTransitionWithAD+0x2f
16 0000005a`9cf5f900 00007ff8`904158ba : 0000005a`9cf5fb70 0000005a`9cf5fb68 00000000`00000000 00000000`00000200 : clr!ManagedPerAppDomainTPCount::DispatchWorkItem+0x11c
17 0000005a`9cf5fa90 00007ff8`904157da : 0000010b`010b010b 0000005a`9cf5fb20 00000000`00000000 0000005a`66b48e20 : clr!ThreadpoolMgr::ExecuteWorkRequest+0x64
18 0000005a`9cf5fac0 00007ff8`90433e1e : 00000000`00000000 00000000`00000000 00000000`00000001 00000000`0000041d : clr!ThreadpoolMgr::WorkerThreadStart+0x3b5
19 0000005a`9cf5fb60 00007ff8`9e7c13d2 : 00007ff8`90433da8 0000005a`5add4db0 00000000`00000000 00000000`00000000 : clr!Thread::intermediateThreadProc+0x7d
1a 0000005a`9cf5fca0 00007ff8`a11454e4 : 00007ff8`9e7c13b0 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0x22
1b 0000005a`9cf5fcd0 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x34

更新 2：WinDbg syncblock 命令给了我们这个：

The version of SOS does not match the version of CLR you are debugging.  Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.6.1055.0
SOS Version: 4.6.1637.0
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
  148 0000005a5aec0308          426         0 0000000000000000     none    0000005022945ab8 System.Threading.TimerQueue
-----------------------------
Total           152
CCW             1
RCW             1
ComClassFactory 0
Free            66

更新 3：更多挖掘表明我们有大约 42000 个 Timer 对象：

00007ff8871bedd0    41728      1001472 System.Runtime.Caching.MemoryCacheEqualityComparer
00007ff88f4a0998    42394      1017456 System.Threading.TimerHolder
00007ff8871bbed0    41728      1335296 System.Runtime.Caching.UsageBucket[]
00007ff88f51ab30    41749      1335968 Microsoft.Win32.SafeHandles.SafeWaitHandle
00007ff88f519de0    42394      1356608 System.Threading.Timer
00007ff8871be870    41728      1669120 System.Runtime.Caching.CacheUsage
00007ff88f50ea80    41734      2003232 System.Threading.ManualResetEvent
00007ff8871be810    41728      2336768 System.Runtime.Caching.CacheExpires
00007ff88f519f08    42390      2712960 System.Threading.TimerCallback
00007ff8871be558    41728      3338240 System.Runtime.Caching.MemoryCacheStore
00007ff88f4a0938    42394      3730672 System.Threading.TimerQueueTimer
00007ff8871be8d0    41728      4005888 System.Runtime.Caching.UsageBucket
00007ff8871bb9c8    41728     11016192 System.Runtime.Caching.ExpiresBucket[]

检查一些 _methodPtr 引用，它们都指向：

00007ff8`871b22c0 0f1f440000      nop     dword ptr [rax+rax]
00007ff8`871b22c5 33d2            xor     edx,edx
00007ff8`871b22c7 4533c0          xor     r8d,r8d
00007ff8`871b22ca 488d055ffeffff  lea     rax,[System_Runtime_Caching_ni+0x32130 (00007ff8`871b2130)]
00007ff8`871b22d1 48ffe0          jmp     rax

而 GC 跟踪看起来与此类似：

0:000> !gcroot 00000055629e5ca0
The version of SOS does not match the version of CLR you are debugging.  Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.6.1055.0
SOS Version: 4.6.1637.0
Thread 27a368:
    0000005a61c4ed10 00007ff88f2d2490 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
        r14: 
            ->  0000004b6296f840 System.Threading.ThreadHelper
            ->  0000004b6296f7a0 System.Threading.ThreadStart
            ->  0000004b6296f750 Quartz.Simpl.SimpleThreadPool+WorkerThread
            ->  0000004b6296f7e0 System.Threading.Thread
            ->  0000004b62959710 System.Runtime.Remoting.Contexts.Context
            ->  0000004aa29315a8 System.AppDomain
            ->  0000004c22c4b368 System.EventHandler
            ->  00000051e2eb5f48 System.Object[]
            ->  00000050629e6180 System.EventHandler
            ->  000000506298b268 System.Runtime.Caching.MemoryCache
            ->  000000506298b348 System.Runtime.Caching.MemoryCacheStore[]
            ->  000000506298d470 System.Runtime.Caching.MemoryCacheStore
            ->  000000506298d5a0 System.Runtime.Caching.CacheExpires
            ->  000000506298e868 System.Threading.Timer
            ->  000000506298eaa8 System.Threading.TimerHolder
            ->  000000506298e888 System.Threading.TimerQueueTimer
            ->  000000506298fe78 System.Threading.TimerQueueTimer

【问题讨论】：

Jeez Marie，如果一千个线程无法将 CPU 使用率提高到 100%，那么所有希望都将落空。如果你有那么多计时器在滴答作响，那么前一段时间出现了严重错误。不是很明显它是如何从 TimerQueueTimer.Fire() 直接进入 Monitor.Enter()，也许你需要寻找 [MethodImpl(MethodImplOptions.Synchronized)]。总是导致意外死锁的好方法。
感谢您的提示，将查找该属性。更多挖掘表明这可能与 Kestrel 无关，而是与我们的应用程序也在使用的 Quartz.net 相关。添加了标签。
这似乎很有可能。 Quartz 是一个 Java 库。 MethodImplOptions.Synchronized 是继承自 Java 的诅咒。
深入研究 Quartz.net 的源代码（我们正在使用的 v 2.3.3），我发现 Quartz.Simpl.SimpleThreadPool+ 的 Run() 方法中有显式 Monitor.Enter 调用工作线程。没有我能看到的 MethodImplOptions.Synchronized 属性。我们将尝试将 Quartz 配置为不使用它自己的 SimpleThreadPool 并使用其他东西。
我们在 RabbitMQ 客户端库中也看到了同样的情况。似乎创建了很多 Timer 对象，这导致 Quartz 或 RabbitMQ（都使用自己的线程池）中的线程池停止并创建大量新线程。这可能与使用 GCLatencyMode.SustainedLowLatency 有关吗？这是我们在展示此行为的版本中所做的更改之一。

标签： c# multithreading rabbitmq quartz.net kestrel

【解决方案1】：

只是想为未来的 interwebz 旅行者添加这个。根本原因是我们使用了一个System.Runtime.Caching.MemoryCache 实例，我们经常在没有适当处理的情况下重新创建它。 MemoryCaches 为函数调用创建了定时器，当缓存被替换时，这些定时器并没有从内存中清除，定时器会不时地抓取一个线程池线程来检查它们是否应该触发，所以当定时器建立时，CPU使用率也是如此。

难以检测的原因是它没有出现在堆栈跟踪中，即使在转储文件中也是如此。相反，我们会看到计时器调用的类（主要是 lambdas）。基本上，我们通过对所有代码的广泛审计发现了这个问题。 MemoryCache 的文档明确表示不要做我们所做的事情。

解决方案是在创建新缓存之前处理旧缓存，然后问题就消失了。

编辑：查看上面的堆栈跟踪，看起来它确实给了我们很好的证据表明问题出在System.Runtime.Caching。我猜我们只是瞎了眼，没想到问题出在 System 命名空间内。

【讨论】：

感谢您的关注！
我真的非常感谢您添加了事情的结果。不确定这是否是我需要的答案，但它让我有理由深入挖掘一个方向。