一:背景 1. 講故事 停了一個月沒有更新文章了,主要是忙於寫 C#內功修煉系列的PPT,現在基本上接近尾聲,可以回頭繼續更新這段時間分析dump的一些事故報告,有朋友微信上找到我,說他們的系統出現了大量的http超時,程式不響應處理了,讓我幫忙看下怎麼回事,dump也抓到了。 二:WinDbg分析 ...
一:背景
1. 講故事
停了一個月沒有更新文章了,主要是忙於寫 C#內功修煉系列的PPT
,現在基本上接近尾聲,可以回頭繼續更新這段時間分析dump的一些事故報告,有朋友微信上找到我,說他們的系統出現了大量的http超時,程式不響應處理了,讓我幫忙看下怎麼回事,dump也抓到了。
二:WinDbg分析
1. 為什麼會出現請求超時
既然超時說明server端不響應這個請求,繼而達到了超時時間的一種異常情況,所以首先要想到的就是 線程池的健康度
,可以用 !tp
命令觀察,輸出如下:
0:000> !tp
CPU utilization: 0%
Worker Thread: Total: 537 Running: 537 Idle: 0 MaxLimit: 32767 MinLimit: 12
Work Request in Queue: 82
Unknown Function: 00007fff566a17d0 Context: 0000020f08cbd658
Unknown Function: 00007fff566a17d0 Context: 0000020f09acfa80
Unknown Function: 00007fff566a17d0 Context: 0000020f08702198
Unknown Function: 00007fff566a17d0 Context: 0000020f09ad9068
Unknown Function: 00007fff566a17d0 Context: 0000020f09abffe8
Unknown Function: 00007fff566a17d0 Context: 0000020f093c9948
Unknown Function: 00007fff566a17d0 Context: 0000020f093cfd28
Unknown Function: 00007fff566a17d0 Context: 0000020f093d9358
Unknown Function: 00007fff566a17d0 Context: 0000020f093c34e8
Unknown Function: 00007fff566a17d0 Context: 0000020f093dc568
...
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 24 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 12
從上面的卦象看異常非常明顯,線程池總共有 537個工作線程都是處於運行狀態,相信有經驗的朋友應該一眼就知道是怎麼回事,專業術語叫:線程饑餓
,並且線程池隊列也積壓了 82個 待處理的任務。
2. 線程為什麼會饑餓
線程饑餓的原因有更多,我特意問了下 chatgpt,列舉如下:
- 優先順序傾斜:如果某些線程的優先順序設置過高,而其他線程的優先順序設置過低,高優先順序的線程可能會長時間占用CPU資源,導致低優先順序線程無法獲得執行機會。
- 死鎖:當多個線程相互等待對方釋放資源時,可能會導致死鎖。在死鎖情況下,所有線程都無法繼續執行,從而導致線程饑餓。
- 資源競爭:多個線程競爭有限的資源(如共用記憶體、文件、網路連接等)時,可能會導致某些線程長時間無法獲取到所需的資源而處於饑餓狀態。
- 不公平的調度策略:調度器可能存在不公平的調度策略,導致某些線程無法獲得公平的CPU時間片,從而長時間無法執行。
- 線程阻塞:某些線程可能由於等待I/O操作、鎖或其他原因而被阻塞,如果阻塞時間過長,可能導致其他線程饑餓。
- 線程池配置不當:如果線程池中的線程數量設置不當,可能會導致某些任務長時間等待執行,從而引發線程饑餓。
那到底是哪一種情況呢?可以用 ~*e !clrstack
看一下各個線程此時正在做什麼,輸出如下:
0:000> ~*e !clrstack
...
OS Thread Id: 0x2924 (74)
Child SP IP Call Site
000000e0ef47dc30 00007fff60fd6974 [GCFrame: 000000e0ef47dc30]
000000e0ef47dd58 00007fff60fd6974 [HelperMethodFrame_1OBJ: 000000e0ef47dd58] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
000000e0ef47de70 00007ffef33e7269 System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken)
000000e0ef47df00 00007ffef33e6b58 System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken)
000000e0ef47df70 00007ffef33e69e1 System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken)
000000e0ef47e040 00007ffef60cce33 System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task)
000000e0ef47e070 00007ffef9df2c73 Exceptionless.Submission.DefaultSubmissionClient.SendHeartbeat(System.String, Boolean, Exceptionless.ExceptionlessConfiguration)
000000e0ef47e110 00007ffef109f03f System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000e0ef47e1e0 00007ffef109e784 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000e0ef47e210 00007ffef15b670b System.Threading.TimerQueueTimer.CallCallback()
000000e0ef47e270 00007ffef15b644d System.Threading.TimerQueueTimer.Fire()
000000e0ef47e2e0 00007ffef15b5613 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
000000e0ef47e320 00007ffef10b8319 System.Threading.ThreadPoolWorkQueue.Dispatch()
000000e0ef47e7a0 00007fff4fa06993 [DebuggerU2MCatchHandlerFrame: 000000e0ef47e7a0]
000000e0ef47e908 00007fff4fa06993 [ContextTransitionFrame: 000000e0ef47e908]
000000e0ef47eb40 00007fff4fa06993 [DebuggerU2MCatchHandlerFrame: 000000e0ef47eb40]
...
發現有 473 個線程都在 Exceptionless.Submission.DefaultSubmissionClient.SendHeartbeat
方法上進行等待,這就有意思了,原來是開源的日誌收集組件
發送的心跳檢測方法,接下來趕緊看一下這個方法的源碼。
public void SendHeartbeat(string sessionIdOrUserId, bool closeSession, ExceptionlessConfiguration config)
{
if (!config.IsValid)
{
return;
}
string requestUri = $"{GetHeartbeatServiceEndPoint(config)}/events/session/heartbeat?id={sessionIdOrUserId}&close={closeSession}";
try
{
_client.Value.AddAuthorizationHeader(config.ApiKey);
_client.Value.GetAsync(requestUri).ConfigureAwait(continueOnCapturedContext: false).GetAwaiter()
.GetResult();
}
catch (Exception exception)
{
config.Resolver.GetLog().Error("Error submitting heartbeat: " + exception.GetMessage());
}
}
從源碼看,居然用同步的方式發送 http請求
,在這非同步方法滿天飛的世界里,上面的寫法實屬異類。
3. 該如何解決呢?
既然是 Exceptionless 內部寫的 SendHeartbeat 方法,我們程式員基本上無法干預,能做到的無非如下兩點:
- 升級框架
看下了用的還是超老的 4.3
版本,可以升級到目前最新的 6.0.4
觀察試試。
[assembly: AssemblyTitle("Exceptionless")]
[assembly: AssemblyProduct("Exceptionless")]
[assembly: AssemblyCompany("Exceptionless")]
[assembly: AssemblyTrademark("Exceptionless")]
[assembly: AssemblyCopyright("Copyright (c) 2017 Exceptionless. All rights reserved.")]
[assembly: AssemblyConfiguration("Release")]
[assembly: AssemblyFileVersion("4.3.2027.0")]
[assembly: AssemblyInformationalVersion("4.3.2027$(VERSION_SUFFIX) f8d73f2fd7")]
[assembly: TargetFramework(".NETFramework,Version=v4.5", FrameworkDisplayName = ".NET Framework 4.5")]
[assembly: AssemblyVersion("4.3.2027.0")]
- 使用替代品,或者不用
哈哈,不用它,這是萬能的治根之法。
三:對線程註入速度的解答
1. 朋友提了一個疑問
我現在知道這個 url 某個時段可能響應出了問題,但我線程池裡的線程增速應該很快呀,多餘的線程不是可以響應客戶端請求嗎?為什麼我發現的情況是全部卡死呢?
2. 疑問的簡單解答
這個問題其實是考察對線程池底層的瞭解,尤其是多久會向線程池註入一個活線程,在 .NET Framework 時代,線上程饑餓的情況下線程池內部的 GateThread線程 會 1s 註入一個活線程,那如何驗證呢? 我們觀察後續的線程創建時間即可,使用 ~*e .ttime
。
0:000> ~*e .ttime
...
Created: Thu Nov 16 11:10:21.582 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
Created: Thu Nov 16 11:10:22.593 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
Created: Thu Nov 16 11:10:23.562 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
Created: Thu Nov 16 11:10:24.062 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
Created: Thu Nov 16 11:10:24.577 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
Created: Thu Nov 16 11:10:25.562 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
Created: Thu Nov 16 11:10:26.562 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.015
Created: Thu Nov 16 11:10:27.562 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.015
Created: Thu Nov 16 11:10:28.562 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.015
Created: Thu Nov 16 11:10:29.577 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.015
Created: Thu Nov 16 11:10:30.562 2023 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
從卦中的輸出來看,每一個 Created 大概差 1s 鐘,這也是 GateThread 的功勞,這種註入速度在 .NET8 中已經做了優化,比如上面這種情況,Task 內部會主動喚醒 GateThread 線程讓其立即註入新線程,從而提升程式的響應速度。
四:總結
很多時候分析下來發現是 第三方組件
拖垮了程式,自己又沒有太多的介入能力,真的很無奈,框架都用了那麼久,現在看到了一隻蒼蠅,已是食之無味,棄之可惜。