一:背景
1. 讲故事
前几天有位朋友加 wx 抱怨他的程序在高峰期总是莫名其妙的cpu爆高,求助如何分析?
和这位朋友沟通下来,据说这问题困扰了他们几年😂,还请了微软的工程师过来解决,无疾而终,应该还是没找对微软的大佬。。。
关于程序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
标记,你又好奇了,这又啥意思?
SuspendEE
=Suspend CLR Execution Engine (EE)
也就是说,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处理完毕。
从图中可以看出,当前有 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 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
反编译这段代码。
好家伙,这写法真🐂👃,无数的字符串拼接,我都感觉 gen
和 LOH
都来不及分配内存段了😥😥😥,真的是害死 GC 了。。。
三:总结
其实这是一个教科书式的问题,也有教科书式的解决方法,而且我看了下这个方法有 600 多行的代码,基本上都是做string拼接的事,最后说一下解决方案。
- 重构该方法,尽量用 StringBuilder 替代 String,将因这种 GC 触发的次数降到最低。
最后的小彩蛋,貌似这个分析结果和朋友的深度怀疑不约而同。。。
更多高质量干货:参见我的 GitHub: dotnetfly