再記一次 應用服務器 CPU 暴高事故分析

一：背景

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

標籤：.NET技术

上一篇：聊聊如何使用單例模式

下一篇：搭建ASP.NET WEB API框架(1) 從零開始