关于.net:再记一次-应用服务器-CPU-暴高事故分析

50次阅读

共计 6916 个字符，预计需要花费 18 分钟才能阅读完成。

一：背景

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   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.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 形式运行，如下图所示：

三：总结

很显然这次事件是因为管理混乱造成的，因为历史遗留问题，有些网站必须用 32 bit 运行，有些必须用 64 bit 运行，据运维说，目前服务器存在不能建过多的应用程序域，导致多个网站专用一个程序域，外表上是运维弄错应用程序域，根子上还是没有彻底革新的信心！

更多高质量干货：参见我的 GitHub: dotnetfly

正文完
.net
发表至： .net
2021-02-08
 0
关于.net:如何在-ASPNET-Core-中使用-NLog-的高级特性
关于net:Microsoft-Azure-动手实验营实现-NET-应用现代化火热报名中
关于.net:NET-Word-文档转换为-XML-文件
关于.net:NET-再出发-20岁生日快乐