記一次 .NET 某機械臂智慧機器人控制系統MRS CPU爆高分析

一：背景

1. 講故事

這是6月中旬一位朋友加wx求助dump的故事，他的程式 cpu爆高UI卡死，問如何解決，截圖如下：

在拿到這個dump後，我發現這是一個關於機械臂的MRS程式，哈哈，在機械臂這種智慧機器人領域居然還有 .NET 的用武之地，有點超出我的認知哈，不知道把員工當兄弟的大強子倉庫裡可有 .NET 控制的幾臺機械臂。

關於介面卡死的問題我這裡就不討論了，只討論這個cpu爆高的問題如何解決，畢竟追這個系列的朋友都被前面那些各種 記憶體洩漏，記憶體爆漲 弄倦了，換個口味也挺好。

二： Windbg 分析

1. 現象驗證

別人說cpu高，我得先用資料證明一下是否真的如此，方法很簡單，用 !tp 命令即可。



0:000> !tp

CPU utilization: 100%

Worker Thread: Total: 151 Running: 151 Idle: 0 MaxLimit: 32767 MinLimit: 4

Work Request in Queue: 1

    AsyncTimerCallbackCompletion TimerInfo@000000001dc25bb0

--------------------------------------

Number of Timers: 0

--------------------------------------

Completion Port Thread:Total: 2 Free: 1 MaxFree: 8 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 4

從卦象上看，有兩個值得關注的指標：

CPU utilization: 100%

這表明當時抓dump的那個時刻，機器的cpu確實為100%，確實比較糟糕，說點題外話，有幾位朋友說他想抓這種100%的dump，發現阿里雲的遠端桌面連不上，太尷尬了。。。

Total: 151 Running: 151

當前執行緒池的work執行緒有151個，正在執行的也是151個，這說明什麼呢？說明每一個執行緒都在忙碌著，同時也預示著當前的執行緒不夠用，急需招人，當前系統絕對有一股力在推著它。

2. 檢視執行緒列表

接下來再看一下當前的執行緒列表，使用 !t 命令。



0:000> !t

ThreadCount:      171

UnstartedThread:  1

BackgroundThread: 167

PendingThread:    1

DeadThread:       2

Hosted Runtime:   no

                                                                                                        Lock

       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception

   0    1  7e0 00000000028901c0    26020 Preemptive  00000000049C9360:00000000049C98A8 0000000000602420 1     STA (GC)

   9    2  df8 00000000028bc850    2b220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA (Finalizer)

  11    3  144 000000001fdef570  102a220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA (Threadpool Worker)

  14    9  dbc 0000000020703650  202b220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA

  15   10  5a4 00000000206d5860    2b220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA

  16   11  17c 00000000206df220    2b220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA

  17   12  dd4 00000000205e49a0    2b220 Preemptive  00000000049A7A20:00000000049A98A8 0000000000602420 0     MTA

  18   14  8fc 0000000020495000    2b220 Preemptive  00000000049A5A40:00000000049A78A8 0000000000602420 0     MTA

  19   17  a84 0000000020817490  202b220 Preemptive  00000000049ADBB0:00000000049AF8A8 0000000000602420 0     MTA

  ...

 180  167 12b8 0000000026436d70  1021220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA (Threadpool Worker)

 181  168 11a4 0000000026437540  1021220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA (Threadpool Worker)

 182  169  880 0000000026437d10  1021220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA (Threadpool Worker)

 183  170 1334 00000000264384e0  1021220 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     MTA (Threadpool Worker)

 184  171  278 0000000026438cb0     1400 Preemptive  0000000000000000:0000000000000000 0000000000602420 0     Ukn

從卦象看：ID=1 的執行緒有一個 GC 標記，我去，看樣子是觸發GC了，這裡要提醒一下，工作執行緒在 GC=Workstation 模式下，是可以充當GC回收執行緒的，這和 GC=Server 模式下是不同的。

3. 檢視執行緒棧

既然是 GC 觸發了，那就 死馬當活馬醫，按照GC觸發的套路查，基本流程如下：

調出所有執行緒棧，使用 !EEStack 命令。



0:000> !EEStack

---------------------------------------------

Thread   0

Current frame: ntdll!NtGetContextThread+0xa

Child-SP         RetAddr          Caller, Callee

...

查詢 WaitUntilGCComplete 關鍵詞看有多少執行緒在等待 GC 回收

使用 Ctrl+F 檢索即可，截圖如下：

從圖中看：有96個執行緒在等待GC完成，到這裡，我的嘴角已經上揚了，。。。

查詢 try_allocate_more_space 關鍵詞判斷是什麼業務邏輯觸發了GC

我去，咋回事？這有頭沒尾的，既然沒有 try_allocate_more_space 關鍵詞也就說明當前的GC大概率不是自動觸發的，那又是誰觸發的呢？有點奇葩哈？

