記一次 .NET 某藥廠業務系統 CPU爆高分析

一線碼農發表於2023-12-20

一：背景

1. 講故事

前段時間有位朋友找到我，說他們的程式出現了CPU爆高，讓我幫忙看下怎麼回事？這種問題好的辦法就是抓個dump丟給我，推薦的工具就是用 procdump 自動化抓捕。

二：Windbg 分析

1. CPU 真的爆高嗎

還是老規矩，要想找到這個答案，可以使用 !tp 命令。


0:044> !tp
logStart: 1
logSize: 200
CPU utilization: 88 %
Worker Thread: Total: 8 Running: 4 Idle: 4 MaxLimit: 1023 MinLimit: 4
Work Request in Queue: 0
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 8 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 4

從卦中資料看當前cpu確實達到了 88%，接下來我們觀察下這個程式的機器cpu是否給力，可以用 !cpuid 觀察。


0:044> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,94,3  GenuineIntel    3192
 1  6,94,3  GenuineIntel    3192
 2  6,94,3  GenuineIntel    3192
 3  6,94,3  GenuineIntel    3192

從卦中看，尼瑪也就4core，有點弱哈，好歹也是一個高利潤的藥廠，這麼摳門哈。

2. 為什麼會CPU爆高

導致 CPU 爆高的因素有很多，沒有標準答案，需要自己去找原因，首先我們觀察下這個程式的執行緒數量，可以使用 !t 命令即可。


0:044> !t
ThreadCount:      451
UnstartedThread:  0
BackgroundThread: 443
PendingThread:    0
DeadThread:       1
Hosted Runtime:   no
                                                                             Lock  
 DBG   ID     OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1     22b8 04CE8728     26020 Preemptive  18E5C92C:18E5E4DC 04c86c20 -00001 STA 
   3    2     17c8 04B25768     2b220 Preemptive  18CAF3A0:18CB1374 04c86c20 -00001 MTA (Finalizer) 
   4    4     238c 04C0CDD8   202b020 Preemptive  18E45D88:18E464DC 04c86c20 -00001 MTA 
   5    5     230c 0A6C37A0   202b020 Preemptive  18DAC318:18DAC47C 04c86c20 -00001 MTA 
   6    6     23a0 0A70E620   202b220 Preemptive  00000000:00000000 04c86c20 -00001 MTA 
   ...

從卦中資料看，當前有 451 個執行緒，其中後臺執行緒是 443 個，再結合剛才的 !tp 看到的執行緒池執行緒也才 8 個，這就說明這個程式中有 400+ 的執行緒是直接透過 new Thread 建立的，這個資訊就比較可疑了，為啥不用執行緒池用 Thread ，有蹊蹺。

接下來的思路就是使用 ~*e !clrstack 命令觀察下每個執行緒此時都在做什麼，命令一輸入，刷了好久。


