記一次.NET某工控圖片上傳CPU爆高分析

一：背景 1.講故事今天給大家帶來一個入門級的 CPU 爆高案例，前段時間有位朋友找到我，說他的程式間歇性的 CPU 爆高，不知道是啥情況，讓我幫忙看下，既然找到我，那就用 WinDbg 看一下。二：WinDbg 分析 1. CPU 真的爆高嗎其實我一直都在強調，要相信數據，口說無憑，一定要親 ...

一：背景

1.講故事

今天給大家帶來一個入門級的 CPU 爆高案例，前段時間有位朋友找到我，說他的程式間歇性的 CPU 爆高，不知道是啥情況，讓我幫忙看下，既然找到我，那就用 WinDbg 看一下。

二：WinDbg 分析

1. CPU 真的爆高嗎

其實我一直都在強調，要相信數據，口說無憑，一定要親自驗證一下，可以使用 !tp 命令。


0:000> !tp
CPU utilization: 81%
Worker Thread: Total: 32 Running: 0 Idle: 18 MaxLimit: 2047 MinLimit: 2
Work Request in Queue: 0
--------------------------------------
Number of Timers: 1
--------------------------------------
Completion Port Thread:Total: 0 Free: 0 MaxFree: 4 CurrentLimit: 0 MaxLimit: 1000 MinLimit: 2

從卦中可以看到，當前的 CPU=81%，果然爆高無疑，接下來就得調查下為什麼會爆高，可以從觸發 GC 入手。

2. GC 觸發了嗎

要觀察是否 GC 觸發，可以觀察下線程列表上是否有 (GC) 字樣，比如下麵的輸出。


0:006> !t
ThreadCount:      38
UnstartedThread:  0
BackgroundThread: 37
PendingThread:    0
DeadThread:       0
Hosted Runtime:   no
                                                                         Lock  
       ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1  5f0 01310688     2a020 Preemptive  00000000:00000000 0130aa50 0     MTA 
   2    2  818 0131e358     2b220 Preemptive  00000000:00000000 0130aa50 0     MTA (Finalizer) 
   3    6  7b0 01374908   202b220 Preemptive  00000000:00000000 0130aa50 0     MTA 
   4    7  f98 01381c50   102a220 Preemptive  00000000:00000000 0130aa50 0     MTA (Threadpool Worker) 
   6    3  610 013eba78     2b220 Cooperative 00000000:00000000 0130aa50 1     MTA (GC) 
   9   44  e04 05585068   1029220 Preemptive  00000000:00000000 0130aa50 0     MTA (Threadpool Worker) 
  10   25  448 063dab30     21220 Preemptive  00000000:00000000 0130aa50 0     Ukn 
  ...

從卦中可以看到6號線程果然帶了 (GC) 字樣，接下來用 kb 觀察下到底是哪一代GC。


0:006> kb
 # ChildEBP RetAddr      Args to Child              
00 05beef18 72bb4825     0b771000 00000003 00000001 clr!WKS::gc_heap::relocate_survivor_helper+0x87
01 05beef48 72bb46da     0b771000 00000001 00000000 clr!WKS::gc_heap::relocate_survivors+0x93
02 05beef98 72bb1913     00000000 00000001 73180140 clr!WKS::gc_heap::relocate_phase+0x8b
03 05bef140 72bb0f69     00000000 00000001 00000001 clr!WKS::gc_heap::plan_phase+0x13b8
04 05bef168 72bb12ef     5e7aa9c3 7317fcd0 00000000 clr!WKS::gc_heap::gc1+0xe8
05 05bef1a0 72bb140c     00000040 7317ff04 7317ff04 clr!WKS::gc_heap::garbage_collect+0x447
06 05bef1c8 72bb161c     00000000 00000000 00000040 clr!WKS::GCHeap::GarbageCollectGeneration+0x1fb
07 05bef1ec 72bb1696     7317ff04 71a9d900 00000002 clr!WKS::gc_heap::trigger_gc_for_alloc+0x1e
08 05bef21c 72bff51a     00000000 00000040 0c1c7aa4 clr!WKS::gc_heap::try_allocate_more_space+0x162
09 05bef230 72bff687     00000000 01304d38 72bff140 clr!WKS::gc_heap::allocate_more_space+0x18
0a 05bef24c 72ab4477     013ebab8 00000040 00000002 clr!WKS::GCHeap::Alloc+0x5c
0b 05bef26c 72ab44f5     01000000 71ab5e90 05bef3f8 clr!Alloc+0x87
0c 05bef2b4 72ab4595     5e7aab5f 00000bb8 05bef3f8 clr!AllocateObject+0x99
0d 05bef33c 719b8281     71a2417c 05bef358 05bef35c clr!JIT_New+0x6b
0e 05bef360 7225652d     00000000 00000000 00000000 mscorlib_ni!System.Threading.Tasks.Task.Delay+0x41 [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 5885] 
0f 05bef454 05a9d18a     00000000 00000000 00000000 mscorlib_ni!System.Threading.Tasks.Task.Delay+0xd [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 5843] 
...

