一：背景
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?????MHz0??6,106,6??<unavailable>???27001??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)
...有些朋友要問了，你是怎么確定就是這兩個線程呢？其實有兩個方法可以驗證。
使用 !whttp 看http請求
既然是 web 請求，自然就可以拿到里面的 HttpContext，這里面記錄著當前請求的運行時間，這個信息非常重要，截圖如下：
從圖中可以看到，有兩個 xxxx/Export 請求運行時間非常高，一個是 4min30s ，一個是 50s ，剛好落在了 42 和 46 號線程上。
借助第二個 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 + 的誘因大概有三個。
數據量大
AutoSizeColumn 速度慢
代碼上的其他因素
跟朋友溝通后，朋友說這塊請求中的 AutoSizeColumn 方法忘了改掉。
三：總結
這個 Dump 分析起來其實非常簡單，思路也比較明朗，重點還是提醒一下大家慎用 NPOI 的 AutoSizeColumn 方法，弄不好就得出個生產事故！
