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

更多高质量干货：参见我的 GitHub: dotnetfly

一：背景

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上交流了下。

.png)

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爆高分析

一：背景

1. 讲故事

二： Windbg 分析

1. 现象验证

2. 查看线程列表

3. 查看线程栈

4. GC到底是怎么触发的

5. 真的全是GC背锅吗

三：总结

一线码农

引用和评论

记一次 .NET 某供应链WEB网站 CPU 爆高事故分析

.NET中通过C#导入Excel数据到DataTable以及DataTable到Excel

C#导出数据库到Excel文件（.NET）

.NET平台通过C#代码轻松提取PDF文本

C# 字符串拼接的 7 种方式及性能对比

.NET用C#添加动作到PDF文档

使用WinDbg调试.net3.5（基于.net2.0)的iis网站程序CPU过高及内存过高的问题