欢迎光临
我的个人博客网站

记一次 .NET 某化妆品 webapi 卡死分析


一:背景

1. 讲故事

10月份星球里的一位老朋友找到我,说他们公司的程序在一个网红直播带货下给弄得无响应了,无响应期间有大量的 RabbitMQ 超时,寻求如何找到根源,聊天截图我就不发了。

既然无响应了,那必然是程序的大量线程被主动或者被动的挂起,朋友也很及时的从程序上抽了一管血下来,接下来就上 windbg 一起探究下到底发生了什么?

二:Windbg 分析

1. 线程们都怎么了

要想看所有线程,还是老命令 !t

 0:000> !t ThreadCount:      5221 UnstartedThread:  0 BackgroundThread: 5199 PendingThread:    0 DeadThread:       21 Hosted Runtime:   no                                                                                                             Lock    DBG   ID     OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception   20    1     74e4 00000276CB778180  202a020 Preemptive  0000000000000000:0000000000000000 00000276cb77c9d0 -00001 MTA    31    2     42cc 00000276CB6CA830    2b220 Preemptive  0000000000000000:0000000000000000 00000276cb77c9d0 -00001 MTA (Finalizer)    32    3     2b40 00000276CB85D1B0  102a220 Preemptive  0000000000000000:0000000000000000 00000276cb77c9d0 -00001 MTA (Threadpool Worker)     2    6     bccc 00000276CBA5D2F0    20220 Preemptive  0000000000000000:0000000000000000 00000276cb77c9d0 -00001 Ukn    33    9     7224 00000276CBA5C0C0  3029220 Preemptive  0000000000000000:0000000000000000 00000276cb77c9d0 -00001 MTA (Threadpool Worker) System.IO.IOException 00000279ccc56cd0    9   23     29e0 0000027BD86FD180    20220 Preemptive  0000000000000000:0000000000000000 00000276cb77c9d0 -00001 Ukn  ...  

从简要信息看,当前有 5000+ 的线程,太牛了,一般一台机器的所有进程的线程加起来也没这么多。。。不过我目前看到最多的是 1w + 的线程 😂😂😂, 就是那种不用线程池,直接用 Thread 造成的一种线程垃圾。

可以看到线程列表中的 9号线程 抛了托管异常,接下来看看是个啥错误, 使用 !wpe 00000279ccc56cd0 命令。

 0:000> !wpe 00000279ccc56cd0 Address: 00000279ccc56cd0 Exception Type: System.IO.IOException Message: Unable to read data from the transport connection: 远程主机强迫关闭了一个现有的连接。. Inner Exception: 00000279ccc56b20 System.Net.Sockets.SocketException 远程主机强迫关闭了一个现有的连接。 Stack: SP               IP               Function 000000791b88c970 00007ffd844a1b31 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32) 000000791b88ee80 00007ffd849e6f8a System.IO.BufferedStream.ReadByteSlow() 000000791b88eeb0 00007ffd8312950a RabbitMQ.Client.Impl.InboundFrame.ReadFrom(System.IO.Stream, Byte[]) 000000791b88ef40 00007ffd849e6d7d RabbitMQ.Client.Framing.Impl.Connection.MainLoopIteration() 000000791b88efa0 00007ffd8312832f RabbitMQ.Client.Framing.Impl.Connection.MainLoop()  HResult: 80131620  

从堆栈信息来看,程序做了一个远程访问 RabbitMQ,结果 tcp 连接被对方关闭了,貌似和朋友说的有大量 RabbitMQ 超时有关。

