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

本文轉載自查看原文 2021-09-06 09:48 5425 C#/ windbg

一：背景

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() 的調用。

免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。

猜您在找 記一次 .NET 某智能交通后台服務 CPU爆高分析記一次 .NET 某資訊論壇 CPU爆高分析記一次 .NET 某醫院HIS系統 CPU爆高分析記一次 .NET 某電商交易平台Web站 CPU爆高分析記一次 .NET 某市附屬醫院 Web程序偶發性CPU爆高分析記一次 .NET游戲站程序的 CPU 爆高分析記一次 .NET 車聯網雲端服務 CPU爆高分析記一次 .NET 某旅行社Web站 CPU爆高分析 SmartRobotControlPlateform——智能機器人控制平台（新）記一次 .NET醫院公眾號系統線程CPU雙高分析