一、背景

1. 講故事

停了一個月沒有更新文章了，主要是忙于寫 C#內(nèi)功修煉系列的PPT，現(xiàn)在基本上接近尾聲，可以回頭繼續(xù)更新這段時間分析dump的一些事故報告，有朋友微信上找到我，說他們的系統(tǒng)出現(xiàn)了大量的http超時，程序不響應(yīng)處理了，讓我?guī)兔聪略趺椿厥拢琩ump也抓到了。6od28資訊網(wǎng)——每日最新資訊28at.com

二、WinDbg分析

1. 為什么會出現(xiàn)請求超時

既然超時說明server端不響應(yīng)這個請求，繼而達到了超時時間的一種異常情況，所以首先要想到的就是 線程池的健康度，可以用 !tp 命令觀察，輸出如下：6od28資訊網(wǎng)——每日最新資訊28at.com

0:000> !tpCPU utilization: 0%Worker Thread: Total: 537 Running: 537 Idle: 0 MaxLimit: 32767 MinLimit: 12Work 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個工作線程都是處于運行狀態(tài)，相信有經(jīng)驗的朋友應(yīng)該一眼就知道是怎么回事，專業(yè)術(shù)語叫：線程饑餓，并且線程池隊列也積壓了 82個 待處理的任務(wù)。6od28資訊網(wǎng)——每日最新資訊28at.com

2. 線程為什么會饑餓

線程饑餓的原因有更多，我特意問了下 chatgpt，列舉如下：6od28資訊網(wǎng)——每日最新資訊28at.com

• 優(yōu)先級傾斜：如果某些線程的優(yōu)先級設(shè)置過高，而其他線程的優(yōu)先級設(shè)置過低，高優(yōu)先級的線程可能會長時間占用CPU資源，導致低優(yōu)先級線程無法獲得執(zhí)行機會。
• 死鎖：當多個線程相互等待對方釋放資源時，可能會導致死鎖。在死鎖情況下，所有線程都無法繼續(xù)執(zhí)行，從而導致線程饑餓。
• 資源競爭：多個線程競爭有限的資源（如共享內(nèi)存、文件、網(wǎng)絡(luò)連接等）時，可能會導致某些線程長時間無法獲取到所需的資源而處于饑餓狀態(tài)。
• 不公平的調(diào)度策略：調(diào)度器可能存在不公平的調(diào)度策略，導致某些線程無法獲得公平的CPU時間片，從而長時間無法執(zhí)行。
• 線程阻塞：某些線程可能由于等待I/O操作、鎖或其他原因而被阻塞，如果阻塞時間過長，可能導致其他線程饑餓。
• 線程池配置不當：如果線程池中的線程數(shù)量設(shè)置不當，可能會導致某些任務(wù)長時間等待執(zhí)行，從而引發(fā)線程饑餓。

那到底是哪一種情況呢？可以用 ~*e !clrstack 看一下各個線程此時正在做什么，輸出如下：6od28資訊網(wǎng)——每日最新資訊28at.com

0:000> ~*e !clrstack...OS Thread Id: 0x2924 (74)        Child SP               IP Call Site000000e0ef47dc30 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] ...

發(fā)現(xiàn)有 473 個線程都在 Exceptionless.Submission.DefaultSubmissionClient.SendHeartbeat 方法上進行等待，這就有意思了，原來是開源的日志收集組件發(fā)送的心跳檢測方法，接下來趕緊看一下這個方法的源碼。6od28資訊網(wǎng)——每日最新資訊28at.com

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()); }}

從源碼看，居然用同步的方式發(fā)送 http請求，在這異步方法滿天飛的世界里，上面的寫法實屬異類。6od28資訊網(wǎng)——每日最新資訊28at.com

3. 該如何解決呢？

既然是 Exceptionless 內(nèi)部寫的 SendHeartbeat 方法，我們程序員基本上無法干預，能做到的無非如下兩點：6od28資訊網(wǎng)——每日最新資訊28at.com

• 升級框架

看下了用的還是超老的 4.3 版本，可以升級到目前最新的 6.0.4 觀察試試。6od28資訊網(wǎng)——每日最新資訊28at.com

[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")]

圖片6od28資訊網(wǎng)——每日最新資訊28at.com

• 使用替代品，或者不用

哈哈，不用它，這是萬能的治根之法。6od28資訊網(wǎng)——每日最新資訊28at.com

三、對線程注入速度的解答

1. 朋友提了一個疑問

我現(xiàn)在知道這個 url 某個時段可能響應(yīng)出了問題，但我線程池里的線程增速應(yīng)該很快呀，多余的線程不是可以響應(yīng)客戶端請求嗎？為什么我發(fā)現(xiàn)的情況是全部卡死呢？6od28資訊網(wǎng)——每日最新資訊28at.com

2. 疑問的簡單解答

這個問題其實是考察對線程池底層的了解，尤其是多久會向線程池注入一個活線程，在 .NET Framework 時代，在線程饑餓的情況下線程池內(nèi)部的 GateThread線程 會 1s 注入一個活線程，那如何驗證呢？我們觀察后續(xù)的線程創(chuàng)建時間即可，使用 ~*e .ttime 。6od28資訊網(wǎng)——每日最新資訊28at.com

0:000> ~*e .ttime...Created: Thu Nov 16 11:10:21.582 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.000Created: Thu Nov 16 11:10:22.593 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.000Created: Thu Nov 16 11:10:23.562 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.000Created: Thu Nov 16 11:10:24.062 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.000Created: Thu Nov 16 11:10:24.577 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.000Created: Thu Nov 16 11:10:25.562 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.000Created: Thu Nov 16 11:10:26.562 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.015Created: Thu Nov 16 11:10:27.562 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.015Created: Thu Nov 16 11:10:28.562 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.015Created: Thu Nov 16 11:10:29.577 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.015Created: Thu Nov 16 11:10:30.562 2023 (UTC + 8:00)Kernel:  0 days 0:00:00.000User:    0 days 0:00:00.000

從卦中的輸出來看，每一個 Created 大概差 1s 鐘，這也是 GateThread 的功勞，這種注入速度在 .NET8 中已經(jīng)做了優(yōu)化，比如上面這種情況，Task 內(nèi)部會主動喚醒 GateThread 線程讓其立即注入新線程，從而提升程序的響應(yīng)速度。6od28資訊網(wǎng)——每日最新資訊28at.com

四、總結(jié)

很多時候分析下來發(fā)現(xiàn)是 第三方組件 拖垮了程序，自己又沒有太多的介入能力，真的很無奈，框架都用了那么久，現(xiàn)在看到了一只蒼蠅，已是食之無味，棄之可惜。6od28資訊網(wǎng)——每日最新資訊28at.com

本文鏈接：http://www.tebozhan.com/showinfo-26-89402-0.html記一次 .NET 某酒店后臺服務(wù)卡死分析

聲明：本網(wǎng)頁內(nèi)容旨在傳播知識，若有侵權(quán)等問題請及時與本網(wǎng)聯(lián)系，我們將在第一時間刪除處理。郵件：2376512515@qq.com

上一篇： Python 高效編程的 15 個優(yōu)秀實踐

下一篇： 說到Python處理大數(shù)據(jù)集，別說你會用Pandas