再记一次应用服务器 CPU 暴高事故分析

一：背景

1. 前言

大概有2个月没写博客了，不是不想写哈????，关注公号的朋友应该知道我这两个月一直都在翻译文章，前前后后大概100篇左右吧，前几天看公号的 常读用户 降了好几十，心疼哈，还得回过神来继续写！

2. 讲故事

上周给 武汉同济 做项目升级，本以为一切顺利，结果捅娄子了，第二天上午高峰期运维说生产上两台应用服务器 cpu 被打满，影响到所有客户使用，造成了大面积瘫痪，真尬尴，得先让运维抓一个 dump 下来再重启网站，还好，老板人可以，没有问责 ????。

二：CPU 爆高问题分析

1. 找思路

分析 dump，没什么比 windbg 更专业了，不过分析 dump 我还是比较拿手的，那怎么分析呢？最简单粗暴的做法就是看每一个线程当时都在做什么，进而推测一下就 八九不离十 了。

2. 查看所有线程栈

首先用 !t 和 !tp 看一下当前程序的 线程 和 线程池 的整体概况。


0:000> !t
ThreadCount:      60
UnstartedThread:  0
BackgroundThread: 38
PendingThread:    0
DeadThread:       22
Hosted Runtime:   noLock  ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception11    1 2c24 02487038     28220 Preemptive  00000000:00000000 010df4f8 0     Ukn 28    2 2ca0 024bad90     2b220 Preemptive  00000000:00000000 010df4f8 0     MTA (Finalizer) 30    3 2d04 024f1450   102a220 Preemptive  00000000:00000000 010df4f8 0     MTA (Threadpool Worker) 31    4 2054 024fb188     21220 Preemptive  00000000:00000000 010df4f8 0     Ukn 32    6 1128 02574400   1020220 Preemptive  00000000:00000000 010df4f8 0     Ukn (Threadpool Worker) 2    5 27ac 02520da8     20220 Preemptive  00000000:00000000 010df4f8 0     Ukn 35   17 2c44 1cc362c8   202b220 Preemptive  00000000:00000000 024fa838 1     MTA 36   20 1740 1cccc748     21220 Preemptive  00000000:00000000 010df4f8 0     Ukn 37   21 16c4 1cc08240     21220 Preemptive  00000000:00000000 010df4f8 0     Ukn 38   22 16a8 1ccd28b8     21220 Preemptive  00000000:00000000 010df4f8 0     Ukn ....0:000> !tp
CPU utilization: 97%
Worker Thread: Total: 21 Running: 21 Idle: 0 MaxLimit: 8191 MinLimit: 8
Work Request in Queue: 23Unknown Function: 6d92a17f  Context: 0109b5f0Unknown Function: 6d92a17f  Context: 0107ed90Unknown Function: 6d92a17f  Context: 0104e750Unknown Function: 6d92a17f  Context: 010a0200AsyncTimerCallbackCompletion TimerInfo@207f8008AsyncTimerCallbackCompletion TimerInfo@0251b418Unknown Function: 6d92a17f  Context: 01096c78Unknown Function: 6d92a17f  Context: 01081398AsyncTimerCallbackCompletion TimerInfo@024d0120Unknown Function: 6d92a17f  Context: 010a9a20Unknown Function: 6d92a17f  Context: 01057950Unknown Function: 6d92a17f  Context: 0104c2d0Unknown Function: 6d92a17f  Context: 010943d8Unknown Function: 6d92a17f  Context: 0107a180Unknown Function: 6d92a17f  Context: 010a7418Unknown Function: 6d92a17f  Context: 010839a0Unknown Function: 6d92a17f  Context: 010678d0Unknown Function: 6d92a17f  Context: 010a2808Unknown Function: 6d92a17f  Context: 0105c250Unknown Function: 6d92a17f  Context: 0108abb8Unknown Function: 6d92a17f  Context: 0108f7c8Unknown Function: 6d92a17f  Context: 0108d1c0Unknown Function: 6d92a17f  Context: 20896498
--------------------------------------
Number of Timers: 0
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 16 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 8

