[[381344]]

 一：背景

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   nc">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.nc">Convert.ToDateTime(System.String, System.IFormatProvider) 
1ad8d9f8 724369b1 System.String.System.IConvertible.ToDateTime(System.IFormatProvider) 
1ad8da00 7243c8a2 System.nc">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) nc">left join xxx as cr WITH(NOLOCK) on v.xxx=cr.xxx nc">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 運行，據運維說，目前服務器存在不能建過多的應用程序域，導致多個網站公用一個程序域，表面上是運維弄錯應用程序域，根子上還是沒有徹底改造的決心!

本文轉載自微信公眾號「 一線碼農聊技術」，可以通過以下二維碼關注。轉載本文請聯系 一線碼農聊技術公眾號。