記一次 .NET 某市附屬醫(yī)院 Web程序 偶發(fā)性CPU爆高分析

一：背景

1. 講故事

這個月初，一位朋友加微信求助他的程序出現(xiàn)了 CPU 偶發(fā)性爆高，希望能有償解決一下。

從描述看，這個問題應(yīng)該困擾了很久，還是醫(yī)院的朋友給力，開門就是 100塊 紅包 ??????，那既然是偶發(fā)性爆高，人工不行，還得用 procdump 自動抓，用 procdump -ma -s 5 -n 2 -c 70 w3wp 埋伏好，幾天后如愿生成了兩個dump，太妙了，接下來就用 windbg 分析吧。

二：Windbg 分析

1. 真的是cpu爆高嗎

一切只相信數(shù)據(jù)，這里用 !tp 看一下此時 machine 的cpu值。

0:062:x86>?!tp
CPU?utilization:?83%
Worker?Thread:?Total:?37?Running:?6?Idle:?31?MaxLimit:?8191?MinLimit:?4
Work?Request?in?Queue:?0
--------------------------------------
Number?of?Timers:?2
--------------------------------------
Completion?Port?Thread:Total:?1?Free:?1?MaxFree:?8?CurrentLimit:?1?MaxLimit:?1000?MinLimit:?4

從數(shù)據(jù)看，此時 CPU utilization: 83%, 沒毛病。

2. 查看線程耗時

既然是偶發(fā)性的bug，而且也說了可能是醫(yī)生操作了什么觸發(fā)了什么條件才導(dǎo)致的，剛好這里也有 2 個dump，那就比一下各個線程的耗時吧，這里只提取 top5 。

0:062:x86>?.time
Debug?session?time:?Thu?Dec?16?14:31:45.000?2021?(UTC?+?8:00)
System?Uptime:?not?available
Process?Uptime:?0?days?1:20:48.000
??Kernel?time:?0?days?0:08:43.000
??User?time:?0?days?1:08:19.000

0:062:x86>?!runaway
?User?Mode?Time
??Thread???????Time
???62:7188?????0?days?0:18:05.343
???44:6c90?????0?days?0:16:16.687
???39:86e8?????0?days?0:14:57.734
???32:1d8c?????0?days?0:01:02.546
???35:23a4?????0?days?0:00:58.250

0:062:x86>?.time
Debug?session?time:?Thu?Dec?16?14:32:00.000?2021?(UTC?+?8:00)
System?Uptime:?not?available
Process?Uptime:?0?days?1:21:03.000
??Kernel?time:?0?days?0:08:45.000
??User?time:?0?days?1:08:41.000

0:062:x86>?!runaway
?User?Mode?Time
??Thread???????Time
???62:7188?????0?days?0:18:11.875
???44:6c90?????0?days?0:16:23.156
???39:86e8?????0?days?0:15:04.156
???32:1d8c?????0?days?0:01:02.546
???35:23a4?????0?days?0:00:58.250

從信息看，間隔15s的dump，相對來說 62,44,39 這三個線程耗時最多，所以這三個線程值得繼續(xù)挖一挖。

3. 查看線程棧

接下來用 ~62s; !clrstack;~44s; !clrstack;~39s; !clrstack 切到這三個線程看下棧情況，如下圖所示：

從棧中看，并沒有用戶代碼，這就很尷尬了，我一度懷疑是不是 webform 的同步上下文導(dǎo)致的，但好歹我還是有一些經(jīng)驗，既然 !clrstack 看不到，那就用 !dumpstack 。

