一:背景
1. 講故事
前天有位朋友加微信求助他的程序出現了CPU爆高的問題,開局就是一個紅包,把我嚇懵了! 🤣🤣🤣
由於是南方小年,我在老家張羅處理起來不方便,沒有第一時間幫他處理,朋友在第二天上午已經找出問題了,反饋說是一個 while(true)
導致的,這就有點意思了,在我分析的眾多 CPU 爆高案例中,還真沒遇到 while(true)
的情況,一直都抱有遺憾,真是運氣好,年前趕上了,哈哈 😄😄😄。
接下來我們就用 windbg 一起來分析下吧。
二:Windbg 分析
1. 查看CPU占用率
一直關注我的朋友都知道,用 !tp
命令就可以了。
0:022> !tp
CPU utilization: 95 Unknown format characterUnknown format control characterWorker Thread: Total: 11 Running: 11 Idle: 0 MaxLimit: 32767 MinLimit: 4
Work Request in Queue: 0
--------------------------------------
Number of Timers: 3
--------------------------------------
Completion Port Thread:Total: 4 Free: 4 MaxFree: 8 CurrentLimit: 4 MaxLimit: 1000 MinLimit: 4
上面有一句 Unknown format characterUnknown format control characterWorker
顯得不太和諧,其實就是 %
的意思,不知道為啥在 .NETCore 會出現這種編碼問題 😂😂😂,接下來我們用 !eeversion
看一下。
0:022> !eeversion
4.700.21.56803 (3.x runtime) free
4,700,21,56803 @Commit: 28bb6f994c28bc91f09bc0ddb5dcb51d0f066806
Workstation mode
In plan phase of garbage collection
SOS Version: 5.0.4.36902 retail build
從基本信息看,當前是 .netcore 3.x
版本,而且很明顯看到當前 GC 處於計划階段。那何為計划階段呢?
2. 何為計划階段
簡而言之,計划階段的GC需要決定當前的的托管堆是做簡單的標記free操作,還是要做重量級的壓縮操作,如果要壓縮處理,還需要涉及到托管堆對象的重定位,這往往會耗費相當多的 CPU 時間片,接下來要探究的是什么導致了 GC 觸發?
3. GC 觸發原因
由於 GC 的觸發往往是用戶線程
分配數據導致的,在GC觸發的整個執行流中,其中有一環就是凍結 CLR執行引擎
,也就是 SuspendEE
,可以在 gc.cpp
中一探究竟。
為什么一定要提 SuspendEE
呢?是因為我可以通過 !t -special
找出那個 SuspendEE
的線程,這樣准確度更高一點。
0:072> !t -special
ThreadCount: 54
UnstartedThread: 0
BackgroundThread: 40
PendingThread: 0
DeadThread: 1
Hosted Runtime: no
OSID Special thread type
1 6328 DbgHelper
2 35c0 Finalizer
4 5aac Timer
5 38b0 ThreadpoolWorker
17 3530 ThreadpoolWorker
18 4484 ThreadpoolWorker
19 1e4c ThreadpoolWorker
21 6380 ThreadpoolWorker
44 5bc4 SuspendEE
52 8ac ThreadpoolWorker
54 4164 ThreadpoolWorker
56 61c8 ThreadpoolWorker
58 1fa4 ThreadpoolWorker
60 2788 ThreadpoolWorker
69 48f4 IOCompletion
70 5708 IOCompletion
71 3b58 ThreadpoolWorker
72 17a0 GC
73 2f00 Gate
74 35e8 IOCompletion
75 5730 IOCompletion
可以看到當前的 44
號線程就是觸發 GC 的線程,接下來就明朗了,看看 44 號線程在做啥?切到 44 號線程,然后 !clrstack
即可。
0:044> !clrstack
OS Thread Id: 0x5bc4 (44)
Child SP IP Call Site
000000A2B0C3E4C8 00007ffd471ead3a [HelperMethodFrame: 000000a2b0c3e4c8]
000000A2B0C3E5E0 00007ffce8b4e506 System.Collections.Generic.List`1[[System.__Canon, System.Private.CoreLib]].System.Collections.Generic.IEnumerable.GetEnumerator() [/_/src/System.Private.CoreLib/shared/System/Collections/Generic/List.cs @ 585]
000000A2B0C3E630 00007ffce85e7a10 xxx.Program.DeletexxxExipredDate()
000000A2B0C3E780 00007ffd46bc1f0b System.Threading.ThreadHelper.ThreadStart_Context(System.Object) [/_/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 44]
000000A2B0C3E7B0 00007ffd46bb90b6 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs @ 172]
000000A2B0C3E830 00007ffd46ba535b System.Threading.ThreadHelper.ThreadStart() [/_/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 93]
000000A2B0C3EA48 00007ffd47236c93 [GCFrame: 000000a2b0c3ea48]
000000A2B0C3ECB0 00007ffd47236c93 [DebuggerU2MCatchHandlerFrame: 000000a2b0c3ecb0]
從輸出信息看,問題出在了 DeletexxxExipredDate()
方法,接下來探究下這個方法的源碼。
private static void DeletexxxExipredDate()
{
while (true)
{
foreach (string key in xxx.xxxSpeedLimit.Keys)
{
try
{
string[] array = xxx.xxxSpeedLimit[key].Split('$');
if (array.Length > 1)
{
DateTime dateTime = Convert.ToDateTime(array[1]);
if ((DateTime.Now - dateTime).TotalSeconds > 21600.0 && xxx.xxxSpeedLimit.ContainsKey(key))
{
xxx.xxxSpeedLimit.TryRemove(key, out var _);
}
}
}
catch (Exception ex)
{
LogHelper.WriteAppExceptionLog("刪除數據出現異常:" + ex.Message, ex);
}
Thread.Sleep(20000);
}
}
}
如果有豐富踩坑經驗的朋友,我相信一眼就能看出這代碼中存在的問題,對,就是當 xxxSpeedLimit
字典為空的時候,就相當於一個 while(true)
死循環啦,對不對?
為了驗證我的說法,可以用 !dso
找到 dict 的內存地址,然后用 !wconcurrentdict
即可。
0:044> !dso
OS Thread Id: 0x5bc4 (44)
RSP/REG Object Name
...
000000A2B0C3E708 000001ba8007f618 System.Collections.Concurrent.ConcurrentDictionary`2[[System.String, System.Private.CoreLib],[System.String, System.Private.CoreLib]]
000000A2B0C3E760 000001ba88501cd0 System.Collections.Generic.List`1+Enumerator[[System.String, System.Private.CoreLib]]
000000A2B0C3E768 000001ba80050ec0 System.Threading.ContextCallback
000000A2B0C3E7F8 000001ba80a1a818 System.Threading.Thread
000000A2B0C3EA28 000001ba80a1a898 System.Threading.ThreadStart
0:044> !wconcurrentdict 000001ba8007f618
Empty ConcurrentDictionary
可以看到,當前就是一個 空字典
😂😂😂
三:總結
這次事故的主要原因:編碼人員缺少了一定的編程經驗,在寫業務邏輯的時候缺少了對 空字典
的流程處理,導致了 while(true)
的尷尬,也有可能是將那個 Thread.Sleep(20000)
放錯了位置🤣🤣🤣
總的來說很感謝這位朋友提供的dump,讓我真的眼見為實啦!
