1. 首頁 > 生活百科 > >

記一次 .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)從代碼看居然是一個商業組件 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 命令去檢索這個變量，觀察各自的布局 。
記一次 .NET 某電子病歷 CPU 爆高分析

文章插圖
因為 gc_type_compacting 和 gc_type_blocking 有重疊，而且觀察進程運行了

推薦閱讀