接下来就是查看各个线程栈,研究下此时这些线程都在干什么,使用 ~*e !clrstack 命令,通过仔细研读线程栈,我发现有大量的方法卡在 xxx.RabbitMq.RabbitMqConnection.GetInstance 方法处。

         Child SP               IP Call Site 0000008B8A9ED6A8 00007ffdf5246594 [HelperMethodFrame_1OBJ: 0000008b8a9ed6a8] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef) 0000008B8A9ED800 00007ffd84a6a4a9 xxx.RabbitMq.RabbitMqConnection.GetInstance(Microsoft.Extensions.Options.IOptions`1<xxx.RabbitMq.RabbitMqConfig>, Microsoft.Extensions.Logging.ILogger`1<System.Object>) 0000008B8A9ED860 00007ffd84a6a317 xxx.RabbitMq.RabbitMqProducer..ctor(Microsoft.Extensions.Options.IOptionsSnapshot`1<xxx.RabbitMq.RabbitMqConfig>, Microsoft.Extensions.Logging.ILogger`1<xxx.RabbitMq.RabbitMqProducer>) 0000008B8A9ED8A0 00007ffd8334817b DynamicClass.ResolveService(ILEmitResolverBuilderRuntimeContext, Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope) 0000008B8A9ED930 00007ffd83347d76 DynamicClass.ResolveService(ILEmitResolverBuilderRuntimeContext, Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngineScope) 0000008B8A9EDE90 00007ffd844f3cb3 Microsoft.Extensions.DependencyInjection.ActivatorUtilities.GetService(System.IServiceProvider, System.Type, System.Type, Boolean) [/_/src/libraries/Common/src/Extensions/ActivatorUtilities/ActivatorUtilities.cs @ 173] DynamicClass.lambda_method196(System.Runtime.CompilerServices.Closure, System.IServiceProvider, System.Object[]) 0000008B8A9EDF20 00007ffd84a0fc9c Microsoft.AspNetCore.Mvc.Controllers.ControllerFactoryProvider+c__DisplayClass5_0.g__CreateController|0(Microsoft.AspNetCore.Mvc.ControllerContext) 0000008B8A9EDF70 00007ffd8452ce7f Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State ByRef, Scope ByRef, System.Object ByRef, Boolean ByRef) [/_/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs @ 285] 0000008B8A9EE030 00007ffd84a0fac8 Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync() [/_/src/Mvc/Mvc.Core/src/Infrastructure/ControllerActionInvoker.cs @ 490] 0000008B8A9EE0B0 00007ffd845346cd Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State ByRef, Scope ByRef, System.Object ByRef, Boolean ByRef) [/_/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs @ 883] 0000008B8A9EE240 00007ffd84a0f9ad Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextExceptionFilterAsync() [/_/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs @ 1024] 0000008B8A9EE2C0 00007ffd84534272 Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State ByRef, Scope ByRef, System.Object ByRef, Boolean ByRef) [/_/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs @ 883] 0000008B8A9EE450 00007ffd84a0f850 Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeNextResourceFilter() [/_/src/Mvc/Mvc.Core/src/Infrastructure/ResourceInvoker.cs @ 976] ...  

从调用栈信息看,源头是一个http请求,然后在 GetInstance 下的 lock 处被冻结,这就激发了我很大的好奇心,接下来根据 IP 导出源码看看。

 public sealed class RabbitMqConnection {     public static RabbitMqConnection GetInstance(IOptions<RabbitMqConfig> options, ILogger<dynamic> logger)     {         if (_uniqueInstance == null || _uniqueInstance.Connection == null || !_uniqueInstance.Connection.IsOpen)         {             lock (_objLock)             {                 if (_uniqueInstance == null || _uniqueInstance.Connection == null || !_uniqueInstance.Connection.IsOpen)                 {                     _uniqueInstance = new RabbitMqConnection(options.Value, logger);                 }             }         }         return _uniqueInstance;     }  	private RabbitMqConnection(RabbitMqConfig config, ILogger<dynamic> logger) 	{ 		Policy.Handle<SocketException>().Or<BrokerUnreachableException>().WaitAndRetry(6, (int retryAttempt) => TimeSpan.FromSeconds(1.0), delegate (Exception ex, TimeSpan time, int retryCount, Context content) 		{ 			if (6 == retryCount) 			{ 				throw ex; 			} 			_logger.LogError(ex, $"{retryCount}:{ex.Message}"); 		}) 			.Execute(delegate 			{ 				Connection = factory.CreateConnection(); 			}); 	} }  

从代码逻辑看,朋友用了 双检锁 来给 RabbitMQ 实例做单例化,如果实例创建失败还会有 6 次 1s 的尝试,这种写法乍一看没什么问题。

2. 单例写法真的没问题吗

如果单例写法没问题的话,为什么有大量的线程卡在 lock 处呢? 既然是 单例 那肯定是 rabbitmq 第一次被实例化后,后人直接乘凉就好了哈,带着这个疑问再次检查 双检索 写法,尼玛,在判断单例的时候居然做了 _uniqueInstance.Connection.IsOpen 判断,大家知道这意味着什么吗?

这意味着,一旦 rabbitmq 在某个时刻挂掉了,单例条件就被破防了,无数的线程排队来做 RabbimtMQ 的实例化,要知道这都是些不实例出来不罢休的勇士,继而导致程序挂死…🤣🤣🤣

3. 验证我的想法

