共计 6164 个字符,预计需要花费 16 分钟才能阅读完成。
一:背景
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.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
这三个线程耗时最多,所以这三个线程值得持续挖一挖。
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.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="% 高血压病 %"
原来是医生含糊查问了一个 高血压病
导致的。。。
不过这里次要是想通知大家的是, 当因为内存受到肯定水平的毁坏导致 sos 彻底趴窝也不要怕,可能还有其余的插件能够救咱们于水火之中,多一个插件多一条路哈。
三:总结
总的来说,这次偶发的 CPU 爆高事变,犯的绝对比拟低级,对 List.Insert
的复杂度可能也不是很理解,也有可能是为了赶业务所欠的债吧,改发也绝对简略,先用 add
送到 list,最初再对立按规定做一下重整排序。