4. GC到底是怎麼觸發的

要想找出答案，最簡單粗暴的做法就是看下那個標記為 GC 的執行緒到底做了什麼? 這裡使用 !clrstack 即可。



0:000> !clrstack

OS Thread Id: 0x7e0 (0)

        Child SP               IP Call Site

000000000043e470 00000000778c1fea [InlinedCallFrame: 000000000043e470] System.GC._Collect(Int32, Int32)

000000000043e470 000007feea38ce2a [InlinedCallFrame: 000000000043e470] System.GC._Collect(Int32, Int32)

000000000043e440 000007feea38ce2a System.GC.Collect()

000000000043e4f0 000007fe8bcd29ca xxx.xxx.T_Tick(System.Object, System.EventArgs)

000000000043e520 000007fee3d0ef6f System.Windows.Forms.Timer.OnTick(System.EventArgs)

000000000043e550 000007fee3d076fe System.Windows.Forms.Timer+TimerNativeWindow.WndProc(System.Windows.Forms.Message ByRef)

000000000043e580 000007fee3cea3c3 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)

000000000043e620 000007fee43611f1 DomainBoundILStubClass.IL_STUB_ReversePInvoke(Int64, Int32, Int64, Int64)

000000000043e890 000007feeac1221e [InlinedCallFrame: 000000000043e890] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)

000000000043e890 000007fee3d6a378 [InlinedCallFrame: 000000000043e890] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)

000000000043e860 000007fee3d6a378 DomainBoundILStubClass.IL_STUB_PInvoke(MSG ByRef)

000000000043e920 000007fee3cff23e System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(IntPtr, Int32, Int32)

000000000043ea10 000007fee3cfebd2 System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)

000000000043eab0 000007fee3cfe9df System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)

000000000043eb10 000007fe8b6208a6 xxx.Program.Main()

000000000043ede0 000007feeac16bb3 [GCFrame: 000000000043ede0]

我去，從執行緒棧上看，居然是一個 Timer 在手工呼叫 GC.Collect()，這是什麼業務，接下來用 ip2md + savemodule 把 xxx.xxx.T_Tick 原始碼匯出來看一看。



0:000> !ip2md 000007fe8bcd29ca

MethodDesc:   000007fe8b50ae90

Method Name:  xxx.xxx.T_Tick(System.Object, System.EventArgs)

Class:        000007fe8b6ac628

MethodTable:  000007fe8b50b080

mdToken:      00000000060002b5

Module:       000007fe8b504118

IsJitted:     yes

CodeAddr:     000007fe8bcd29a0

Transparency: Critical

0:000> !savemodule 000007fe8b504118 D:\dumps\MRS-CPU\T_Tick.dll

3 sections in file

section 0 - VA=2000, VASize=1a85fc, FileAddr=200, FileSize=1a8600

section 1 - VA=1ac000, VASize=5088, FileAddr=1a8800, FileSize=5200

section 2 - VA=1b2000, VASize=c, FileAddr=1ada00, FileSize=200

用 ILSpy 開啟 T_Tick.dll，截圖如下：

從程式碼邏輯看，朋友做了 3min 觸發一個 GC 的業務邏輯，我不知道這麼做是想幹嘛，所以就和朋友在wx上交流了下。

5. 真的全是GC背鍋嗎

其實在我分享過的很多cpu爆高的dump中，有相當一部分是由於頻繁觸發GC所致，比如大字串拼接，誤用正則表示式等等，但3min一次的gc就能把cpu搞掛，這要是小白還能忽悠過去，在懂一點的朋友眼裡是經不住推敲的，言外之意就是真正的禍首還沒找到。。。要尋找可疑禍首，最好的方法就是對所有執行緒棧進行地毯式搜尋，截圖如下：

從上圖中可以看到，當前有112個執行緒卡在 System.Collections.Generic.Dictionary2[[System.Int32, mscorlib],[System.__Canon, mscorlib]].FindEntry(Int32) 處，你肯定會說了，卡住是因為GC觸發凍住了所有執行緒所致，當然這個理論無需反駁，確實是這樣。

我相信有經驗的朋友肯定會發現一個問題，那就是多執行緒環境下出現了一個執行緒不安全的 Dictionary，我在之前的一篇車聯網CPU爆高分析中也提到了這個問題，它會導致在 FindEntry 操作時出現死迴圈的怪異現象。

到這裡為止，CPU爆高的問題基本也就全找到了。

三：總結

本次cpu爆高事故主要是由於:

多執行緒環境下使用了非執行緒安全的 Dictionary 導致了死迴圈。
週期性的呼叫 GC.Collection() 讓其雪上加霜。

找出問題後，解決辦法也就簡單了，建議將 Dictioanry 改成 ConcurrentDictionary，同時去掉手工對 GC.Collection() 的呼叫。

記一次 .NET 某機械臂智慧機器人控制系統MRS CPU爆高分析