记一次 .NET 某机械臂智能机器人控制系统MRS CPU爆高分析

2022-06-01 08:46:25

一：背景

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