記一次 .NET 某醫院HIS系統 CPU爆高分析

一線碼農發表於2021-05-14

一：背景

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 反編譯這段程式碼。