記一次.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:???noLock??ID?OSID?ThreadOBJ????State?GC?Mode?????GC?Alloc?Context??Domain???Count?Apt?Exception0????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>?!runawayUser?Mode?TimeThread???????Time6:610??????0?days?0:47:07.98410:448??????0?days?0:11:32.53112:17d4?????0?days?0:01:34.2659:e04??????0?days?0:01:29.46811:16ec?????0?days?0:01:11.56213: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?????MHz0??6,85,4??GenuineIntel????31931??6,85,4??GenuineIntel????3193

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

三：總結

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