記一次.NET某工控圖片上傳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 間歇性爆高埋下了禍根，所以大家在使用新的語法時，一定要弄清楚場景，萬不可生搬硬套，

轉載請註明出處，本文鏈接：https://www.uj5u.com/net/534025.html

標籤：C#

上一篇：C# 鎖匯總

下一篇：簡易血槽殘影設計方案（使用協程）