记一次 .NET 某电子病历 CPU 爆高分析

一:背景1.讲故事前段时间有位朋友微信找到我 , 说他的程序出现了 CPU 爆高 , 帮忙看下程序到底出了什么情况?图就不上了 , 我们直接进入主题 。
二:WinDbg 分析1. CPU 真的爆高吗?要确认是否真的爆高 , 可以使用 !tp 观察 。
0:000> !tpCPU utilization: 96%Worker Thread: Total: 36 Running: 36 Idle: 0 MaxLimit: 32767 MinLimit: 16Work Request in Queue: 61Unknown Function: 00007ffc5c461750Context: 00000187da7a9788Unknown Function: 00007ffc5c461750Context: 0000017fcdd36e88...Unknown Function: 00007ffc5c461750Context: 00000187da5e87d8Unknown Function: 00007ffc5c461750Context: 00000187da872788--------------------------------------Number of Timers: 2--------------------------------------Completion Port Thread:Total: 1 Free: 1 MaxFree: 32 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 16从卦中可以看到 CPU=96% , 果然是 CPU 爆高 , 而且 Work Request 也累积了 61 个任务未处理 , 看样子下游不给力哈? 不给力有可能是因为 GC 触发导致线程频繁停顿 , 也可能真的是处理太慢 。
2. 是 GC 触发了吗?要查看是否真的 GC 触发 , 可以用 !t -special 观察下是否有 SuspendEE 字样 。
0:000> !t -specialThreadCount:83UnstartedThread:0BackgroundThread: 74PendingThread:0DeadThread:9Hosted Runtime:noLockID OSID ThreadOBJState GC ModeGC Alloc ContextDomainCount Apt Exception191 1c84 0000017abe10cf6028220 Preemptive0000000000000000:0000000000000000 0000017abe103f70 0Ukn...OSID Special thread type26 1c78 DbgHelper27 1328 GC SuspendEE28 1e78 GC29 1ffc GC30 1de0 GC 果不其然 27 号线程带了 SuspendEE ,说明当前 GC 是触发状态 , 接下来看下 27 号线程的非托管栈, 到底发生了什么 。
0:027> k # Child-SPRetAddrCall Site00 00000074`11aff348 00007ffc`66624abfntdll!NtWaitForSingleObject+0x1401 00000074`11aff350 00007ffc`591aa747KERNELBASE!WaitForSingleObjectEx+0x8f02 00000074`11aff3f0 00007ffc`591aa6ffclr!CLREventWaitHelper2+0x3c03 00000074`11aff430 00007ffc`591aa67cclr!CLREventWaitHelper+0x1f04 00000074`11aff490 00007ffc`59048ef5clr!CLREventBase::WaitEx+0x7c05 00000074`11aff520 00007ffc`5905370eclr!SVR::t_join::join+0x10f06 00000074`11aff580 00007ffc`59049278clr!SVR::gc_heap::plan_phase+0x11f407 00000074`11aff900 00007ffc`590494d6clr!SVR::gc_heap::gc1+0xb808 00000074`11aff950 00007ffc`59048c64clr!SVR::gc_heap::garbage_collect+0x87009 00000074`11aff9f0 00007ffc`59192487clr!SVR::gc_heap::gc_thread_function+0x740a 00000074`11affa20 00007ffc`59194194clr!SVR::gc_heap::gc_thread_stub+0x7e0b 00000074`11affa60 00007ffc`694184d4clr!GCThreadStub+0x240c 00000074`11affa90 00007ffc`69dee8b1kernel32!BaseThreadInitThunk+0x140d 00000074`11affac0 00000000`00000000ntdll!RtlUserThreadStart+0x21从栈方法 gc_thread_function() 来看 , 这是一个专有的 GC 线程 , 熟悉 server GC 的朋友应该知道 , 用户线程分配 引发GC后 , 会通过 event 唤醒GC线程 , 言外之意就是还没有找到这个用户线程触发的导火索 , 要想找到答案有很多方法 , 查看当前的 GCSettings 观察 GC 触发的诱因及代数 , 截图如下:

记一次 .NET 某电子病历 CPU 爆高分析

文章插图
我去 , 居然是一个诱导式FullGC , 言外之意就是有代码会调用 GC.Collect()  , 接下来我们用 ~*e !clrstack 导出所有的线程栈 , 观察 GC.Collect() 字样 , 还真给找到了 。。。
0:117> !clrstackOS Thread Id: 0x170c (117)Child SPIP Call Site0000007419f1d580 00007ffc69e25ac4 [InlinedCallFrame: 0000007419f1d580] System.GC._Collect(Int32, Int32)0000007419f1d580 00007ffbfba0fbf2 [InlinedCallFrame: 0000007419f1d580] System.GC._Collect(Int32, Int32)0000007419f1d550 00007ffbfba0fbf2 Spire.Pdf.PdfDocument.Dispose()...0000007419f1e2f0 00007ffc504b1092 System.Web.Mvc.MvcHandler.EndProcessRequest(System.IAsyncResult)

经验总结扩展阅读