乐趣区

关于.net:用-windbg-分析一个-ListInsert-导致某市附属医院-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,最初再对立按规定做一下重整排序。

退出移动版