因為 C++ 預設是 this 協定，從 clr!WKS::gc_heap::plan_phase+0x13b8 方法的第二個參數 00000001 可知，當前觸發了 1 代 GC，其實 1 代 GC 本來就觸發頻繁，所以問題不大，主要就是看是否為 2 代GC，即 FullGC。

到這裡，GC觸發的路堵死了，我們就看下是不是還有其他的可疑情況，比如高時鐘個數的線程。

3. 有長時間運行線程嗎

如果是當事人，可以用 Process Explorer 工具直接觀察 Thread 列表的 Cycles Delta 列就能知道，比如下麵的百度雲管家，

可以看到 11156 號線程占用了太多的時鐘周期個數，可惜我不是當事人，所以只能用 cpuid 命令觀察。


0:006> !runaway
 User Mode Time
  Thread       Time
    6:610      0 days 0:47:07.984
   10:448      0 days 0:11:32.531
   12:17d4     0 days 0:01:34.265
    9:e04      0 days 0:01:29.468
   11:16ec     0 days 0:01:11.562
   13:1458     0 days 0:01:07.703
   ...

從卦中可以看到，6號線程耗費的時鐘個數遙遙領先，甩了第二名 10 號線程幾條街，這個線程非常可疑，得好好研究下它的托管棧了。


0:006> !clrstack
OS Thread Id: 0x610 (6)
Child SP       IP Call Site
05bef2d0 72bb47ae [HelperMethodFrame: 05bef2d0] 
05bef344 719b8281 System.Threading.Tasks.Task.Delay(Int32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 5885]
05bef36c 7225652d System.Threading.Tasks.Task.Delay(Int32) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 5843]
05bef370 05a9d18a xxx.Api.Core.xxx+c__DisplayClass2_0.<.cctor>b__0()
05bef45c 719b7118 System.Threading.Tasks.Task.InnerInvoke() [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 2884]
05bef468 719b6cc0 System.Threading.Tasks.Task.Execute() [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 2498]
05bef48c 719b70ea System.Threading.Tasks.Task.ExecutionContextCallback(System.Object) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 2861]
05bef490 719d40c5 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 954]
05bef4fc 719d3fd6 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 902]
05bef510 719b6f68 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 2827]
05bef574 719b6e72 System.Threading.Tasks.Task.ExecuteEntry(Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 2756]
05bef584 71a2acbc System.Threading.Tasks.ThreadPoolTaskScheduler.LongRunningThreadWork(System.Object) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\ThreadPoolTaskScheduler.cs @ 49]
05bef588 719a70e3 System.Threading.ThreadHelper.ThreadStart_Context(System.Object) [f:\dd\ndp\clr\src\BCL\system\threading\thread.cs @ 74]
05bef594 719d40c5 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 954]
05bef600 719d3fd6 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 902]
05bef614 719d3f91 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @ 891]
05bef62c 71a28cae System.Threading.ThreadHelper.ThreadStart(System.Object) [f:\dd\ndp\clr\src\BCL\system\threading\thread.cs @ 93]
05bef770 72a90096 [GCFrame: 05bef770] 
05bef954 72a90096 [DebuggerU2MCatchHandlerFrame: 05bef954]

從線程棧上看還好有一個托管方法 xxx.Api.Core.xxx+c__DisplayClass2_0.<.cctor>b__0 ，接下來觀察下源碼，修剪後的代碼如下：


static xxxUploadPool()
{
    _queue = new ConcurrentQueue<xxxModel>();
    _xxx = new xxxService();
    int second = Configuration.xxx * 1000;
    Task.Factory.StartNew(delegate
    {
        while (true)
        {
            lock (_queue)
            {
                if (_queue.Count > 0 && _queue.TryDequeue(out var result))
                {
                    _xxx.UploadFilexxxx(result._path, result._repositoryName, xxx);
                }
            }
            Task.Delay(second);
        }
    }, TaskCreationOptions.LongRunning);
}

這段代碼很有意思，它的本來想法就是開啟一個長線程，然後在長線程中不斷的輪詢等待，問題就出在了這個等待上，即 Task.Delay(second); 這句，這句代碼起不到任何作用，而且一旦 _queue 中的數據為空就成了死迴圈，給 CPU 打滿埋下了禍根。

這裡有一個疑問：一個線程能把 CPU 打滿，那太瞧不起CPU 了，肯定是有對等的 core 個數的線程一起發力，打爆CPU，那如何驗證？觀察下 CPU 的個數。


0:006> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,85,4  GenuineIntel    3193
 1  6,85,4  GenuineIntel    3193

也就說只要有兩個線程進入了 xxxUploadPool 那就夠了，現象也正是如此。

三：總結

這段代碼確實很有意思，猜測原來就是 Thread.Sleep(second) ，但為了趕潮流改成了 Task.Delay(second)，在不清楚後者的使用場景下給 CPU 間歇性爆高埋下了禍根，所以大家在使用新的語法時，一定要弄清楚場景，萬不可生搬硬套。