技術文章 » 記一次某製造業ERP系統 CPU打爆事故分析

記一次某製造業ERP系統 CPU打爆事故分析

2022-10-11 09:00:11

一：背景

1.講故事

前些天有位朋友微信找到我，說他的程式出現了CPU階段性爆高，過了一會就下去了，諮詢下這個爆高階段程式內部到底發生了什麼？ 畫個圖大概是下面這樣，你懂的。

按經驗來說，這種情況一般是程式在做 CPU 密集型運算，所以讓朋友在 CPU 高的時候間隔 5~10s 抓兩個 dump 下來，然後就是用 WinDbg 分析。

二：WinDbg 分析

1. CPU 真的爆高嗎

耳聽為虛，眼見為實，我們用 !tp 觀察下當前的CPU情況。


0:000> !tp
CPU utilization: 100%
Worker Thread: Total: 16 Running: 2 Idle: 14 MaxLimit: 32767 MinLimit: 2
Work Request in Queue: 0
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 4 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 2

果不其然，CPU直接打滿，接下來就是看看當前有幾個CPU邏輯核，這麼不夠扛。。。


0:000> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,106,6  <unavailable>   2700
 1  6,106,6  <unavailable>   2700

我去，一個生產環境居然只有兩個核。。。果然這大環境下公司活著都不夠滋潤。

2. 到底是誰引發的

既然是階段性爆高，最簡單粗暴的就是看下各個執行緒棧，使用 ~*e !clrstack 命令即可，因為只有兩核，所以理論上兩個執行緒就可以把 CPU 幹趴下，掃了一下執行緒棧，果然有對號入座的，輸出資訊如下：


0:000> ~*e !clrstack 
OS Thread Id: 0x146c (42)
        Child SP               IP Call Site
00000089abcfca18 00007ffc4baffdb4 [InlinedCallFrame: 00000089abcfca18] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfca18 00007ffbdd4a7a48 [InlinedCallFrame: 00000089abcfca18] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfc9f0 00007ffbdd4a7a48 DomainNeutralILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef)
00000089abcfcaa0 00007ffbdd52ad0a System.Drawing.SafeNativeMethods+Gdip.GdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089abcfcae0 00007ffbdd52ac3f System.Drawing.Image.Dispose(Boolean)
00000089abcfcb30 00007ffbdd556b5a System.Drawing.Image.Dispose()
00000089abcfcb60 00007ffbe39397c7 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcc00 00007ffbe3939654 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcd30 00007ffbe39382e1 NPOI.SS.Util.SheetUtil.GetColumnWidth(NPOI.SS.UserModel.ISheet, Int32, Boolean)
00000089abcfcdc0 00007ffbe39380bc NPOI.XSSF.UserModel.XSSFSheet.AutoSizeColumn(Int32, Boolean)
...

OS Thread Id: 0x1c8c (46)
        Child SP               IP Call Site