0:062:x86>?!dumpstack
OS?Thread?Id:?0x7188?(62)
TEB?information?is?not?available?so?a?stack?size?of?0xFFFF?is?assumed
Current?frame:?(MethodDesc?6b0e1b58?+0x1c?System.Collections.Generic.ObjectEqualityComparer`1[[System.__Canon,?mscorlib]].Equals(System.__Canon,?System.__Canon))
ChildEBP?RetAddr??Caller,?Callee
3867ebfc?6b440484?(MethodDesc?6b0db558?+0x54?System.Collections.Generic.List`1[[System.__Canon,?mscorlib]].Contains(System.__Canon))
3867ec18?24bbc3c5?(MethodDesc?25e2ba88?+0x845?xxx.bl_baseInfo.getBljl(System.String,?System.String)),?calling?2f23072e
3867ec84?6b466d0b?(MethodDesc?6b0dcb5c?+0x7b?System.String.TrimHelper(Int32)),?calling?(MethodDesc?6b0d1cf4?+0?System.Globalization.CharUnicodeInfo.IsWhiteSpace(Char))
3867ec98?24bbba00?(MethodDesc?2a6eca54?+0x1b8?xxx_blcx.Button1_Click(System.Object,?System.EventArgs)),?calling?(MethodDesc?25e2ba88?+0??xxx.getBljl(System.String,?System.String))
3867ecb8?05b5d487?05b5d487
3867ecec?6092da13?(MethodDesc?5fdff5c0?System.Web.UI.WebControls.Button.OnClick(System.EventArgs))
3867ed04?5ffdd1cd?(MethodDesc?5fdff5e8?+0xcd?System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String))
3867ed1c?5ffdd0fd?(MethodDesc?5fdff5e0?+0xd?System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String))
...

真是太奇怪了，用戶代碼 xxx.bl_baseInfo.getBljl 怎么跑到非托管棧 ? 這真是第一次遇到，從棧上看，程序在 xxx.bl_baseInfo.getBljl() 方法中遇到了問題，接下來用 !dso 把堆對象都導(dǎo)出來。

0:062:x86>?!dso
Error?requesting?heap?segment?b4fe0000
Failed?to?retrieve?segments?for?gc?heap
Unable?to?determine?bounds?of?gc?heap

我去，這個 dump 的棧被破壞了，可能是 cpu 爆高導(dǎo)致的，也有可能是抓的不好，這下太折磨了，得，只能用 kb 到非托管棧上找方法參數(shù)。

0:062:x86>?kb
?#?ChildEBP?RetAddr??????Args?to?Child??????????????
00?3867ebfc?6b440484?????cd0a25a8?124e2c7c?0efb330c?mscorlib_ni!System.Collections.Generic.ObjectEqualityComparer`1[System.__Canon].Equals(System.__Canon,?System.__Canon)$##6003913+0x1c
01?3867ec18?24bbc3c5?????cd0a25a8?132b35e4?132b35cc?mscorlib_ni!System.Collections.Generic.List`1[System.__Canon].Contains(System.__Canon)$##600398F+0x54
WARNING:?Frame?IP?not?in?any?known?module.?Following?frames?may?be?wrong.
02?3867ec98?24bbba00?????0e3aead8?8412256c?3867ecc0?0x24bbc3c5
03?3867ecb8?05b5d487?????0a3d6f00?3867f170?5381fbca?0x24bbba00
04?3867ecec?6092da13?????0a3d6e48?00000000?132a20c0?0x5b5d487
05?3867ed04?5ffdd1cd?????124ca1a8?80208dfc?80208dfc?System_Web_ni![COLD]?System.Web.UI.WebControls.Button.OnClick(System.EventArgs)$##60029E3+0xb
...

接下來我們 !do 一下 132b35cc 地址，看看是什么 list。

