技術文章 » 記一次 .NET 某電子病歷 CPU 爆高分析

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

2022-10-12 12:00:51

一：背景

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
  1. 觸發 GC 的請求是 /xxx/xxx/xxxMedTags 也高達 32s ，說明程式此時整體變慢。

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

三：總結

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

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

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

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

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

圖片名稱