记一次 .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 触发的诱因及代数，截图如下：

文章插图
我去，居然是一个诱导式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)

从代码看居然是一个商业组件 Spire.Pdf 在 Dispose 时手工释放触发的，一般这么做的目的是想通过此方法间接释放非托管资源。
其实一个 FullGC 不代表什么，如果频繁的 FullGC 肯定是有问题的，那如何观察是否频繁呢？在 CLR 源码中有一个 full_gc_counts 的全局变量，记录着FullGC 的次数，代码如下：

size_t gc_heap::full_gc_counts[gc_type_max];enum gc_type{gc_type_compacting = 0,gc_type_blocking = 1,#ifdef BACKGROUND_GCgc_type_background = 2,#endif //BACKGROUND_GCgc_type_max = 3};

接下来可以用 x 命令去检索这个变量，观察各自的布局。