記一次 .NET 某電子病歷 CPU 爆高分析

一：背景

1.講故事

前段時間有位朋友微信找到我，說他的程式出現了 CPU 爆高，幫忙看下程式到底出了什麼情況？圖就不上了，我們直接進入主題。

二：WinDbg 分析

1. CPU 真的爆高嗎？

要確認是否真的爆高，可以使用 !tp 觀察。

0:000> !tp
CPU utilization: 96%
Worker Thread: Total: 36 Running: 36 Idle: 0 MaxLimit: 32767 MinLimit: 16
Work Request in Queue: 61
    Unknown Function: 00007ffc5c461750  Context: 00000187da7a9788
    Unknown Function: 00007ffc5c461750  Context: 0000017fcdd36e88
    ...
    Unknown Function: 00007ffc5c461750  Context: 00000187da5e87d8
    Unknown Function: 00007ffc5c461750  Context: 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 -special
ThreadCount:      83
UnstartedThread:  0
BackgroundThread: 74
PendingThread:    0
DeadThread:       9
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
  19    1 1c84 0000017abe10cf60    28220 Preemptive  0000000000000000:0000000000000000 0000017abe103f70 0     Ukn 
  ...
          OSID Special thread type
       26 1c78 DbgHelper 
       27 1328 GC SuspendEE 
       28 1e78 GC 
       29 1ffc GC 
       30 1de0 GC 

果不其然 27 號線程帶了 SuspendEE ,說明當前 GC 是觸髮狀態，接下來看下 27 號線程的非托管棧, 到底發生了什麼。

0:027> k
 # Child-SP          RetAddr               Call Site
00 00000074`11aff348 00007ffc`66624abf     ntdll!NtWaitForSingleObject+0x14
01 00000074`11aff350 00007ffc`591aa747     KERNELBASE!WaitForSingleObjectEx+0x8f
02 00000074`11aff3f0 00007ffc`591aa6ff     clr!CLREventWaitHelper2+0x3c
03 00000074`11aff430 00007ffc`591aa67c     clr!CLREventWaitHelper+0x1f
04 00000074`11aff490 00007ffc`59048ef5     clr!CLREventBase::WaitEx+0x7c
05 00000074`11aff520 00007ffc`5905370e     clr!SVR::t_join::join+0x10f
06 00000074`11aff580 00007ffc`59049278     clr!SVR::gc_heap::plan_phase+0x11f4
07 00000074`11aff900 00007ffc`590494d6     clr!SVR::gc_heap::gc1+0xb8
08 00000074`11aff950 00007ffc`59048c64     clr!SVR::gc_heap::garbage_collect+0x870
09 00000074`11aff9f0 00007ffc`59192487     clr!SVR::gc_heap::gc_thread_function+0x74
0a 00000074`11affa20 00007ffc`59194194     clr!SVR::gc_heap::gc_thread_stub+0x7e
0b 00000074`11affa60 00007ffc`694184d4     clr!GCThreadStub+0x24
0c 00000074`11affa90 00007ffc`69dee8b1     kernel32!BaseThreadInitThunk+0x14
0d 00000074`11affac0 00000000`00000000     ntdll!RtlUserThreadStart+0x21

從棧方法 gc_thread_function() 來看，這是一個專有的 GC 線程，熟悉 server GC 的朋友應該知道，用戶線程分配 引發GC後，會通過 event 喚醒GC線程，言外之意就是還沒有找到這個用戶線程觸發的導火索，要想找到答案有很多方法，查看當前的 GCSettings 觀察 GC 觸發的誘因及代數，截圖如下：

我去，居然是一個誘導式FullGC，言外之意就是有代碼會調用 GC.Collect() ，接下來我們用 ~*e !clrstack 導出所有的線程棧，觀察 GC.Collect() 字樣，還真給找到了。。。

0:117> !clrstack 
OS Thread Id: 0x170c (117)
        Child SP               IP Call Site
0000007419f1d580 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_GC
    gc_type_background = 2,
#endif //BACKGROUND_GC
    gc_type_max = 3
};

接下來可以用 x 命令去檢索這個變數，觀察各自的佈局。

因為 gc_type_compacting 和 gc_type_blocking 有重疊，而且觀察進程運行了 17min，所以 17min 觸發了至少 113 =90+23 次 FullGC。

0:117> .time
Debug session time: Tue Sep  6 15:56:08.000 2022 (UTC + 8:00)
System Uptime: 0 days 21:59:52.396
Process Uptime: 0 days 0:17:10.000
  Kernel time: 0 days 0:34:34.000
  User time: 0 days 0:39:05.000

這個算頻繁嗎？觸發點是否集中？ 在DUMP這種照片下是不得而知的，為了穩一點再看看可有其他的線索。

3. 還有其他線索嗎？

既然線程池堆積了很多任務，除了受到一些諸如 GC 的外因影響，內因肯定是最主要的，既然都是 http 請求，可以用 !whttp 觀察各自的 HttpContext。

0:117> !whttp
HttpContext    Thread Time Out Running  Status Verb     Url
0000017b406b6f80  102 00:05:00 00:08:56    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017b46797110  107 00:05:00 00:07:35    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017b814572f8   97 00:05:00 00:08:49    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017b84634490  104 00:05:00 00:07:46    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017bc04767b0   90 00:05:00 00:08:43    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e3e79cbb8   96 00:05:00 00:09:45    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e7ee10b80   88 00:05:00 00:09:40    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e89b2cfb0  109 00:05:00 00:04:37    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017e8adb6b80  106 00:05:00 00:02:53    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017d41e90f28  103 00:05:00 00:08:04    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017d4385d528  101 00:05:00 00:07:39    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017d471b7d58   98 00:05:00 00:06:50    200 GET      /xxxx/xxx/xxxLogOutputExcel
0000017bc8283c48  117 00:05:00 00:00:32    200 GET      /xxx/xxx/xxxMedTags
...

從卦中看，有兩點信息：

1. 高達 17 個 Excel 導出請求，一般來說導出操作都是 CPU 密集型的, 17 個請求可能剛好把 CPU 全部打滿，可以通過 !cpuid 驗證下。

0:117> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,79,1  <unavailable>   1995
 1  6,79,1  <unavailable>   1995
 2  6,79,1  <unavailable>   1995
 3  6,79,1  <unavailable>   1995
 4  6,79,1  <unavailable>   1995
 5  6,79,1  <unavailable>   1995
 6  6,79,1  <unavailable>   1995
 7  6,79,1  <unavailable>   1995
 8  6,79,1  <unavailable>   1995
 9  6,79,1  <unavailable>   1995
10  6,79,1  <unavailable>   1995
11  6,79,1  <unavailable>   1995
12  6,79,1  <unavailable>   1995
13  6,79,1  <unavailable>   1995
14  6,79,1  <unavailable>   1995
15  6,79,1  <unavailable>   1995

2. 觸發 GC 的請求是 /xxx/xxx/xxxMedTags 也高達 32s ，說明程式此時整體變慢。

接下來就是把挖到的這兩點信息告訴朋友，重點是 xxxLogOutputExcel 導出，一定要限定頻次。

三：總結

總體來說這次生產事故誘發的因素有兩個：

• 主因是客戶高頻次的點擊 Excel 導出，越著急越點，越點越著急，導致系統的雪崩。

• 高頻的Excel點擊操作，間接導致 Spire.Pdf 在某一時段為了釋放非托管資源頻發的誘導 GC.Collect，進而雪上加霜。

解決方案就簡單了，抑制高頻點擊。

多一點耐心，少一點急躁，也許我們相處的會更好。