記一次 .NET 某智慧交通後臺服務 CPU爆高分析

一線碼農發表於2022-01-28

一:背景

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,讓我真的眼見為實啦!

圖片名稱

相關文章