从上面的输出大概可以看到如下几点信息：

当前程序有 60 个线程。
当前 CPU 利用率为 97%，爆高无疑。
线程池中有21个线程全部打满，还有23个任务在 任务队列 中排队等待处理。

总的来看，系统已经高负荷，不堪重负了，接下来的一个疑问就来了，所有的线程都被打满而且线程池中还有大量等待处理的任务在排队，现有的线程都在干嘛呢？难道不处理吗？

2. 查看所有线程的托管线程栈

既然现存的有 60 个线程，那我就使用 ~ *e !clrstack 命令看看所有的线程都在干嘛？


0:000> ~ *e !clrstack
OS Thread Id: 0x8d8 (44)
Child SP       IP Call Site
1ad8d750 7759f901 [InlinedCallFrame: 1ad8d750] 
1ad8d74c 71e1a9ea DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, IntPtr, System.String, System.String, Int32, Int32, System.String, Int32, Int32, Int32)
1ad8d750 71d52f0b [InlinedCallFrame: 1ad8d750] System.Globalization.CompareInfo.InternalCompareString(IntPtr, IntPtr, System.String, System.String, Int32, Int32, System.String, Int32, Int32, Int32)
1ad8d7b4 71d52f0b System.Globalization.CompareInfo.Compare(System.String, Int32, Int32, System.String, Int32, Int32, System.Globalization.CompareOptions)
1ad8d7e0 71e16ab9 System.String.Compare(System.String, Int32, System.String, Int32, Int32, System.Globalization.CultureInfo, System.Globalization.CompareOptions)
1ad8d810 71d51c8e System.Globalization.DateTimeFormatInfo.Tokenize(System.TokenType, System.TokenType ByRef, Int32 ByRef, System.__DTString ByRef)
1ad8d86c 71d51a92 System.__DTString.GetSeparatorToken(System.Globalization.DateTimeFormatInfo, Int32 ByRef, Char ByRef)
1ad8d88c 71d513c4 System.DateTimeParse.Lex(DS, System.__DTString ByRef, System.DateTimeToken ByRef, System.DateTimeRawInfo ByRef, System.DateTimeResult ByRef, System.Globalization.DateTimeFormatInfo ByRef, System.Globalization.DateTimeStyles)
1ad8d8dc 71d50b59 System.DateTimeParse.TryParse(System.String, System.Globalization.DateTimeFormatInfo, System.Globalization.DateTimeStyles, System.DateTimeResult ByRef)
1ad8d974 71dfce8b System.DateTimeParse.Parse(System.String, System.Globalization.DateTimeFormatInfo, System.Globalization.DateTimeStyles)
1ad8d9d8 7243c9bc System.Convert.ToDateTime(System.String, System.IFormatProvider)
1ad8d9f8 724369b1 System.String.System.IConvertible.ToDateTime(System.IFormatProvider)
1ad8da00 7243c8a2 System.Convert.ToDateTime(System.Object)

由于输出的太多，这里就简略输出了，不过我大体罗列了一下线程大概都在做什么事情。

有 9 个线程正在执行 GetAllByCondition() 方法

有 4 个线程正在执行 GetDayInvoice() 方法

9 + 4 个线程都在搞这两个方法，这就比较可疑了，不过从各个线程的栈顶上看并没有类似 wait 关键词，这就意味着大家不是在争抢锁啥的，那问题在哪里呢？

继续分析这两个方法到底在数据库中读了什么？通过 !dso 抓取 GetDayInvoice() 方法中的 sql，这里我就模糊一下了哈，windbg命令大概如下：


