记一次 .NET 某市附属医院 Web程序 偶发性CPU爆高分析
一:背景
1. 講故事
這個月初,一位朋友加微信求助他的程序出現了 CPU 偶發性爆高,希望能有償解決一下。
從描述看,這個問題應該困擾了很久,還是醫院的朋友給力,開門就是 100塊 紅包 🤣🤣🤣,那既然是偶發性爆高,人工不行,還得用 procdump 自動抓,用 procdump -ma -s 5 -n 2 -c 70 w3wp 埋伏好,幾天后如愿生成了兩個dump,太妙了,接下來就用 windbg 分析吧。
二:Windbg 分析
1. 真的是cpu爆高嗎
一切只相信數據,這里用 !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從數據看,此時 CPU utilization: 83%, 沒毛病。
2. 查看線程耗時
既然是偶發性的bug,而且也說了可能是醫生操作了什么觸發了什么條件才導致的,剛好這里也有 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.000Kernel?time:?0?days?0:08:43.000User?time:?0?days?1:08:19.0000:062:x86>?!runawayUser?Mode?TimeThread???????Time62:7188?????0?days?0:18:05.34344:6c90?????0?days?0:16:16.68739:86e8?????0?days?0:14:57.73432:1d8c?????0?days?0:01:02.54635:23a4?????0?days?0:00:58.2500: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.000Kernel?time:?0?days?0:08:45.000User?time:?0?days?1:08:41.0000:062:x86>?!runawayUser?Mode?TimeThread???????Time62:7188?????0?days?0:18:11.87544:6c90?????0?days?0:16:23.15639:86e8?????0?days?0:15:04.15632:1d8c?????0?days?0:01:02.54635:23a4?????0?days?0:00:58.250從信息看,間隔15s的dump,相對來說 62,44,39 這三個線程耗時最多,所以這三個線程值得繼續挖一挖。
3. 查看線程棧
接下來用 ~62s; !clrstack;~44s; !clrstack;~39s; !clrstack 切到這三個線程看下棧情況,如下圖所示:
從棧中看,并沒有用戶代碼,這就很尷尬了,我一度懷疑是不是 webform 的同步上下文導致的,但好歹我還是有一些經驗,既然 !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 把堆對象都導出來。
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 爆高導致的,也有可能是抓的不好,這下太折磨了,得,只能用 kb 到非托管棧上找方法參數。
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??<no?information>用輸出中可以看到,這個 list=23w 條記錄,它正在 list.Contains 處,有了這些信息,接下來就可以把源碼導出來,簡化后的代碼如下:
public?IList<xxx>?getBljl(string?as_search,?string?as_ztbz){IList<me_zyblbr>?list?=?new?List<me_zyblbr>();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;}眼尖的朋友肯定能注意到,在數據量大的情況下,這里的 list.Insert(0, me_zyblbr); 有大問題,畢竟 list.Insert 的復雜度是 O(N),針對 23w 來說總的時間復雜度就是:
n(n-1)/2 = 23w(23w-1)/2 = 26,450,000,000 = 264億 。
然后就是 3個這樣的線程就一起把cpu給抬起來了。
4. 到底是什么sql語句導致
雖然問題根已找到,但朋友最關心的是這位醫生到底輸入了什么導致 sql 查詢了如此大的數據, 不知道醫生要扣錢還是他們要向上面有個交代😂😂😂, 由于堆,棧都 被損壞了,找起來還是很麻煩的,我用了 sos 中的 !lno, !dumpheap 都是報錯,徹底趴窩了,最后想了下 sosex 中也有一個 !mdso 命令,終于一路坎坷的找到了重要的 OracleParameter 參數。
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.OracleParameter0: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="%高血壓病%"原來是醫生模糊查詢了一個 高血壓病 導致的。。。
不過這里主要是想告訴大家的是,當由于內存遭到一定程度的破壞導致 sos 徹底趴窩也不要怕,可能還有其他的插件可以救我們于水火之中,多一個插件多一條路哈。
三:總結
總的來說,這次偶發的CPU爆高事故,犯的相對比較低級,對 List.Insert 的復雜度可能也不是很了解,也有可能是為了趕業務所欠的債吧,改發也相對簡單,先用 add 送到 list,最后再統一按規則做一下重整排序。
END
工作中的你,是否已遇到 ...?
1. CPU爆高
2. 內存暴漲
3. 資源泄漏
4. 崩潰死鎖
5. 程序呆滯
等緊急事件,全公司都指望著你能解決...? 危難時刻才能展現你的技術價值,作為專注于.NET高級調試的技術博主,歡迎微信搜索: 一線碼農聊技術,免費協助你分析Dump文件,希望我能將你的踩坑經驗分享給更多的人。
總結
以上是生活随笔為你收集整理的记一次 .NET 某市附属医院 Web程序 偶发性CPU爆高分析的全部內容,希望文章能夠幫你解決所遇到的問題。
- 上一篇: 在ASP.Net Core和JAVA中,
- 下一篇: 讲一讲应用服务的新鲜事儿