0:062:x86>?!do?132b35cc
Name:????????System.Collections.Generic.List`1[[xxx.Model.me_zyblbr,?xxx]]
MethodTable:?29f36c8c
EEClass:?????6b0aedc4
Size:????????24(0x18)?bytes
File:????????C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
??????MT????Field???Offset?????????????????Type?VT?????Attr????Value?Name
6b4aea10??4001871????????4?????System.__Canon[]??0?instance?8e8054e0?_items
6b513c04??4001872????????c?????????System.Int32??1?instance???233139?_size
6b513c04??4001873???????10?????????System.Int32??1?instance???233139?_version
6b512104??4001874????????8????????System.Object??0?instance?00000000?_syncRoot
6b4aea10??4001875????????4?????System.__Canon[]??0???static??

用輸出中可以看到，這個 list=23w 條記錄，它正在 list.Contains 處，有了這些信息，接下來就可以把源碼導(dǎo)出來，簡化后的代碼如下：

??public?IList?getBljl(string?as_search,?string?as_ztbz)
??{
???IList?list?=?new?List();
???using?(CDataBase?cDataBase?=?new?CDataBase("xxx"))
???{
????????????????var?text?=?"select?xxxx??from?xxx";
????OracleDataReader?oracleDataReader?=?cDataBase.SetReader(text);
????while?(oracleDataReader.Read())
????{
?????if?(!list.Contains(me_zyblbr))
?????{
??????list.Insert(0,?me_zyblbr);
?????}
????}
????oracleDataReader.Close();
????return?list;
???}
???return?list;
??}

眼尖的朋友肯定能注意到，在數(shù)據(jù)量大的情況下，這里的 list.Insert(0, me_zyblbr); 有大問題，畢竟 list.Insert 的復(fù)雜度是 O(N)，針對 23w 來說總的時間復(fù)雜度就是：

n(n-1)/2 = 23w(23w-1)/2 = 26,450,000,000 = 264億 。

然后就是 3個這樣的線程就一起把cpu給抬起來了。

4. 到底是什么sql語句導(dǎo)致

雖然問題根已找到，但朋友最關(guān)心的是這位醫(yī)生到底輸入了什么導(dǎo)致 sql 查詢了如此大的數(shù)據(jù), 不知道醫(yī)生要扣錢還是他們要向上面有個交代??????， 由于堆，棧都 被損壞了，找起來還是很麻煩的，我用了 sos 中的 !lno, !dumpheap 都是報錯,徹底趴窩了，最后想了下 sosex 中也有一個 !mdso 命令，終于一路坎坷的找到了重要的 OracleParameter 參數(shù)。

0:062:x86>?!mdso
Thread?62:
Location??????????Object????????????Type
------------------------------------------------------------
EDI:??????132b35cc??System.Collections.Generic.List`1[[xxx.me_zyblbr,?xxx]]
3867ec08??124e2c7c??System.Collections.Generic.ObjectEqualityComparer`1[[xxx.me_zyblbr,?xxx]]
3867ec44??132b3a5c??Oracle.DataAccess.Client.OracleParameter

0:062:x86>?!mdt?132b3a5c
132b3a5c?(Oracle.DataAccess.Client.OracleParameter)
????__identity:NULL?(System.Object)
????m_pOpoPrmValCtx:4e691200?(System.UIntPtr)
????m_paramName:125fe6f0?(System.String)?Length=5,?String=":xxx"
????m_sourceColumn:NULL?(System.String)
????m_sourceVersion:0x200?(System.Data.DataRowVersion)
????m_dbType:0x0?(System.Data.DbType)
????m_oraDbType:0x77?(NVarchar2)?(Oracle.DataAccess.Client.OracleDbType)
????m_bOracleDbTypeExSet:false?(System.Boolean)
????m_maxSize:0xffffffff?(System.Int32)
????m_maxArrayBindSize:NULL?(System.Int32[])
????m_nullable:false?(System.Boolean)
????m_value:132b3af8?(System.String)?Length=6,?String="%高血壓病%"

原來是醫(yī)生模糊查詢了一個 高血壓病 導(dǎo)致的。。。

不過這里主要是想告訴大家的是,當(dāng)由于內(nèi)存遭到一定程度的破壞導(dǎo)致 sos 徹底趴窩也不要怕，可能還有其他的插件可以救我們于水火之中，多一個插件多一條路哈。

三：總結(jié)

總的來說，這次偶發(fā)的CPU爆高事故，犯的相對比較低級，對 List.Insert 的復(fù)雜度可能也不是很了解，也有可能是為了趕業(yè)務(wù)所欠的債吧，改發(fā)也相對簡單，先用 add 送到 list，最后再統(tǒng)一按規(guī)則做一下重整排序。