一：背景
1. 前言
大概有2個月沒寫部落格了，不是不想寫哈?，關注公號的朋友應該知道我這兩個月一直都在翻譯文章，前前後後大概100篇左右吧，前幾天看公號的 常讀使用者 降了好幾十，心疼哈，還得回過神來繼續寫！
2. 講故事
上週給 武漢同濟 做專案升級，本以為一切順利，結果捅婁子了，第二天上午高峰期運維說生產上兩臺 應用伺服器 cpu 被打滿，影響到所有客戶使用，造成了大面積癱瘓，真尬尷，得先讓運維抓一個 dump 下來再重啟網站，還好，老闆人可以，沒有問責 ?。
二：CPU 爆高問題分析
1. 找思路
分析 dump，沒什麼比 windbg 更專業了，不過分析 dump 我還是比較拿手的，那怎麼分析呢？ 最簡單粗暴的做法就是看每一個執行緒當時都在做什麼，進而推測一下就 八九不離十 了。
2. 檢視所有執行緒棧
首先用 !t 和 !tp 看一下當前程式的 執行緒 和 執行緒池 的整體概況。
0:000> !t
ThreadCount: 60
UnstartedThread: 0
BackgroundThread: 38
PendingThread: 0
DeadThread: 22
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
11 1 2c24 02487038 28220 Preemptive 00000000:00000000 010df4f8 0 Ukn
28 2 2ca0 024bad90 2b220 Preemptive 00000000:00000000 010df4f8 0 MTA (Finalizer)
30 3 2d04 024f1450 102a220 Preemptive 00000000:00000000 010df4f8 0 MTA (Threadpool Worker)
31 4 2054 024fb188 21220 Preemptive 00000000:00000000 010df4f8 0 Ukn
32 6 1128 02574400 1020220 Preemptive 00000000:00000000 010df4f8 0 Ukn (Threadpool Worker)
2 5 27ac 02520da8 20220 Preemptive 00000000:00000000 010df4f8 0 Ukn
35 17 2c44 1cc362c8 202b220 Preemptive 00000000:00000000 024fa838 1 MTA
36 20 1740 1cccc748 21220 Preemptive 00000000:00000000 010df4f8 0 Ukn
37 21 16c4 1cc08240 21220 Preemptive 00000000:00000000 010df4f8 0 Ukn
38 22 16a8 1ccd28b8 21220 Preemptive 00000000:00000000 010df4f8 0 Ukn
....
0:000> !tp
CPU utilization: 97%
Worker Thread: Total: 21 Running: 21 Idle: 0 MaxLimit: 8191 MinLimit: 8
Work Request in Queue: 23
Unknown Function: 6d92a17f Context: 0109b5f0
Unknown Function: 6d92a17f Context: 0107ed90
Unknown Function: 6d92a17f Context: 0104e750
Unknown Function: 6d92a17f Context: 010a0200
AsyncTimerCallbackCompletion TimerInfo@207f8008
AsyncTimerCallbackCompletion TimerInfo@0251b418
Unknown Function: 6d92a17f Context: 01096c78
Unknown Function: 6d92a17f Context: 01081398
AsyncTimerCallbackCompletion TimerInfo@024d0120
Unknown Function: 6d92a17f Context: 010a9a20
Unknown Function: 6d92a17f Context: 01057950
Unknown Function: 6d92a17f Context: 0104c2d0
Unknown Function: 6d92a17f Context: 010943d8
Unknown Function: 6d92a17f Context: 0107a180
Unknown Function: 6d92a17f Context: 010a7418
Unknown Function: 6d92a17f Context: 010839a0
Unknown Function: 6d92a17f Context: 010678d0
Unknown Function: 6d92a17f Context: 010a2808
Unknown Function: 6d92a17f Context: 0105c250
Unknown Function: 6d92a17f Context: 0108abb8
Unknown Function: 6d92a17f Context: 0108f7c8
Unknown Function: 6d92a17f Context: 0108d1c0
Unknown Function: 6d92a17f Context: 20896498
--------------------------------------
Number of Timers: 0
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 16 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 8
從上面的輸出大概可以看到如下幾點資訊：
-
當前程式有 60 個執行緒。
-
當前 CPU 利用率為 97%，爆高無疑。
-
執行緒池中有21個執行緒全部打滿，還有23個任務在
任務佇列中排隊等待處理。
總的來看，系統已經高負荷，不堪重負了，接下來的一個疑問就來了，所有的執行緒都被打滿而且執行緒池中還有大量等待處理的任務在排隊，現有的執行緒都在幹嘛呢？難道不處理嗎？
2. 檢視所有執行緒的託管執行緒棧
既然現存的有 60 個執行緒，那我就使用 ~ *e !clrstack 命令看看所有的執行緒都在幹嘛？
0:000> ~ *e !clrstack
OS Thread Id: 0x8d8 (44)
Child SP IP Call Site
1ad8d750 7759f901 [InlinedCallFrame: 1ad8d750]
1ad8d74c 71e1a9ea DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, IntPtr, System.String, System.String, Int32, Int32, System.String, Int32, Int32, Int32)
1ad8d750 71d52f0b [InlinedCallFrame: 1ad8d750] System.Globalization.CompareInfo.InternalCompareString(IntPtr, IntPtr, System.String, System.String, Int32, Int32, System.String, Int32, Int32, Int32)
1ad8d7b4 71d52f0b System.Globalization.CompareInfo.Compare(System.String, Int32, Int32, System.String, Int32, Int32, System.Globalization.CompareOptions)
1ad8d7e0 71e16ab9 System.String.Compare(System.String, Int32, System.String, Int32, Int32, System.Globalization.CultureInfo, System.Globalization.CompareOptions)
1ad8d810 71d51c8e System.Globalization.DateTimeFormatInfo.Tokenize(System.TokenType, System.TokenType ByRef, Int32 ByRef, System.__DTString ByRef)
1ad8d86c 71d51a92 System.__DTString.GetSeparatorToken(System.Globalization.DateTimeFormatInfo, Int32 ByRef, Char ByRef)
1ad8d88c 71d513c4 System.DateTimeParse.Lex(DS, System.__DTString ByRef, System.DateTimeToken ByRef, System.DateTimeRawInfo ByRef, System.DateTimeResult ByRef, System.Globalization.DateTimeFormatInfo ByRef, System.Globalization.DateTimeStyles)
1ad8d8dc 71d50b59 System.DateTimeParse.TryParse(System.String, System.Globalization.DateTimeFormatInfo, System.Globalization.DateTimeStyles, System.DateTimeResult ByRef)
1ad8d974 71dfce8b System.DateTimeParse.Parse(System.String, System.Globalization.DateTimeFormatInfo, System.Globalization.DateTimeStyles)
1ad8d9d8 7243c9bc System.Convert.ToDateTime(System.String, System.IFormatProvider)
1ad8d9f8 724369b1 System.String.System.IConvertible.ToDateTime(System.IFormatProvider)
1ad8da00 7243c8a2 System.Convert.ToDateTime(System.Object)
由於輸出的太多，這裡就簡略輸出了，不過我大體羅列了一下執行緒大概都在做什麼事情。
- 有 9 個執行緒正在執行
GetAllByCondition()方法
- 有 4 個執行緒正在執行
GetDayInvoice()方法
9 + 4 個執行緒都在搞這兩個方法，這就比較可疑了，不過從各個執行緒的棧頂上看並沒有類似 wait 關鍵詞，這就意味著大家不是在爭搶鎖啥的，那問題在哪裡呢？
繼續分析這兩個方法到底在資料庫中讀了什麼？ 通過 !dso 抓取 GetDayInvoice() 方法中的 sql，這裡我就模糊一下了哈，windbg命令大概如下：
0:000> ~45s
eax=1c06a5c8 ebx=00000000 ecx=59002090 edx=59002090 esi=000003d4 edi=00000000
eip=7759f901 esp=1d95cfa8 ebp=1d95d014 iopl=0 nv up ei pl zr na pe nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246
ntdll!NtWaitForSingleObject+0x15:
7759f901 83c404 add esp,4
0:045> !dso
OS Thread Id: 0x2a04 (45)
ESP/REG Object Name
1D95D6D0 aaaac9f4 System.String SELECT xxxxxx FROM xxxx as v WITH(NOLOCK) left join xxx as cr WITH(NOLOCK) on v.xxx=cr.xxx left join xxx as crr WITH(NOLOCK) on cr.PID=crr.ID WHERE xxx IN (SELECT DISTINCT xxx FROM xxxx WITH(NOLOCK) WHERE (SendTime>='2021-01-21 14:30:39' OR xxx>='2021-01-21 14:30:39' OR xxx>='2021-01-21 14:30:39') AND ((InvoiceType =1 and( IsRepeat=0 or IsRepeat is null )) OR xxx IN(16,15)) )
然後讓運維查了下，這條sql大概有 13w 的記錄，我第一反應就是查這麼大的資料是不是有毛病撒，問了下懂業務的老大，這一塊原來是做 初始化同步, 而且這塊好久都沒人動過，言外之意原來也是這麼查的，一點毛病也沒有呀，我去，說的也是哈，為啥以前沒問題呢？？？
3. 檢視託管堆
既然一條sql查了 13w 條資料，剛才是 4個執行緒在執行 GetDayInvoice()，也就意味著有 52w 條資料正在從 sqlserver 中獲取，接下來我的本能反應就是看看託管堆，使用 !dumpheap -stat 就可以了,如下程式碼所示：
0:045> !dumpheap -stat
The garbage collector data structures are not in a valid state for traversal.
It is either in the "plan phase," where objects are being moved around, or
we are at the initialization or shutdown of the gc heap. Commands related to
displaying, finding or traversing objects as well as gc heap segments may not
work properly. !dumpheap and !verifyheap may incorrectly complain of heap
consistency errors.
Object <exec cmd="!ListNearObj /d 02881000">02881000</exec> has an invalid method table.
我去，有點尷尬，居然報錯了，先擦擦頭上的汗，這句話： The garbage collector data structures are not in a valid state for traversal 引起了我的警覺，當前託管堆是無效狀態，gc被觸發了。。。當前還是 plan phase 狀態，是不是 gc 導致了 cpu 爆高呢？
4. 零碎資訊整合
通過上面這些零碎的資訊，不知道大家可整明白了，讓我來說的話，簡而言之： GetDayInvoice() 讀了大量資料，導致gc頻繁回收，進而導致 cpu 爆高，這裡有幾個概念需要大家瞭解下：
-
這個程式是 32bit，意味著最大隻能吃 4G 記憶體。
-
32bit 的臨時代（ 0+1 代） 大概 幾十M 的空間。
-
IIS 是
伺服器模式的GC，意味著當前的託管執行緒會臨時充當 GC 回收執行緒。
尤其是上面第三個概念，既然當前gc被觸發了，也就意味著託管執行緒被臨時給 GC 徵用了，那我可以看下是否真的是這樣，可以用 ~ *e !dumpstack 檢視所有執行緒的託管和非託管的所有棧資訊，如下圖所示：
可以清晰的看到，呼叫 GetDayInvoice() 的執行緒在 CLR 層面觸發了 gc，而此時 gc 想呼叫 try_allocate_more_space 來給自己分配更多的空間，而且 wait_for_gc_done 也表示它在等待其他gc執行緒處理完成，所以就卡死在這裡了。
如果不信的話，還可以繼續觀察其他執行緒的非託管堆疊，如下圖所示：
從 clr!SVR::GCHeap::WaitUntilGCComplete+0x35, calling clr!CLREventBase::WaitEx 可以看出，都是在等待 GC 完成，導致 CPU 爆高。
5. 找到問題根源
彙總一下就是：這次 cpu 爆高是因為 32bit 程式只能吃 4G 記憶體，而程式需要同步大量的資料，導致記憶體被打滿，gc無法分配更多的記憶體讓程式使用，gc的機制讓 cpu 打的滿滿的，知道問題之後，解決辦法很簡單，將 iis 的 應用程式域 的配置 啟用32bit應用程式 改成 False 即可，這樣程式就可以以 64bit 方式執行，如下圖所示：
三：總結
很顯然這次事件是因為管理混亂造成的，因為歷史遺留問題，有些網站必須用 32 bit 執行，有些必須用 64 bit 執行，據運維說，目前伺服器存在不能建過多的應用程式域，導致多個網站公用一個程式域，表面上是運維弄錯應用程式域，根子上還是沒有徹底改造的決心！
更多高質量乾貨：參見我的 GitHub: dotnetfly