00000089ad43dba8 00007ffc4baffdb4 [InlinedCallFrame: 00000089ad43dba8] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43dba8 00007ffbdd4a7a48 [InlinedCallFrame: 00000089ad43dba8] System.Drawing.SafeNativeMethods+Gdip.IntGdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43db80 00007ffbdd4a7a48 DomainNeutralILStubClass.IL_STUB_PInvoke(System.Runtime.InteropServices.HandleRef)
00000089ad43dc30 00007ffbdd52ad0a System.Drawing.SafeNativeMethods+Gdip.GdipDisposeImage(System.Runtime.InteropServices.HandleRef)
00000089ad43dc70 00007ffbdd52ac3f System.Drawing.Image.Dispose(Boolean)
00000089ad43dcc0 00007ffbdd556b5a System.Drawing.Image.Dispose()
00000089ad43dcf0 00007ffbe39397c7 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089ad43dd90 00007ffbe3939654 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089ad43dec0 00007ffbe39382e1 NPOI.SS.Util.SheetUtil.GetColumnWidth(NPOI.SS.UserModel.ISheet, Int32, Boolean)
00000089ad43df50 00007ffbe39380bc NPOI.XSSF.UserModel.XSSFSheet.AutoSizeColumn(Int32, Boolean)
...
00000089ad43e460 00007ffbe115b193 System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(System.Web.Mvc.ControllerContext, System.Web.Mvc.ActionDescriptor, System.Collections.Generic.IDictionary`2<System.String,System.Object>)
...
00000089abcfd310 00007ffbe115b147 System.Web.Mvc.Async.AsyncControllerActionInvoker+c.b__9_0(System.IAsyncResult, ActionInvocation)
...

有些朋友要問了，你是怎麼確定就是這兩個執行緒呢？ 其實有兩個方法可以驗證。

  1. 使用 !whttp 看http請求

既然是 web 請求，自然就可以拿到裡面的 HttpContext，這裡面記錄著當前請求的執行時間，這個資訊非常重要，截圖如下：

從圖中可以看到，有兩個 xxxx/Export 請求執行時間非常高，一個是 4min30s ，一個是 50s ，剛好落在了 42 和 46 號執行緒上。

  1. 藉助第二個 dump 檔案

這就是為什麼要抓二個dump的原因了，因為另一個dump會給我們相當有價值的對比資訊，同樣使用 !whttp 驗證。

接下來我們就要調研為什麼這兩個執行緒會執行這麼久？

3. 為什麼會執行這麼久

既然是 Export 匯出檔案，第一時間就應該想到是不是和資料量有關？通過執行緒棧上的方法，發現是一個List 集合，接下來用 !dso 命令找出來看看。


0:042> !dso
OS Thread Id: 0x146c (42)
RSP/REG          Object           Name
00000089ABCFCAC8 0000020683b7c128 System.Drawing.Bitmap
00000089ABCFCAF8 0000020683b7c158 System.Drawing.Graphics
00000089ABCFCB10 0000020683b7c128 System.Drawing.Bitmap
00000089ABCFCB30 0000020683b7c128 System.Drawing.Bitmap
00000089ABCFCB40 0000020683b7c4d0 NPOI.XSSF.UserModel.XSSFCellStyle
00000089ABCFCB50 0000020683b7c198 NPOI.XSSF.UserModel.XSSFRichTextString
00000089ABCFCB68 0000020683b7c198 NPOI.XSSF.UserModel.XSSFRichTextString
00000089ABCFCBC0 0000020683b7c198 NPOI.XSSF.UserModel.XSSFRichTextString
00000089ABCFCBC8 0000020683b7c2e8 System.String[]
00000089ABCFCBD0 0000020683b7c360 System.Drawing.Font
00000089ABCFCDE8 0000020666501240 System.Collections.Generic.List`1[[System.Collections.Generic.List`1[[System.Object, mscorlib]], mscorlib]]
...

0:042> !do 0000020666501240
Name:        System.Collections.Generic.List`1[[System.Collections.Generic.List`1[[System.Object, mscorlib]], mscorlib]]
MethodTable: 00007ffbde342440
EEClass:     00007ffc36fc2af8
Size:        40(0x28) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ffc36e4e250  40018a0        8     System.__Canon[]  0 instance 00000207658592d8 _items
00007ffc36e385a0  40018a1       18         System.Int32  1 instance            44906 _size
00007ffc36e385a0  40018a2       1c         System.Int32  1 instance            44906 _version
00007ffc36e35dd8  40018a3       10        System.Object  0 instance 0000000000000000 _syncRoot
00007ffc36e4e250  40018a4        0     System.__Canon[]  0   shared           static _emptyArray
                                 >> Domain:Value dynamic statics NYI 0000020563eec3c0:NotInit dynamic statics NYI 0000020795f5b9a0:NotInit  <<

可以清楚的看到，這個list高達 4.5w，這個量級說多也不多，說少也不少，言外之意就是程式碼寫的也不好不到哪裡去。

4. 使用者程式碼要承擔責任嗎

要判斷使用者程式碼是不是很爛，除了白盒看程式碼，也可以黑盒觀察這幾個執行緒棧，可以發現兩個dump 顯示的棧資訊都和 AutoSizeColumn 方法有關。


00000089abcfcae0 00007ffbdd52ac3f System.Drawing.Image.Dispose(Boolean)
00000089abcfcb30 00007ffbdd556b5a System.Drawing.Image.Dispose()
00000089abcfcb60 00007ffbe39397c7 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcc00 00007ffbe3939654 NPOI.SS.Util.SheetUtil.GetCellWidth(NPOI.SS.UserModel.ICell, Int32, NPOI.SS.UserModel.DataFormatter, Boolean)
00000089abcfcd30 00007ffbe39382e1 NPOI.SS.Util.SheetUtil.GetColumnWidth(NPOI.SS.UserModel.ISheet, Int32, Boolean)
00000089abcfcdc0 00007ffbe39380bc NPOI.XSSF.UserModel.XSSFSheet.AutoSizeColumn(Int32, Boolean)

從名字看是 NOPI 提供的自動調整列寬 的方法，那是不是這個方法的單次效能很慢呢？要尋找答案，只能求助百度啦。。。

  • 圖一

  • 圖二

到這裡我們基本就搞清楚了，導致 reqeust 高達 5min + 的誘因大概有三個。

  1. 資料量大

  2. AutoSizeColumn 速度慢

  3. 程式碼上的其他因素

跟朋友溝通後，朋友說這塊請求中的 AutoSizeColumn 方法忘了改掉。

三：總結

這個 Dump 分析起來其實非常簡單，思路也比較明朗，重點還是提醒一下大家慎用 NPOI 的 AutoSizeColumn 方法，弄不好就得出個生產事故！

圖片名稱