用 windbg 分析一个 List.Insert 导致某市附属医院 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.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，最后再统一按规则做一下重整排序。