记一次 .NET某差旅系统 CPU爆高分析

一：背景

1. 讲故事

前些天训练营里的一位学员找到我，说他们的差旅后台系统出现了CPU爆高的情况，爆高之后就下不去了，自己分析了下也没找到原因，事情比较紧急，让我帮忙看下是什么回事，手里也有dump，丢过我之后我们上 windbg 分析吧。

二：WinDbg分析

1. 为什么会CPU爆高

看过这个系列的朋友都知道CPU是否爆高，可以用 !tp 命令来验证，参考输出如下：


0:000> !tp
CPU utilization: 100%
Worker Thread: Total: 66 Running: 66 Idle: 0 MaxLimit: 32767 MinLimit: 4
Work Request in Queue: 93
    Unknown Function: 00007ffc744f1750  Context: 000002c3acdad7d8
    AsyncTimerCallbackCompletion TimerInfo@000002bf57193d20
    Unknown Function: 00007ffc744f1750  Context: 000002c3acb2aef0
    ...
    Unknown Function: 00007ffc744f1750  Context: 000002c3ad336718
--------------------------------------
Number of Timers: 0
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 8 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 4

从卦中的 CPU utilization: 100% 可以确认此时CPU被打满了，同时也有一个现象就是这个线程池队列有堆积的情况，一般来说堆积就表示下游处理不力，常常表现为程序卡死，Http超时，和 CPU爆高问题 没有直接关系，这是一个经验问题，大家一定要甄别，以免陷入误区。

接下来我们看下这台机器的CPU能力如何，能力越弱越容易被打爆，可以用 !cpuid 观察。


0:000> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,85,7  <unavailable>   2095
 1  6,85,7  <unavailable>   2095
 2  6,85,7  <unavailable>   2095
 3  6,85,7  <unavailable>   2095

从卦中可以看到当前的 CPU=4core，只要4个满负荷的Thread就可以轻松打爆，接下来我们的研究方向在哪里呢？对，就是从 Thread 入手。

2. 线程都在干什么

要想看线程都在干什么？可以使用 ~*e !clrstack 观察即可，参考输出如下：


OS Thread Id: 0x968 (87)
        Child SP               IP Call Site
000000e63babb9a8 00007ffc879a6974 [GCFrame: 000000e63babb9a8] 
000000e63babba78 00007ffc879a6974 [HelperMethodFrame_1OBJ: 000000e63babba78] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
000000e63babbb90 00007ffc5e735bbf System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\system\threading\ManualResetEventSlim.cs @ 669]
000000e63babbc20 00007ffc5e72e9c5 System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 3320]
000000e63babbc90 00007ffc5f0cc188 System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 3259]
000000e63babbd60 00007ffc5f0c9176 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].GetResultCore(Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Future.cs @ 559]
000000e63babbda0 00007ffc1b98f2cf xxxCheckFilterAttribute.GetRequestParameter(System.Web.Http.Controllers.HttpActionContext)
...

从卦中可以看到大量的 Wait 等待，其实就是代码中调用 Task.Result 所致，即异步中混合同步，虽然这是一个可能导致线程饥饿的问题，但和我们的目标：CPU爆高无关，所以我们需要在茫茫调用栈中寻找其他可能导致的 CPU 爆高线程，经过仔细而耐心的查找，终于找到了疑似调用栈，刚好有5个都停留在这个位置。参考如下：


OS Thread Id: 0x26a8 (35)
        Child SP               IP Call Site
