一：背景
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: no
- Lock
- ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain nc">Count Apt Exception
- 11 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: 23
- Unknown Function: 6d92a17f Context: 0109b5f0
- Unknown Function: 6d92a17f Context: 0107ed90
- Unknown Function: 6d92a17f Context: 0104e750
- Unknown Function: 6d92a17f Context: 010a0200
- AsyncTimerCallbackCompletion TimerInfo@207f8008
- AsyncTimerCallbackCompletion TimerInfo@0251b418
- Unknown Function: 6d92a17f Context: 01096c78
- Unknown Function: 6d92a17f Context: 01081398
- AsyncTimerCallbackCompletion TimerInfo@024d0120
- Unknown Function: 6d92a17f Context: 010a9a20
- Unknown Function: 6d92a17f Context: 01057950
- Unknown Function: 6d92a17f Context: 0104c2d0
- Unknown Function: 6d92a17f Context: 010943d8
- Unknown Function: 6d92a17f Context: 0107a180
- Unknown Function: 6d92a17f Context: 010a7418
- Unknown Function: 6d92a17f Context: 010839a0
- Unknown Function: 6d92a17f Context: 010678d0
- Unknown Function: 6d92a17f Context: 010a2808
- Unknown Function: 6d92a17f Context: 0105c250
- Unknown Function: 6d92a17f Context: 0108abb8
- Unknown Function: 6d92a17f Context: 0108f7c8
- Unknown Function: 6d92a17f Context: 0108d1c0
- Unknown 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.nc">Convert.ToDateTime(System.String, System.IFormatProvider)
- 1ad8d9f8 724369b1 System.String.System.IConvertible.ToDateTime(System.IFormatProvider)
- 1ad8da00 7243c8a2 System.nc">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) nc">left join xxx as cr WITH(NOLOCK) on v.xxx=cr.xxx nc">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 方式运行，如下图所示：
三：总结很显然这次事件是因为管理混乱造成的，因为历史遗留问题，有些网站必须用 32 bit 运行，有些必须用 64 bit 运行，据运维说，目前服务器存在不能建过多的应用程序域，导致多个网站公用一个程序域，表面上是运维弄错应用程序域，根子上还是没有彻底改造的决心!
本文转载自微信公众号「 一线码农聊技术」，可以通过以下二维码关注。转载本文请联系 一线码农聊技术公众号。
