停了一个月没有更新文章了,主要是忙于写 C#内功修炼系列的PPT
,现在基本上接近尾声,可以回头继续更新这段时间分析dump的一些事故报告,有朋友微信上找到我,说他们的系统出现了大量的http超时,程序不响应处理了,让我帮忙看下怎么回事,dump也抓到了。
既然超时说明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个 待处理的任务。
线程饥饿的原因有更多,我特意问了下 chatgpt,列举如下:
那到底是哪一种情况呢?可以用 ~*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请求
,在这异步方法满天飞的世界里,上面的写法实属异类。
既然是 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")]
哈哈,不用它,这是万能的治根之法。
我现在知道这个 url 某个时段可能响应出了问题,但我线程池里的线程增速应该很快呀,多余的线程不是可以响应客户端请求吗?为什么我发现的情况是全部卡死呢?
这个问题其实是考察对线程池底层的了解,尤其是多久会向线程池注入一个活线程,在 .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 线程让其立即注入新线程,从而提升程序的响应速度。
很多时候分析下来发现是 第三方组件
拖垮了程序,自己又没有太多的介入能力,真的很无奈,框架都用了那么久,现在看到了一只苍蝇,已是食之无味,弃之可惜。