记一次 .NET 某药厂业务系统 CPU爆高分析
一:背景
1. 講故事
前段時(shí)間有位朋友找到我,說(shuō)他們的程序出現(xiàn)了CPU爆高,讓我?guī)兔聪略趺椿厥拢窟@種問(wèn)題好的辦法就是抓個(gè)dump丟給我,推薦的工具就是用 procdump 自動(dòng)化抓捕。
二:Windbg 分析
1. CPU 真的爆高嗎
還是老規(guī)矩,要想找到這個(gè)答案,可以使用 !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
從卦中數(shù)據(jù)看當(dāng)前cpu確實(shí)達(dá)到了 88%,接下來(lái)我們觀察下這個(gè)程序的機(jī)器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,有點(diǎn)弱哈,好歹也是一個(gè)高利潤(rùn)的藥廠,這么摳門哈。
2. 為什么會(huì)CPU爆高
導(dǎo)致 CPU 爆高的因素有很多,沒(méi)有標(biāo)準(zhǔn)答案,需要自己去找原因,首先我們觀察下這個(gè)程序的線程數(shù)量,可以使用 !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
...
從卦中數(shù)據(jù)看,當(dāng)前有 451 個(gè)線程,其中后臺(tái)線程是 443 個(gè),再結(jié)合剛才的 !tp 看到的線程池線程也才 8 個(gè),這就說(shuō)明這個(gè)程序中有 400+ 的線程是直接通過(guò) new Thread 創(chuàng)建的,這個(gè)信息就比較可疑了,為啥不用線程池用 Thread ,有蹊蹺。
接下來(lái)的思路就是使用 ~*e !clrstack 命令觀察下每個(gè)線程此時(shí)都在做什么,命令一輸入,刷了好久。
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]
...
在卦中的各個(gè)線程棧上也沒(méi)有看到什么特別明顯的業(yè)務(wù)函數(shù),大多都是停在 Thread.SleepInternal 上進(jìn)行等待,這就讓我陷入了迷茫。
3. 一朝頓悟,走出迷茫
CPU不可能無(wú)緣無(wú)故的爆高,總會(huì)是那些線程給抬起來(lái)的,但這個(gè)程序中的線程大多都在 Thread.SleepInternal 上,若說(shuō)他們能把 CPU 弄爆總有點(diǎn)說(shuō)不過(guò)去。
但問(wèn)題總得要解決,在無(wú)突破口的情況也只能硬著頭皮在 Thread.SleepInternal 上強(qiáng)行突破了,首先用 Ctrl+F 搜下有多少線程卡在 SleepInternal 上,截圖如下:
尼瑪,幾乎所有線程都在 Sleep,一般來(lái)說(shuō)有這么多線程都在 Sleep 也是少數(shù),接下來(lái)抽一個(gè)線程看看業(yè)務(wù)方法是怎么進(jìn)行 Sleep 的,參考代碼如下:
在這個(gè)Loop方法中我發(fā)現(xiàn)有很多的 Sleep(1),看到這個(gè)我突然想到了高頻的上下文切換導(dǎo)致的 CPU 爆高。
接下來(lái)這個(gè)代碼的指令到底停在哪個(gè)方法呢?可以反編譯 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
...
通過(guò)卦中的 >>> 可以確認(rèn)很多的方法都是在 while (!base.IsTerminated) 中進(jìn)行空轉(zhuǎn),如果 Sleep(1) 的線程比較少那可能沒(méi)什么問(wèn)題,但也扛不住400多線程一起玩哈,最后高頻的上下文切換導(dǎo)致的 CPU 爆高。
在 Sleep(1) 內(nèi)部會(huì)涉及到CPU的等待隊(duì)列,就緒隊(duì)列,以及定時(shí)器 _KTIMER 內(nèi)核對(duì)象, 因?yàn)?Windows 源碼不公開,內(nèi)部還是比較搞的,可以用 !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個(gè)優(yōu)先級(jí)的數(shù)組隊(duì)列。
有了上面的分析結(jié)果,最后就是告訴朋友做到如下兩點(diǎn):
- 減少 Thread.Sleep(1) 的線程參與數(shù)。
- 盡量將 1 -> 50 來(lái)緩解,當(dāng)然越大越好。
三:總結(jié)
這次CPU的爆高還是挺有意思,不是業(yè)務(wù)方法導(dǎo)致的爆高,而是大量的 Sleep(1) 導(dǎo)致的高頻上下文切換所致,有點(diǎn)意思,留下此文給大家避坑!
總結(jié)
以上是生活随笔為你收集整理的记一次 .NET 某药厂业务系统 CPU爆高分析的全部?jī)?nèi)容,希望文章能夠幫你解決所遇到的問(wèn)題。
- 上一篇: 索引是什么?(什么是倒排索引)
- 下一篇: 将Abp默认事件总线改造为分布式事件总线