既然从源码中推出了这个代码缺陷,但口说无凭,我得拿出证据,要想验证很简单,到托管堆寻找 RabbitMqConnection 实例,看下此时它的 IsOpen 是不是 false 即可, 通过 ILSpy 查看源码发现它是用 CloseReason==null 来判断的。

记一次 .NET 某化妆品 webapi 卡死分析

接下来看看 CloseReason 不为空即可。

 0:000> !dumpheap -type RabbitMqConnection          Address               MT     Size 00000277cbd7aa68 00007ffd831f1570       32   00000277ccb13068 00007ffd831f1570       32     0:000> !DumpObj /d 00000277cbd7b858 Name:        RabbitMQ.Client.Framing.Impl.AutorecoveringConnection MethodTable: 00007ffd83235db0 EEClass:     00007ffd83242898 Size:        200(0xc8) bytes File:        G:xxxRabbitMQ.Client.dll Fields:               MT    Field   Offset                 Type VT     Attr            Value Name 00007ffd82397238  4000180       bc       System.Boolean  1 instance                0 _disposed 00007ffd82390c68  4000181        8        System.Object  0 instance 00000277cbd7b920 _eventLock 00007ffd831fc230  4000182       10 ...g.Impl.Connection  0 instance 00000277cbd7d5f8 _delegate  0:000> !DumpObj /d 00000277cbd7d5f8 Name:        RabbitMQ.Client.Framing.Impl.Connection MethodTable: 00007ffd831fc230 EEClass:     00007ffd8322cd70 Size:        232(0xe8) bytes File:        G:xxxRabbitMQ.Client.dll Fields:               MT    Field   Offset                 Type VT     Attr            Value Name 00007ffd82397238  4000198       b8       System.Boolean  1 instance                0 _disposed 00007ffd82390c68  4000199        8        System.Object  0 instance 00000277cbd7d6e0 _eventLock 00007ffd82d93d00  400019a       10 ...ualResetEventSlim  0 instance 00000277cbd7d6f8 _appContinuation 00007ffd83276028  400019b       18 ...ShutdownEventArgs  0 instance 00000279ccc56e28 _closeReason  0:000> !do 00000277ccb13068 Name:        xxx.RabbitMq.RabbitMqConnection MethodTable: 00007ffd831f1570 EEClass:     00007ffd831eb920 Size:        32(0x20) bytes File:        G:xxxxxx.dll Fields:               MT    Field   Offset                 Type VT     Attr            Value Name 00007ffd831f13f8  400001f        8 ...Private.CoreLib]]  0 instance 00000278cbe4c2a0 _logger 00007ffd831f2ab0  4000020       10 ...lient.IConnection  0 instance 0000000000000000 <Connection>k__BackingField 00007ffd831f1570  400001d        8 ...abbitMqConnection  0   static 00000277cbd7aa68 _uniqueInstance 00007ffd82390c68  400001e       10        System.Object  0   static 00000277cbd7aa50 _objLock  

从输出信息中可以很清楚的看到当前托管堆有两个 RabbitMqConnection 对象,其中一个果然是失败了(_closeReason=00000279ccc56e28),还有一个正在努力的new <Connection>k__BackingField=0000000000000000, 这也就验证了假设。

4. 后续

有了这些信息,和朋友做了下沟通,建议再优化一下 IsOpen=false 时的异常处理逻辑,比如 return 或者 throw new,或者干脆不要用懒检测, 千万不要硬着来。

至于造成 RabbitMQ 不响应的一系列诱因,朋友通过参考的开源项目,发现将别人的 AddSingleton 改成了 AddScoped

记一次 .NET 某化妆品 webapi 卡死分析

这也就造成了每一次Http请求都要试探性的判断单例逻辑, 别人的解法是一旦上层单例化了,下层就不会再次处理了,也就不会走 IsOpen 逻辑。

三:总结

造成本次程序卡死的事故,主要有两点:

  1. RabbitMQ 生成单例化中的 IsOpen 判断问题,建议改用自动重连属性 AutomaticRecoveryEnabledTopologyRecoveryEnabled,或者用静态构造函数替代双检锁

  2. 过多的 http 请求对单例逻辑的试探,按照朋友的改发将 Scoped 改成 Singleton 来规避。

记一次 .NET 某化妆品 webapi 卡死分析

赞(0) 打赏
未经允许不得转载:张拓的天空 » 记一次 .NET 某化妆品 webapi 卡死分析
分享到: 更多 (0)

评论 抢沙发

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址

专业的IT技术经验分享 更专业 更方便

联系我们本站主机

觉得文章有用就打赏一下文章作者

支付宝扫一扫打赏

微信扫一扫打赏