记一次 .NET 某医院HIS系统 CPU爆高分析

一：背景

1. 讲故事

前几天有位朋友加 wx 抱怨他的程序在高峰期总是莫名其妙的cpu爆高，求助如何分析？

记一次 .NET 某医院HIS系统 CPU爆高分析-LMLPHP

和这位朋友沟通下来，据说这问题困扰了他们几年😂，还请了微软的工程师过来解决，无疾而终，应该还是没找对微软的大佬。。。

关于程序CPU爆高的问题，老读者应该知道我都写了好几篇了，基本上归为两类：

GC 触发
大量 lock 锁

少部分就是各种莫名其妙的问题了，无法一一列举 🤣🤣🤣，既然朋友找到我了，我得想办法给他解决，话不多聊，上 windbg。

二： windbg 分析

1. 查看同步块表

遇到这种问题，首查 同步块表 已经是我的惯性思维了，命令很简单 !syncblk 。


0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
-----------------------------
Total           20779
CCW             16
RCW             21
ComClassFactory 0
Free            16490

我去，扑了一个空，同步块表中啥也没有。。。既然和锁没关系，那就看看线程吧，毕竟线程就是靠 CPU 养着的。

2. 查看线程

要想查看系统中的 托管线程 ，可以使用 !t 命令, 线程比较多，稍微简化一下。


0:000> !t
ThreadCount:      135
UnstartedThread:  0
BackgroundThread: 132
PendingThread:    0
DeadThread:       1
Hosted Runtime:   no
                                                                                                        Lock
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
  34    1 25d4 000001ea28702130    28220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn
  74    2 3ed0 000001ea286fa940    2b220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     MTA (Finalizer)
  76    3 4a70 000001f4447d7810  102a220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     MTA (Threadpool Worker)
  77    4 326c 000001f4447dbe60    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn
  78    6 2dac 000001f4447d9750  1020220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn (Threadpool Worker)
  79    7 1468 000001f444a2d6f0    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 1     Ukn (GC)
  80    8   f0 000001f444a2cf20    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn
  81    9 3118 000001f444a2f630    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn

先卖个关子，可有朋友看出这些线程有什么异样？？？对，线程 79 的最后一列有一个 Ukn (GC) 标记，我想你肯定好奇，这说明什么？由于底层GC的模式有些变更，但不管怎么说，它在一定程度上告诉你，你的程序触发了GC，为了进一步验证，可以用 !t -special 看下 79 号线程到底属于什么类别以及更加详细的信息。


0:000> !t -special
ThreadCount:      135
UnstartedThread:  0
BackgroundThread: 132
PendingThread:    0
DeadThread:       1
Hosted Runtime:   no
                                                                                                        Lock
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
  34    1 25d4 000001ea28702130    28220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn
  79    7 1468 000001f444a2d6f0    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 1     Ukn (GC)

OSID Special thread type
41 38d8 DbgHelper
42 1c88 GC
74 3ed0 Finalizer
75 402c ProfilingAPIAttach
76 4a70 Timer
79 1468 GC SuspendEE

从最后一行输出中可以看到， 79就是GC线程，后面还有一个奇怪的 SuspendEE 标记，你又好奇了，这又啥意思？

也就是说，79号线程把 CLR执行引擎 给冻结了，目的很简单，就是为了方便其他31个GC线程打理当前的 托管堆，不过这老哥机器真🐂👃，32core，也不知道哪家医院这么给力，补充一下，用 !cpuid 验证。


0:000> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,62,4  <unavailable>   2600
 1  6,62,4  <unavailable>   2600
 2  6,62,4  <unavailable>   2600
 3  6,62,4  <unavailable>   2600
 xxx
31  6,62,4  <unavailable>   2600

既然预判到了是 GC 触发，下一步就可以把所有线程的托管和非托管堆栈全部调出来。

3. 查看各个线程栈

要想查看各个线程的托管和非托管栈很简单, 使用 !eestack 即可，然后可以检索关键词 WaitUntilGCComplete 来判断有多少线程在等待GC处理完毕。

记一次 .NET 某医院HIS系统 CPU爆高分析-LMLPHP

从图中可以看出，当前有 40 个线程被阻塞了，真好，问题越来越清晰了，接下来再分析到底是哪个线程做了什么不该做的事，导致 GC 触发，同样也可以搜 try_allocate_more_space 来判断哪些线程正在分配空间。

记一次 .NET 某医院HIS系统 CPU爆高分析-LMLPHP

我去，可以很明显的看出当前 170 和 187 号线程正在分配大对象 gc_heap::allocate_large_object 触发了 GC，本身大对象堆是一个令人生畏的东西，对它的回收清扫都是非常耗CPU资源的，这也和朋友说到的 1分钟左右CPU就下降了 的情况比较吻合。

4. 寻找祸首

现在关注点就在这两个线程上了，我看了下这两个线程栈都是同一处方法，所以这里就挑一个 187 线程来分析吧，可以用 !clrstack 看下它的托管栈。