0:000> ~45s
eax=1c06a5c8 ebx=00000000 ecx=59002090 edx=59002090 esi=000003d4 edi=00000000
eip=7759f901 esp=1d95cfa8 ebp=1d95d014 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!NtWaitForSingleObject+0x15:
7759f901 83c404          add     esp,4
0:045> !dso
OS Thread Id: 0x2a04 (45)
ESP/REG  Object   Name
1D95D6D0 aaaac9f4 System.String    SELECT xxxxxx FROM xxxx as v WITH(NOLOCK) left join xxx as cr WITH(NOLOCK) on v.xxx=cr.xxx left join xxx  as crr WITH(NOLOCK) on cr.PID=crr.ID  WHERE xxx IN (SELECT DISTINCT xxx FROM xxxx WITH(NOLOCK) WHERE (SendTime>='2021-01-21 14:30:39' OR  xxx>='2021-01-21 14:30:39' OR xxx>='2021-01-21 14:30:39')  AND ((InvoiceType  =1 and( IsRepeat=0 or IsRepeat is null ))  OR xxx IN(16,15))  )

然后让运维查了下，这条sql大概有 13w 的记录，我第一反应就是查这么大的数据是不是有毛病撒，问了下懂业务的老大，这一块原来是做 初始化同步, 而且这块好久都没人动过，言外之意原来也是这么查的，一点毛病也没有呀，我去，说的也是哈，为啥以前没问题呢？？？

3. 查看托管堆

既然一条sql查了 13w 条数据，刚才是 4个线程在执行 GetDayInvoice()，也就意味着有 52w 条数据正在从 sqlserver 中获取，接下来我的本能反应就是看看托管堆，使用 !dumpheap -stat 就可以了,如下代码所示：


0:045> !dumpheap -stat
The garbage collector data structures are not in a valid state for traversal.
It is either in the "plan phase," where objects are being moved around, or
we are at the initialization or shutdown of the gc heap. Commands related to 
displaying, finding or traversing objects as well as gc heap segments may not 
work properly. !dumpheap and !verifyheap may incorrectly complain of heap 
consistency errors.
Object <exec cmd="!ListNearObj /d 02881000">02881000</exec> has an invalid method table.

我去，有点尴尬，居然报错了，先擦擦头上的汗，这句话：The garbage collector data structures are not in a valid state for traversal 引起了我的警觉，当前托管堆是无效状态，gc被触发了。。。当前还是 plan phase 状态，是不是 gc 导致了 cpu 爆高呢？

4. 零碎信息整合

通过上面这些零碎的信息，不知道大家可整明白了，让我来说的话，简而言之：GetDayInvoice() 读了大量数据，导致gc频繁回收，进而导致 cpu 爆高，这里有几个概念需要大家了解下：

这个程序是 32bit，意味着最大只能吃 4G 内存。
32bit 的临时代（ 0+1 代）大概几十M 的空间。
IIS 是 服务器模式 的GC，意味着当前的托管线程会临时充当 GC 回收线程。

尤其是上面第三个概念，既然当前gc被触发了，也就意味着托管线程被临时给 GC 征用了，那我可以看下是否真的是这样，可以用 ~ *e !dumpstack 查看所有线程的托管和非托管的所有栈信息，如下图所示：

可以清晰的看到，调用 GetDayInvoice() 的线程在 CLR 层面触发了 gc，而此时 gc 想调用 try_allocate_more_space 来给自己分配更多的空间，而且 wait_for_gc_done 也表示它在等待其他gc线程处理完成，所以就卡死在这里了。

如果不信的话，还可以继续观察其他线程的非托管堆栈，如下图所示：

从 clr!SVR::GCHeap::WaitUntilGCComplete+0x35, calling clr!CLREventBase::WaitEx 可以看出，都是在等待 GC 完成，导致 CPU 爆高。

5. 找到问题根源

汇总一下就是：这次 cpu 爆高是因为 32bit 程序只能吃 4G 内存，而程序需要同步大量的数据，导致内存被打满，gc无法分配更多的内存让程序使用，gc的机制让 cpu 打的满满的，知道问题之后，解决办法很简单，将 iis 的 应用程序域 的配置 启用32bit应用程序 改成 False 即可，这样程序就可以以 64bit 方式运行，如下图所示：