[[381344]]

 一：背景

1. 前言

大概有2個(gè)月沒寫博客了，不是不想寫哈??，關(guān)注公號(hào)的朋友應(yīng)該知道我這兩個(gè)月一直都在翻譯文章，前前后后大概100篇左右吧，前幾天看公號(hào)的 常讀用戶 降了好幾十，心疼哈，還得回過神來繼續(xù)寫!

2. 講故事

上周給 武漢同濟(jì) 做項(xiàng)目升級(jí)，本以為一切順利，結(jié)果捅婁子了，第二天上午高峰期運(yùn)維說生產(chǎn)上兩臺(tái) 應(yīng)用服務(wù)器 cpu 被打滿，影響到所有客戶使用，造成了大面積癱瘓，真尬尷，得先讓運(yùn)維抓一個(gè) dump 下來再重啟網(wǎng)站，還好，老板人可以，沒有問責(zé) ??。

二：CPU 爆高問題分析

1. 找思路

分析 dump，沒什么比 windbg 更專業(yè)了，不過分析 dump 我還是比較拿手的，那怎么分析呢?最簡(jiǎn)單粗暴的做法就是看每一個(gè)線程當(dāng)時(shí)都在做什么，進(jìn)而推測(cè)一下就 八九不離十 了。

2. 查看所有線程棧

首先用 !t 和 !tp 看一下當(dāng)前程序的 線程 和 線程池 的整體概況。

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 

從上面的輸出大概可以看到如下幾點(diǎn)信息：

• 當(dāng)前程序有 60 個(gè)線程。
• 當(dāng)前 CPU 利用率為 97%，爆高無疑。
• 線程池中有21個(gè)線程全部打滿，還有23個(gè)任務(wù)在 任務(wù)隊(duì)列 中排隊(duì)等待處理。

總的來看，系統(tǒng)已經(jīng)高負(fù)荷，不堪重負(fù)了，接下來的一個(gè)疑問就來了，所有的線程都被打滿而且線程池中還有大量等待處理的任務(wù)在排隊(duì)，現(xiàn)有的線程都在干嘛呢?難道不處理嗎?

2. 查看所有線程的托管線程棧

既然現(xiàn)存的有 60 個(gè)線程，那我就使用 ~ *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) 

由于輸出的太多，這里就簡(jiǎn)略輸出了，不過我大體羅列了一下線程大概都在做什么事情。

• 有 9 個(gè)線程正在執(zhí)行 GetAllByCondition() 方法



• 有 4 個(gè)線程正在執(zhí)行 GetDayInvoice() 方法

9 + 4 個(gè)線程都在搞這兩個(gè)方法，這就比較可疑了，不過從各個(gè)線程的棧頂上看并沒有類似wait 關(guān)鍵詞，這就意味著大家不是在爭(zhēng)搶鎖啥的，那問題在哪里呢?

繼續(xù)分析這兩個(gè)方法到底在數(shù)據(jù)庫(kù)中讀了什么?通過 !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))  )   

然后讓運(yùn)維查了下，這條sql大概有 13w 的記錄，我第一反應(yīng)就是查這么大的數(shù)據(jù)是不是有毛病撒，問了下懂業(yè)務(wù)的老大，這一塊原來是做 初始化同步, 而且這塊好久都沒人動(dòng)過，言外之意原來也是這么查的，一點(diǎn)毛病也沒有呀，我去，說的也是哈，為啥以前沒問題呢???

3. 查看托管堆

既然一條sql查了 13w 條數(shù)據(jù)，剛才是 4個(gè)線程在執(zhí)行 GetDayInvoice()，也就意味著有 52w 條數(shù)據(jù)正在從 sqlserver 中獲取，接下來我的本能反應(yīng)就是看看托管堆，使用 !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. 

我去，有點(diǎn)尷尬，居然報(bào)錯(cuò)了，先擦擦頭上的汗，這句話：The garbage collector data structures are not in a valid state for traversal 引起了我的警覺，當(dāng)前托管堆是無效狀態(tài)，gc被觸發(fā)了。。。當(dāng)前還是 plan phase 狀態(tài)，是不是 gc 導(dǎo)致了 cpu 爆高呢?

4. 零碎信息整合

通過上面這些零碎的信息，不知道大家可整明白了，讓我來說的話，簡(jiǎn)而言之：GetDayInvoice() 讀了大量數(shù)據(jù)，導(dǎo)致gc頻繁回收，進(jìn)而導(dǎo)致 cpu 爆高，這里有幾個(gè)概念需要大家了解下：

• 這個(gè)程序是 32bit，意味著最大只能吃 4G 內(nèi)存。
• 32bit 的臨時(shí)代( 0+1 代) 大概 幾十M 的空間。
• IIS 是 服務(wù)器模式 的GC，意味著當(dāng)前的托管線程會(huì)臨時(shí)充當(dāng) GC 回收線程。

尤其是上面第三個(gè)概念，既然當(dāng)前gc被觸發(fā)了，也就意味著托管線程被臨時(shí)給 GC 征用了，那我可以看下是否真的是這樣，可以用 ~ *e !dumpstack 查看所有線程的托管和非托管的所有棧信息，如下圖所示：

可以清晰的看到，調(diào)用 GetDayInvoice() 的線程在 CLR 層面觸發(fā)了 gc，而此時(shí) gc 想調(diào)用 try_allocate_more_space 來給自己分配更多的空間，而且 wait_for_gc_done 也表示它在等待其他gc線程處理完成，所以就卡死在這里了。

如果不信的話，還可以繼續(xù)觀察其他線程的非托管堆棧，如下圖所示：

從 clr!SVR::GCHeap::WaitUntilGCComplete+0x35, calling clr!CLREventBase::WaitEx 可以看出，都是在等待 GC 完成，導(dǎo)致 CPU 爆高。

5. 找到問題根源

匯總一下就是：這次 cpu 爆高是因?yàn)?32bit 程序只能吃 4G 內(nèi)存，而程序需要同步大量的數(shù)據(jù)，導(dǎo)致內(nèi)存被打滿，gc無法分配更多的內(nèi)存讓程序使用，gc的機(jī)制讓 cpu 打的滿滿的，知道問題之后，解決辦法很簡(jiǎn)單，將 iis 的 應(yīng)用程序域 的配置 啟用32bit應(yīng)用程序 改成 False 即可，這樣程序就可以以 64bit 方式運(yùn)行，如下圖所示：

三：總結(jié)很顯然這次事件是因?yàn)楣芾砘靵y造成的，因?yàn)闅v史遺留問題，有些網(wǎng)站必須用 32 bit 運(yùn)行，有些必須用 64 bit 運(yùn)行，據(jù)運(yùn)維說，目前服務(wù)器存在不能建過多的應(yīng)用程序域，導(dǎo)致多個(gè)網(wǎng)站公用一個(gè)程序域，表面上是運(yùn)維弄錯(cuò)應(yīng)用程序域，根子上還是沒有徹底改造的決心!

本文轉(zhuǎn)載自微信公眾號(hào)「 一線碼農(nóng)聊技術(shù)」，可以通過以下二維碼關(guān)注。轉(zhuǎn)載本文請(qǐng)聯(lián)系 一線碼農(nóng)聊技術(shù)公眾號(hào)。