0:187> !clrstack
OS Thread Id: 0x1ef0 (187)
        Child SP               IP Call Site
00000054ce631e30 00007ffc4021bde2 System.String.FillStringChecked(System.String, Int32, System.String)
00000054ce631e70 00007ffc402222a8 System.String.ConcatArray(System.String[], Int32)
00000054ce631ed0 00007ffc40223528 System.String.Concat(System.String[])
00000054ce631f40 00007ffbe6dbdafb BLL.xxx.xxx.GetRowString(System.String, Boolean, Boolean, System.String, System.String, System.String, System.String, System.String, System.String, Int32, System.String, System.String, System.String, System.String, System.String, System.String, Int32, Int32, System.String, System.Nullable`1, System.Nullable`1, System.String, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.String, System.String, System.String, System.String, System.String ByRef)
00000054ce65cf40 00007ffbe6ab3187 BLL.xxx.xxx.ExpZB(System.String, Boolean, Boolean, System.String, System.String, System.String, System.String, Int32, System.String, System.String, System.String, Int32, System.String, System.String, System.String, System.String, System.String, System.String, Int32, Int32, System.String, System.Nullable`1, System.Nullable`1, System.String, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.String, System.String, System.String, System.String)

从堆栈上看，貌似是使用了 System.String.Concat 拼接 string 所致，好家伙，string 拼接这么多年不知道被人抨击了多少次，还是有很多的人踩坑😓😓😓，为了进一步验证，可以使用 !clrstack -p + !da -details xxx 看看这个 System.String[] 到底是什么，简化如下：


0:187> !clrstack -p
OS Thread Id: 0x1ef0 (187)
00000054ce631e70 00007ffc402222a8 System.String.ConcatArray(System.String[], Int32)
    PARAMETERS:
        values (<CLR reg>) = 0x000001ea69e8d2f8
        totalLength = <no data>
0:187> !da -details 0x000001ea69e8d2f8
Name:        System.String[]
Size:        128(0x80) bytes
Array:       Rank 1, Number of elements 13, Type CLASS
Element Methodtable: 00007ffc403d6948
[0] 000001f2391a83f0
    Name:        System.String
    MethodTable: 00007ffc403d6948
    EEClass:     00007ffc3fcd50e0
    Size:        445950(0x6cdfe) bytes
    File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
    String:      xxxxx

从输出信息中可以看到，String[] 里面有 13 个元素，其中最大的一个 string 是 445950 bytes = 445k，大于大对象的85k界定，所以这里的 Concat 就是症结所在，同样 170 线程也是如此，接下来我还得要解决的一个问题是：为什么会有如此大的字符串产生，代码里面到底做了什么？？？要想寻找答案，还得从dump中导出源码一探究竟。

5. 查看问题代码

要想分析问题代码，可以通过 !ip2md + !savemodule 导出 BLL.xxx.xxx.GetRowString 方法。


0:187> !ip2md 00007ffbe6dbdafb
MethodDesc:   00007ffbe5342118
Method Name:  BLL.xxx.xxx.GetRowString(System.String, Boolean, Boolean, System.String, System.String, System.String, System.String, System.String, System.String, Int32, System.String, System.String, System.String, System.String, System.String, System.String, Int32, Int32, System.String, System.Nullable`1<Int32>, System.Nullable`1<Int32>, System.String, System.Nullable`1<Single>, System.Nullable`1<Single>, System.Nullable`1<Single>, System.Nullable`1<Single>, System.String, System.String, System.String, System.String, System.String ByRef)
Class:        00007ffbe52fe328
MethodTable:  00007ffbe53421d8
mdToken:      0000000006000096
Module:       00007ffbe471a890
0:187> !savemodule  00007ffbe471a890 E:\dumps\RowString.dll
3 sections in file
section 0 - VA=2000, VASize=f7fcc, FileAddr=200, FileSize=f8000
section 1 - VA=fa000, VASize=3bc, FileAddr=f8200, FileSize=400
section 2 - VA=fc000, VASize=c, FileAddr=f8600, FileSize=200

然后祭出 ILSpy 反编译这段代码。

记一次 .NET 某医院HIS系统 CPU爆高分析-LMLPHP

好家伙，这写法真🐂👃，无数的字符串拼接，我都感觉 gen 和 LOH 都来不及分配内存段了😥😥😥，真的是害死 GC 了。。。

三：总结

其实这是一个教科书式的问题，也有教科书式的解决方法，而且我看了下这个方法有 600 多行的代码，基本上都是做string拼接的事，最后说一下解决方案。

重构该方法，尽量用 StringBuilder 替代 String，将因这种 GC 触发的次数降到最低。

最后的小彩蛋，貌似这个分析结果和朋友的深度怀疑不约而同。。。

记一次 .NET 某医院HIS系统 CPU爆高分析-LMLPHP

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

一线码农