0:044> ~*e !clrstack
...
OS Thread Id: 0x220c (18)
Child SP       IP Call Site
184CF614 77dd19dc [HelperMethodFrame: 184cf614] System.Threading.Thread.SleepInternal(Int32)
184CF680 141975f4 System.Threading.Thread.Sleep(Int32) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Thread.cs @ 357]
184CF694 165055b9 xxx.ActionThread`1[[xxx]].Loop()
184CF878 74467741 System.Threading.Thread+StartHelper.Callback(System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Thread.cs @ 42]
184CF888 7446fca1 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs @ 183]
184CF8C0 74466742 System.Threading.Thread.StartCallback() [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 105]
184CFA14 74cbc29f [DebuggerU2MCatchHandlerFrame: 184cfa14] 
...

在卦中的各個執行緒棧上也沒有看到什麼特別明顯的業務函式，大多都是停在 Thread.SleepInternal 上進行等待，這就讓我陷入了迷茫。

3. 一朝頓悟，走出迷茫

CPU不可能無緣無故的爆高，總會是那些執行緒給抬起來的，但這個程式中的執行緒大多都在 Thread.SleepInternal 上，若說他們能把 CPU 弄爆總有點說不過去。

但問題總得要解決，在無突破口的情況也只能硬著頭皮在 Thread.SleepInternal 上強行突破了，首先用 Ctrl+F 搜下有多少執行緒卡在 SleepInternal 上，截圖如下：

尼瑪，幾乎所有執行緒都在 Sleep，一般來說有這麼多執行緒都在 Sleep 也是少數，接下來抽一個執行緒看看業務方法是怎麼進行 Sleep 的，參考程式碼如下：

在這個Loop方法中我發現有很多的 Sleep(1)，看到這個我突然想到了高頻的上下文切換導致的 CPU 爆高。

接下來這個程式碼的指令到底停在哪個方法呢？可以反編譯 Loop 方法。


0:047> !clrstack
OS Thread Id: 0xad8 (47)
Child SP       IP Call Site
20B5F434 77dd19dc [HelperMethodFrame: 20b5f434] System.Threading.Thread.SleepInternal(Int32)
20B5F4A0 141975f4 System.Threading.Thread.Sleep(Int32) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Thread.cs @ 357]
20B5F4B4 1f123c71 xxx.ActionThread`1[[xxx].Loop()
20B5F698 74467741 System.Threading.Thread+StartHelper.Callback(System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Thread.cs @ 42]
20B5F6A8 1baab7da System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs @ 183]
20B5F6E0 74466742 System.Threading.Thread.StartCallback() [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 105]
20B5F834 74cbc29f [DebuggerU2MCatchHandlerFrame: 20b5f834] 
0:047> !U /d 1f123c71
Normal JIT generated code
xxx.ActionThread`1[xxx].Loop()
ilAddr is 0A324040 pImport is 08AD6468
Begin 1F123C10, size abd
1f123c10 55              push    ebp
1f123c11 8bec            mov     ebp,esp
1f123c13 57              push    edi
1f123c14 56              push    esi
1f123c15 81ecd4010000    sub     esp,1D4h
1f123c1b c5f877          vzeroupper
1f123c1e c5d857e4        vxorps  xmm4,xmm4,xmm4
1f123c22 c5fa7fa524feffff vmovdqu xmmword ptr [ebp-1DCh],xmm4
1f123c2a c5fa7fa534feffff vmovdqu xmmword ptr [ebp-1CCh],xmm4
1f123c32 b850feffff      mov     eax,0FFFFFE50h
1f123c37 c5fa7f6405f4    vmovdqu xmmword ptr [ebp+eax-0Ch],xmm4
1f123c3d c5fa7f640504    vmovdqu xmmword ptr [ebp+eax+4],xmm4
1f123c43 c5fa7f640514    vmovdqu xmmword ptr [ebp+eax+14h],xmm4
1f123c49 83c030          add     eax,30h
...
1f123c5a e84115cc55      call    coreclr!JIT_DbgIsJustMyCode (74de51a0)
1f123c5f 90              nop
1f123c60 90              nop
1f123c61 e9300a0000      jmp     xxx.ActionThread<xxx>.Loop+0xa86 (1f124696)
1f123c66 90              nop
1f123c67 b901000000      mov     ecx,1
1f123c6c e87f54eaea      call    09fc90f0 (System.Threading.Thread.Sleep(Int32), mdToken: 06002D01)
>>> 1f123c71 90              nop
...

透過卦中的 >>> 可以確認很多的方法都是在 while (!base.IsTerminated) 中進行空轉，如果 Sleep(1) 的執行緒比較少那可能沒什麼問題，但也扛不住400多執行緒一起玩哈，最後高頻的上下文切換導致的 CPU 爆高。

在 Sleep(1) 內部會涉及到CPU的等待佇列，就緒佇列，以及定時器 _KTIMER 核心物件, 因為 Windows 原始碼不公開，內部還是比較搞的，可以用 !pcr 命令觀察下 cpu的揹包。


lkd> !pcr 0
KPCR for Processor 0 at fffff8058023c000:
    Major 1 Minor 1
	NtTib.ExceptionList: fffff80589089fb0
	    NtTib.StackBase: fffff80589088000
	   NtTib.StackLimit: 000000137e1fa158
	 NtTib.SubSystemTib: fffff8058023c000
	      NtTib.Version: 000000008023c180
	  NtTib.UserPointer: fffff8058023c870
	      NtTib.SelfTib: 000000137dfe0000

	            SelfPcr: 0000000000000000
	               Prcb: fffff8058023c180
	               Irql: 0000000000000000
                 ...

	      CurrentThread: ffff910c66906080
	         NextThread: 0000000000000000
	         IdleThread: fffff80583d27a00

	          DpcQueue: 

lkd> dt nt!_KPRCB fffff8058023c180
   +0x008 CurrentThread    : 0xffff910c`66906080 _KTHREAD
   +0x010 NextThread       : (null) 
   +0x018 IdleThread       : 0xfffff805`83d27a00 _KTHREAD
   ...
   +0x7c00 WaitListHead     : _LIST_ENTRY [ 0xffff910c`5ec30158 - 0xffff910c`628b1158 ]
   +0x7c80 DispatcherReadyListHead : [32] _LIST_ENTRY [ 0xfffff805`80243e00 - 0xfffff805`80243e00 ]

上面的[32]就是等待執行緒的32個優先順序的陣列佇列。

有了上面的分析結果，最後就是告訴朋友做到如下兩點：

  • 減少 Thread.Sleep(1) 的執行緒參與數。
  • 儘量將 1 -> 50 來緩解，當然越大越好。

三：總結

這次CPU的爆高還是挺有意思，不是業務方法導致的爆高，而是大量的 Sleep(1) 導致的高頻上下文切換所致，有點意思，留下此文給大家避坑！

相關文章