一:背景
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:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 5885] 0f 05bef454 05a9d18a 00000000 00000000 00000000 mscorlib_ni!System.Threading.Tasks.Task.Delay+0xd [f:ddndpclrsrcBCLsystemthreadingTasksTask.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:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 5885] 05bef36c 7225652d System.Threading.Tasks.Task.Delay(Int32) [f:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 5843] 05bef370 05a9d18a xxx.Api.Core.xxx+c__DisplayClass2_0.<.cctor>b__0() 05bef45c 719b7118 System.Threading.Tasks.Task.InnerInvoke() [f:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 2884] 05bef468 719b6cc0 System.Threading.Tasks.Task.Execute() [f:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 2498] 05bef48c 719b70ea System.Threading.Tasks.Task.ExecutionContextCallback(System.Object) [f:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 2861] 05bef490 719d40c5 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:ddndpclrsrcBCLsystemthreadingexecutioncontext.cs @ 954] 05bef4fc 719d3fd6 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:ddndpclrsrcBCLsystemthreadingexecutioncontext.cs @ 902] 05bef510 719b6f68 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef) [f:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 2827] 05bef574 719b6e72 System.Threading.Tasks.Task.ExecuteEntry(Boolean) [f:ddndpclrsrcBCLsystemthreadingTasksTask.cs @ 2756] 05bef584 71a2acbc System.Threading.Tasks.ThreadPoolTaskScheduler.LongRunningThreadWork(System.Object) [f:ddndpclrsrcBCLsystemthreadingTasksThreadPoolTaskScheduler.cs @ 49] 05bef588 719a70e3 System.Threading.ThreadHelper.ThreadStart_Context(System.Object) [f:ddndpclrsrcBCLsystemthreadingthread.cs @ 74] 05bef594 719d40c5 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:ddndpclrsrcBCLsystemthreadingexecutioncontext.cs @ 954] 05bef600 719d3fd6 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:ddndpclrsrcBCLsystemthreadingexecutioncontext.cs @ 902] 05bef614 719d3f91 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [f:ddndpclrsrcBCLsystemthreadingexecutioncontext.cs @ 891] 05bef62c 71a28cae System.Threading.ThreadHelper.ThreadStart(System.Object) [f:ddndpclrsrcBCLsystemthreadingthread.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 间歇性爆高埋下了祸根,所以大家在使用新的语法时,一定要弄清楚场景,万不可生搬硬套。