記一次 .NET某設(shè)備監(jiān)控自動(dòng)化系統(tǒng) CPU爆高分析
一：背景
1. 講故事
先說(shuō)一下題外話(huà)，一個(gè)監(jiān)控別人系統(tǒng)運(yùn)行狀態(tài)的程序，結(jié)果自己出問(wèn)題了，有時(shí)候想一想還是挺諷刺的，哈哈，開(kāi)個(gè)玩笑，我們回到正題，前些天有位朋友找到我，說(shuō)他們的系統(tǒng)會(huì)偶發(fā)性CPU爆高，CPU上去了就下不來(lái)了，讓我?guī)兔匆幌略趺椿厥?，而且自己也分析過(guò)了，沒(méi)找到哪里有問(wèn)題，寫(xiě)監(jiān)控的都是高手，給我的第一感覺(jué)就是這個(gè)dump可能解決起來(lái)不容易，不管怎么說(shuō)，有了dump就開(kāi)干吧！
二：WinDbg 分析
1. CPU真的爆高嗎
作為調(diào)試人，第一準(zhǔn)則就是不要輕信任何人透露給你的信息，因?yàn)槿思以谶@塊是一個(gè)小白，往往他的信息會(huì)把你帶偏，我們只相信數(shù)據(jù)即可，切記!!! 所以我們先用 !tp 觀(guān)察下CPU使用率。
0:198> !tp
CPU utilization: 100%
Worker Thread: Total: 197 Running: 42 Idle: 154 MaxLimit: 32767 MinLimit: 8
Work Request in Queue: 0
--------------------------------------
Number of Timers: 0
--------------------------------------
Completion Port Thread:Total: 10 Free: 5 MaxFree: 16 CurrentLimit: 10 MaxLimit: 1000 MinLimit: 8從卦中信息看當(dāng)前 CPU=100%，還是蠻慘的，那到底誰(shuí)在吃CPU資源呢？根據(jù)經(jīng)驗(yàn)先查一下是不是觸發(fā)了2代GC，接下來(lái)用 !t 觀(guān)察下是否有GC標(biāo)記。
0:198> !t
ThreadCount: 214
UnstartedThread: 0
BackgroundThread: 211
PendingThread: 0
DeadThread: 1
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 276f0 000002789526b5f0 2a020 Preemptive 0000000000000000:0000000000000000 000002789525e840 0 MTA
2 2 25e5c 0000027895296d00 2b220 Preemptive 0000000000000000:0000000000000000 000002789525e840 0 MTA (Finalizer)
3 3 260e8 00000278ae35f0c0 202b020 Preemptive 0000000000000000:0000000000000000 000002789525e840 0 MTA
...
169 2113 10c20 00000278c26766c0 1029220 Preemptive 00000278B5D7D188:00000278B5D7D188 000002789525e840 1 MTA (GC) (Threadpool Worker) xxxException 00000278b5d46ce0
...尼瑪從卦中的 (GC) 來(lái)看，還真的觸發(fā)了GC，接下來(lái)的研究方向就是洞察下是不是CPU爆高的禍?zhǔn)住?/p>
2. GC觸發(fā)導(dǎo)致的嗎
要尋找這個(gè)問(wèn)題的答案，首先就是看下這次GC是不是 FullGC 即可，可以切到 169 號(hào)線(xiàn)程，觀(guān)察下線(xiàn)程棧。
0:169> k 10
# Child-SP RetAddr Call Site
00 000000c4`36ffb798 00007ffc`d5f14313 ntdll!NtWaitForSingleObject+0x14
01 000000c4`36ffb7a0 00007ffc`c927cb27 KERNELBASE!WaitForSingleObjectEx+0x93
02 000000c4`36ffb840 00007ffc`c927cadf clr!CLREventWaitHelper2+0x3c
03 000000c4`36ffb880 00007ffc`c927ca5c clr!CLREventWaitHelper+0x1f
04 000000c4`36ffb8e0 00007ffc`c926bd32 clr!CLREventBase::WaitEx+0x7c
05 000000c4`36ffb970 00007ffc`c9269bc4 clr!ThreadSuspend::SuspendRuntime+0x32c
06 000000c4`36ffba60 00007ffc`c91814e3 clr!ThreadSuspend::SuspendEE+0x128
07 000000c4`36ffbb60 00007ffc`c9185f51 clr!WKS::GCHeap::GarbageCollectGeneration+0xb7
08 000000c4`36ffbbc0 00007ffc`c9260f56 clr!WKS::gc_heap::trigger_gc_for_alloc+0x2d
09 000000c4`36ffbc00 00007ffc`c6b0f7e7 clr!JIT_NewArr1+0xa97
0a 000000c4`36ffc030 00007ffc`6a388270 mscorlib_ni!System.String.ToCharArray+0x27 [f:\dd\ndp\clr\src\BCL\system\string.cs @ 758]
0b 000000c4`36ffc080 00007ffc`6a3880ed 0x00007ffc`6a388270
0c 000000c4`36ffc100 00007ffc`6a56056d 0x00007ffc`6a3880ed
0d 000000c4`36ffc150 00007ffc`6a3cd749 0x00007ffc`6a56056d
0e 000000c4`36ffc1b0 00007ffc`c911989d 0x00007ffc`6a3cd749
0f 000000c4`36ffc220 00007ffc`c9119764 clr!ExceptionTracker::CallHandler+0xfd從卦中看此時(shí)的GC還處于早期的 SuspendEE 階段，無(wú)法獲取內(nèi)部的 settings 結(jié)構(gòu)，這就比較麻煩了，那怎么辦呢？只能看看 GarbageCollectGeneration 的第一個(gè)參數(shù)有沒(méi)有保存在棧中，要是沒(méi)有就慘了。。。方法簽名如下：
size_t
GCHeap::GarbageCollectGeneration (unsigned int gen, gc_reason reason)
{
}根據(jù) x64調(diào)用協(xié)定，gen是保存在 rdx 寄存器里，接下來(lái)觀(guān)察匯編代碼。
0:000> uf 00007ffc`c91814e3
clr!WKS::GCHeap::GarbageCollectGeneration:
00007ffc`c918142c 48895c2418 mov qword ptr [rsp+18h],rbx
00007ffc`c9181431 89542410 mov dword ptr [rsp+10h],edx
00007ffc`c9181435 48894c2408 mov qword ptr [rsp+8],rcx
00007ffc`c918143a 55 push rbp
00007ffc`c918143b 56 push rsi
00007ffc`c918143c 57 push rdi
00007ffc`c918143d 4154 push r12
00007ffc`c918143f 4155 push r13
00007ffc`c9181441 4156 push r14
00007ffc`c9181443 4157 push r15
...
0:169> dd 000000c4`36ffbbc0-0x8+0x10 L1
000000c4`36ffbbc8 00000000從卦中看，謝天謝地，edx保存在 rsp+10h 的位置，通過(guò)dp觀(guān)察內(nèi)存地址的值發(fā)現(xiàn)是0，也就表示當(dāng)前是 0 代GC，這種smallgc 經(jīng)常觸發(fā)是很正常的，并不是我們CPU爆高的誘因，接下來(lái)就陷入迷茫了。。。
3. 路在何方
撞了南墻之后得要看看其他路子，其實(shí)剛才用 !t 觀(guān)察線(xiàn)程列表的時(shí)候我就注意到一個(gè)特征，那就是很多線(xiàn)程上掛了異常，截圖如下：
圖片
從卦中看此時(shí)有19個(gè)線(xiàn)程在拋 xxxResultException 異常，做過(guò)開(kāi)發(fā)的朋友都知道，如果頻繁的拋異常是很耗CPU資源的，因?yàn)樗O(shè)計(jì)到用戶(hù)態(tài)到內(nèi)核態(tài)的切換，如果有 19 個(gè)線(xiàn)程一起拋異常，那絕對(duì)是一個(gè)災(zāi)難。。。
有些朋友說(shuō)我cpu猛一點(diǎn)是不是就可以了，哈哈，理論上是可以的，可以用 !cpuid 觀(guān)察下這臺(tái)機(jī)器的cpu核心數(shù)。
0:169> !cpuid
CP F/M/S Manufacturer MHz
0 6,167,1 <unavailable> 3408
1 6,167,1 <unavailable> 3408
2 6,167,1 <unavailable> 3408
3 6,167,1 <unavailable> 3408
4 6,167,1 <unavailable> 3408
5 6,167,1 <unavailable> 3408
6 6,167,1 <unavailable> 3408
7 6,167,1 <unavailable> 3408從證據(jù)鏈的完整性上來(lái)說(shuō)，其實(shí)這里還需要再做一個(gè)驗(yàn)證，就是19個(gè)線(xiàn)程拋異常不代表他們的并發(fā)性，言外之意就是能不能再找一些其他證據(jù)，怎么找其他證據(jù)呢？
做C#開(kāi)發(fā)的朋友應(yīng)該知道，Exception 屬于引用類(lèi)型，如果密集拋了很多異常，那托管堆上自然就有很多，直到GC回收，所以我們觀(guān)察下這個(gè)時(shí)間差即可，使用 !wdae 命令，這里為了隱私性我就模糊了哈。
0:169> !wdae
384 of Type: xxxResultException 000002789fdb6478 000002789fdb69b0 000002789fdb9848
Message: xxxFailed
Inner Exception: (none)
Stack:
IP Function
00007ffc6a269861 xxx.ChannelAsyncOperation`1[[System.Int32, mscorlib]].End(Int32, Boolean)
...
411 of Type: xxxResultException 000002789fdb6e90 000002789fdb7090 000002789fdb72a8
Message: xxxClosed
Inner Exception: (none)
Stack:
IP Function
00007ffc6a269861 xxx.ChannelAsyncOperation`1[[System.Int32, mscorlib]].End(Int32, Boolean)
...
808 Exceptions in 12 unique type/stack combinations (duplicate types in similar stacks may be rethrows)從卦中看當(dāng)前拋了808個(gè)異常，大多是和channel通信有關(guān)，結(jié)合16個(gè)線(xiàn)程并發(fā)拋，這就穩(wěn)了，看樣子cpu爆高期間就是由于高頻的拋異常所致，分析出這些信息之后，就是告訴朋友把這些異常給解決掉即可。
三：總結(jié)
CPU爆高的誘因非常多，高頻的拋異常就屬于其中一例，其實(shí)這種通信時(shí)發(fā)生了突發(fā)異常正是 Polly 這種 彈性和瞬態(tài)故障處理庫(kù) 大顯身手的地方。