000000e62537b048 00007ffc879a64a4 [HelperMethodFrame: 000000e62537b048] 
000000e62537b190 00007ffc5e68e04a System.String.Concat(System.String, System.String) [f:\dd\ndp\clr\src\BCL\system\string.cs @ 3207]
000000e62537b1e0 00007ffc1dbe85eb xxx.GetParentDeptName_All(System.Collections.Generic.List`1<xxx.xxxDepts>, Int64)
...
000000e62537c870 00007ffc1e0af75b DynamicClass.lambda_method(System.Runtime.CompilerServices.Closure, System.Object, System.Object[])
000000e62537c8b0 00007ffc1b29b3b8 System.Web.Http.Controllers.ReflectedHttpActionDescriptor+ActionExecutor+c__DisplayClass10.b__9(System.Object, System.Object[])
000000e62537c8f0 00007ffc1b29a768 System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(System.Web.Http.Controllers.HttpControllerContext, System.Collections.Generic.IDictionary`2<System.String,System.Object>, System.Threading.CancellationToken)
000000e62537c950 00007ffc1b29a18e System.Web.Http.Controllers.ApiControllerActionInvoker+d__0.MoveNext()
000000e62537c9c0 00007ffc1b2996ca System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, mscorlib]].Start[[System.Web.Http.Controllers.ApiControllerActionInvoker+d__0, System.Web.Http]](d__0 ByRef)
000000e62537ca70 00007ffc1b299611 System.Web.Http.Controllers.ApiControllerActionInvoker.InvokeActionAsyncCore(System.Web.Http.Controllers.HttpActionContext, System.Threading.CancellationToken)
000000e62537cb30 00007ffc1b299535 System.Web.Http.Controllers.ApiControllerActionInvoker.InvokeActionAsync(System.Web.Http.Controllers.HttpActionContext, System.Threading.CancellationToken)
000000e62537cb60 00007ffc1b299504 System.Web.Http.Controllers.ActionFilterResult.b__0(ActionInvoker)
000000e62537cb90 00007ffc1b2994a9 System.Web.Http.Controllers.ActionFilterResult+c__DisplayClass10`1[[System.Web.Http.Controllers.ActionFilterResult+ActionInvoker, System.Web.Http]].b__f()
000000e62537cbe0 00007ffc1b2622f9 System.Web.Http.Filters.ActionFilterAttribute+d__5.MoveNext()
000000e62537cc40 00007ffc1b261cfa System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, mscorlib]].Start[[System.Web.Http.Filters.ActionFilterAttribute+d__5, System.Web.Http]](d__5 ByRef)
000000e62537ccf0 00007ffc1b261bf4 System.Web.Http.Filters.ActionFilterAttribute.CallOnActionExecutedAsync(System.Web.Http.Controllers.HttpActionContext, System.Threading.CancellationToken, System.Func`1<System.Threading.Tasks.Task`1<System.Net.Http.HttpResponseMessage>>)
000000e62537cdd0 00007ffc1b2584d4 System.Web.Http.Filters.ActionFilterAttribute+d__0.MoveNext()

到了这里之后，甭管有没有问题，反正嫌疑很大，接下来就得研究 GetParentDeptName_All 方法。

3. GetParentDeptName_All 有问题吗

要想知道有没有问题，我们用 ILSpy观察其源码，由于客户隐私的问题，这里就稍微模糊一下，截图如下：

从卦中看，尼玛，还真有一个 while 逻辑，一下子就提起了我的兴趣，看样子八九不离十，接下来到线程栈上 GetParentDeptName_All 方法的 listDept 和 deptId 参数给挖出来，我们从35号线程入手，使用 !clrstack -a 参数观察输出结果。


0:035> !clrstack -a
OS Thread Id: 0x26a8 (35)
        Child SP               IP Call Site
000000e62537b048 00007ffc879a64a4 [HelperMethodFrame: 000000e62537b048] 
000000e62537b190 00007ffc5e68e04a System.String.Concat(System.String, System.String) [f:\dd\ndp\clr\src\BCL\system\string.cs @ 3207]
    PARAMETERS:
        str0 (<CLR reg>) = 0x000002c05816f360
        str1 (<CLR reg>) = 0x000002c3e21eaf88
    LOCALS:
        <no data>
        <no data>

000000e62537b1e0 00007ffc1dbe85eb xxx.GetParentDeptName_All(System.Collections.Generic.List`1<xxxDepts>, Int64)
    PARAMETERS:
        this (0x000000e62537b2c0) = 0x000002c059898590
        listDept (0x000000e62537b2c8) = 0x000002c159803390
        deptId (0x000000e62537b2d0) = 0x00000000000324fb

拿到了 listDept 的地址之后，用 .logopen 把 !mdt -e:2 000002c159803390 的输出结果全部记录到文本文件，为了保护客户隐私，这里就不截图了，直接上文本。


[20828] 000002c059802b68 (xxxtDepts)
    <DeptId>k__BackingField:0x324fb (System.Int32)
    <ParentDeptId>k__BackingField:0x31347 (System.Int32)
    ...

[20643] 000002c0597f0e30 (xxxtDepts)
    <DeptId>k__BackingField:0x2f240 (System.Int32)
    <ParentDeptId>k__BackingField:0x31347 (System.Int32)
    ...

[20663] 000002c0597f2d18 (xxxtDepts)
    <DeptId>k__BackingField:0x2f254 (System.Int32)
    <ParentDeptId>k__BackingField:0x2f240 (System.Int32)
    ...

从卦中数据看，listDept数组的第 20643 和 20663 项的子节点和父节点是循环的，这自然就导致了死循环，所以这次生产事故本质上是数据导致的，将结果反馈给朋友，也得到了确认。