一：背景
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
