前些天有位朋友微信找到我,說他的程序出現(xiàn)了CPU階段性爆高,過了一會就下去了,咨詢下這個爆高階段程序內(nèi)部到底發(fā)生了什么? 畫個圖大概是下面這樣,你懂的。
成都創(chuàng)新互聯(lián)公司-專業(yè)網(wǎng)站定制、快速模板網(wǎng)站建設(shè)、高性價比仙居網(wǎng)站開發(fā)、企業(yè)建站全套包干低至880元,成熟完善的模板庫,直接使用。一站式仙居網(wǎng)站制作公司更省心,省錢,快速模板網(wǎng)站建設(shè)找我們,業(yè)務(wù)覆蓋仙居地區(qū)。費(fèi)用合理售后完善,十多年實體公司更值得信賴。
按經(jīng)驗來說,這種情況一般是程序在做 CPU 密集型運(yùn)算
,所以讓朋友在 CPU 高的時候間隔 5~10s
抓兩個 dump 下來,然后就是用 WinDbg 分析。
耳聽為虛,眼見為實,我們用 !tp
觀察下當(dāng)前的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直接打滿,接下來就是看看當(dāng)前有幾個CPU邏輯核,這么不夠扛。。。
0:000> !cpuid
CP F/M/S Manufacturer MHz
0 6,106,6 2700
1 6,106,6 2700
我去,一個生產(chǎn)環(huán)境居然只有兩個核。。。果然這大環(huán)境下公司活著都不夠滋潤。
既然是階段性爆高,最簡單粗暴的就是看下各個線程棧,使用 ~*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)
...
00000089abcfd310 00007ffbe115b147 System.Web.Mvc.Async.AsyncControllerActionInvoker+c.b__9_0(System.IAsyncResult, ActionInvocation)
...
有些朋友要問了,你是怎么確定就是這兩個線程呢? 其實有兩個方法可以驗證。
既然是 web 請求,自然就可以拿到里面的 HttpContext
,這里面記錄著當(dāng)前請求的運(yùn)行時間,這個信息非常重要,截圖如下:
從圖中可以看到,有兩個 xxxx/Export
請求運(yùn)行時間非常高,一個是 4min30s
,一個是 50s
,剛好落在了 42
和 46
號線程上。
這就是為什么要抓二個dump的原因了,因為另一個dump會給我們相當(dāng)有價值的對比信息,同樣使用 !whttp
驗證。
接下來我們就要調(diào)研為什么這兩個線程會運(yùn)行這么久?
既然是 Export 導(dǎo)出文件,第一時間就應(yīng)該想到是不是和數(shù)據(jù)量有關(guān)?通過線程棧上的方法,發(fā)現(xiàn)是一個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高達(dá) 4.5w
,這個量級說多也不多,說少也不少,言外之意就是代碼寫的也不好不到哪里去。
要判斷用戶代碼是不是很爛,除了白盒看代碼,也可以黑盒觀察這幾個線程棧,可以發(fā)現(xiàn)兩個dump 顯示的棧信息都和 AutoSizeColumn
方法有關(guān)。
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 提供的自動調(diào)整列寬
的方法,那是不是這個方法的單次性能很慢呢?要尋找答案,只能求助百度啦。。。
圖一
圖二
到這里我們基本就搞清楚了,導(dǎo)致 reqeust 高達(dá) 5min + 的誘因大概有三個。
數(shù)據(jù)量大
AutoSizeColumn 速度慢
代碼上的其他因素
跟朋友溝通后,朋友說這塊請求中的 AutoSizeColumn
方法忘了改掉。
這個 Dump 分析起來其實非常簡單,思路也比較明朗,重點(diǎn)還是提醒一下大家慎用 NPOI 的 AutoSizeColumn
方法,弄不好就得出個生產(chǎn)事故!