关于.net:记一次-NET-某医院HIS系统-CPU爆高分析

一：背景

1. 讲故事

前几天有位敌人加 wx 埋怨他的程序在高峰期总是莫名其妙的cpu爆高，求助如何剖析？

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

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

GC 触发
大量 lock 锁

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

二： windbg 剖析

1. 查看同步块表

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

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

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

2. 查看线程

要想查看零碎中的 托管线程 ，能够应用 !t 命令, 线程比拟多，略微简化一下。

0:000> !tThreadCount:      135UnstartedThread:  0BackgroundThread: 132PendingThread:    0DeadThread:       1Hosted 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 -specialThreadCount:      135UnstartedThread:  0BackgroundThread: 132PendingThread:    0DeadThread:       1Hosted 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 type41 38d8 DbgHelper 42 1c88 GC 74 3ed0 Finalizer 75 402c ProfilingAPIAttach 76 4a70 Timer79 1468 GC SuspendEE

从最初一行输入中能够看到， 79就是GC线程，前面还有一个奇怪的 SuspendEE 标记，你又好奇了，这又啥意思？

SuspendEE = Suspend CLR Execution Engine (EE)

也就是说，79号线程把 CLR执行引擎 给解冻了，目标很简略，就是为了不便其余31个GC线程打理以后的 托管堆，不过这老哥机器真，32core，也不晓得哪家医院这么给力，补充一下，用 !cpuid 验证。

0:000> !cpuidCP  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 xxx31  6,62,4  <unavailable>   2600

既然预判到了是 GC 触发，下一步就能够把所有线程的托管和非托管堆栈全副调进去。

3. 查看各个线程栈

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

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

我去，能够很显著的看出以后 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 Site00000054ce631e30 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 -pOS Thread Id: 0x1ef0 (187)00000054ce631e70 00007ffc402222a8 System.String.ConcatArray(System.String[], Int32)    PARAMETERS:        values (<CLR reg>) = 0x000001ea69e8d2f8        totalLength = <no data>0:187> !da -details 0x000001ea69e8d2f8Name:        System.String[]Size:        128(0x80) bytesArray:       Rank 1, Number of elements 13, Type CLASSElement 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 00007ffbe6dbdafbMethodDesc:   00007ffbe5342118Method 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:        00007ffbe52fe328MethodTable:  00007ffbe53421d8mdToken:      0000000006000096Module:       00007ffbe471a8900:187> !savemodule  00007ffbe471a890 E:\dumps\RowString.dll3 sections in filesection 0 - VA=2000, VASize=f7fcc, FileAddr=200, FileSize=f8000section 1 - VA=fa000, VASize=3bc, FileAddr=f8200, FileSize=400section 2 - VA=fc000, VASize=c, FileAddr=f8600, FileSize=200

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

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

三：总结

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

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

最初的小彩蛋，貌似这个剖析后果和敌人的深度狐疑不谋而合。。。

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