一：背景

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:???noLock??ID?OSID?ThreadOBJ????State?GC?Mode?????GC?Alloc?Context??Domain???Count?Apt?Exception11????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:?23Unknown?Function:?6d92a17f??Context:?0109b5f0Unknown?Function:?6d92a17f??Context:?0107ed90Unknown?Function:?6d92a17f??Context:?0104e750Unknown?Function:?6d92a17f??Context:?010a0200AsyncTimerCallbackCompletion?TimerInfo@207f8008AsyncTimerCallbackCompletion?TimerInfo@0251b418Unknown?Function:?6d92a17f??Context:?01096c78Unknown?Function:?6d92a17f??Context:?01081398AsyncTimerCallbackCompletion?TimerInfo@024d0120Unknown?Function:?6d92a17f??Context:?010a9a20Unknown?Function:?6d92a17f??Context:?01057950Unknown?Function:?6d92a17f??Context:?0104c2d0Unknown?Function:?6d92a17f??Context:?010943d8Unknown?Function:?6d92a17f??Context:?0107a180Unknown?Function:?6d92a17f??Context:?010a7418Unknown?Function:?6d92a17f??Context:?010839a0Unknown?Function:?6d92a17f??Context:?010678d0Unknown?Function:?6d92a17f??Context:?010a2808Unknown?Function:?6d92a17f??Context:?0105c250Unknown?Function:?6d92a17f??Context:?0108abb8Unknown?Function:?6d92a17f??Context:?0108f7c8Unknown?Function:?6d92a17f??Context:?0108d1c0Unknown?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 運行，據運維說，目前服務器存在不能建過多的應用程序域，導致多個網站公用一個程序域，表面上是運維弄錯應用程序域，根子上還是沒有徹底改造的決心！

總結

以上是生活随笔為你收集整理的再记一次 应用服务器 CPU 暴高事故分析的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。