[[438682]]

一、背景

1. 講故事

10月份星球里的一位老朋友找到我，說(shuō)他們公司的程序在一個(gè)網(wǎng)紅直播帶貨下給弄得無(wú)響應(yīng)了，無(wú)響應(yīng)期間有大量的 RabbitMQ 超時(shí)，尋求如何找到根源，聊天截圖我就不發(fā)了。

既然無(wú)響應(yīng)了，那必然是程序的大量線(xiàn)程被主動(dòng)或者被動(dòng)的掛起，朋友也很及時(shí)的從程序上抽了一管血下來(lái)，接下來(lái)就上 windbg 一起探究下到底發(fā)生了什么?

二、Windbg 分析

1. 線(xiàn)程們都怎么了

要想看所有線(xiàn)程，還是老命令 !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  
... 

從簡(jiǎn)要信息看，當(dāng)前有 5000+ 的線(xiàn)程，太牛了，一般一臺(tái)機(jī)器的所有進(jìn)程的線(xiàn)程加起來(lái)也沒(méi)這么多。。。不過(guò)我目前看到最多的是 1w + 的線(xiàn)程 ??????， 就是那種不用線(xiàn)程池，直接用 Thread 造成的一種線(xiàn)程垃圾。

可以看到線(xiàn)程列表中的 9號(hào)線(xiàn)程 拋了托管異常，接下來(lái)看看是個(gè)啥錯(cuò)誤, 使用 !wpe 00000279ccc56cd0 命令。

0:000> !wpe 00000279ccc56cd0 
Address: 00000279ccc56cd0 
Exception Type: System.IO.IOException 
Message: Unable to read data from the transport connection: 遠(yuǎn)程主機(jī)強(qiáng)迫關(guān)閉了一個(gè)現(xiàn)有的連接。. 
Inner Exception: 00000279ccc56b20 System.Net.Sockets.SocketException 遠(yuǎn)程主機(jī)強(qiáng)迫關(guān)閉了一個(gè)現(xiàn)有的連接。 
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 

從堆棧信息來(lái)看，程序做了一個(gè)遠(yuǎn)程訪(fǎng)問(wèn) RabbitMQ，結(jié)果 tcp 連接被對(duì)方關(guān)閉了，貌似和朋友說(shuō)的有大量 RabbitMQ 超時(shí)有關(guān)。

接下來(lái)就是查看各個(gè)線(xiàn)程棧，研究下此時(shí)這些線(xiàn)程都在干什么，使用 ~*e !clrstack 命令，通過(guò)仔細(xì)研讀線(xiàn)程棧，我發(fā)現(xiàn)有大量的方法卡在 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] 
... 

從調(diào)用棧信息看，源頭是一個(gè)http請(qǐng)求，然后在 GetInstance 下的 lock 處被凍結(jié)，這就激發(fā)了我很大的好奇心，接下來(lái)根據(jù) IP 導(dǎo)出源碼看看。

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

從代碼邏輯看，朋友用了 雙檢鎖 來(lái)給 RabbitMQ 實(shí)例做單例化，如果實(shí)例創(chuàng)建失敗還會(huì)有 6 次 1s 的嘗試，這種寫(xiě)法乍一看沒(méi)什么問(wèn)題。

2. 單例寫(xiě)法真的沒(méi)問(wèn)題嗎

如果單例寫(xiě)法沒(méi)問(wèn)題的話(huà)，為什么有大量的線(xiàn)程卡在 lock 處呢?既然是 單例 那肯定是 rabbitmq 第一次被實(shí)例化后，后人直接乘涼就好了哈，帶著這個(gè)疑問(wèn)再次檢查 雙檢索 寫(xiě)法，尼瑪，在判斷單例的時(shí)候居然做了 _uniqueInstance.Connection.IsOpen 判斷，大家知道這意味著什么嗎?

這意味著，一旦 rabbitmq 在某個(gè)時(shí)刻掛掉了，單例條件就被破防了，無(wú)數(shù)的線(xiàn)程排隊(duì)來(lái)做 RabbimtMQ 的實(shí)例化，要知道這都是些不實(shí)例出來(lái)不罷休的勇士，繼而導(dǎo)致程序掛死...??????

3. 驗(yàn)證我的想法

既然從源碼中推出了這個(gè)代碼缺陷，但口說(shuō)無(wú)憑，我得拿出證據(jù)，要想驗(yàn)證很簡(jiǎn)單，到托管堆尋找 RabbitMqConnection 實(shí)例，看下此時(shí)它的 IsOpen 是不是 false 即可, 通過(guò) ILSpy 查看源碼發(fā)現(xiàn)它是用 CloseReason==null 來(lái)判斷的。

接下來(lái)看看 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:\xxx\RabbitMQ.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:\xxx\RabbitMQ.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:\xxx\xxx.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 

從輸出信息中可以很清楚的看到當(dāng)前托管堆有兩個(gè) RabbitMqConnection 對(duì)象，其中一個(gè)果然是失敗了(_closeReason=00000279ccc56e28)，還有一個(gè)正在努力的new k__BackingField=0000000000000000， 這也就驗(yàn)證了假設(shè)。

4. 后續(xù)

有了這些信息，和朋友做了下溝通，建議再優(yōu)化一下 IsOpen=false 時(shí)的異常處理邏輯，比如 return 或者 throw new，或者干脆不要用懶檢測(cè)， 千萬(wàn)不要硬著來(lái)。

至于造成 RabbitMQ 不響應(yīng)的一系列誘因，朋友通過(guò)參考的開(kāi)源項(xiàng)目，發(fā)現(xiàn)將別人的 AddSingleton 改成了 AddScoped。

這也就造成了每一次Http請(qǐng)求都要試探性的判斷單例邏輯, 別人的解法是一旦上層單例化了，下層就不會(huì)再次處理了，也就不會(huì)走 IsOpen 邏輯。

三、總結(jié)

造成本次程序卡死的事故，主要有兩點(diǎn)：

• RabbitMQ 生成單例化中的 IsOpen 判斷問(wèn)題，建議改用自動(dòng)重連屬性 AutomaticRecoveryEnabled 和 TopologyRecoveryEnabled，或者用靜態(tài)構(gòu)造函數(shù)替代雙檢鎖。 
• 過(guò)多的 http 請(qǐng)求對(duì)單例邏輯的試探，按照朋友的改發(fā)將 Scoped 改成 Singleton 來(lái)規(guī)避。

本文轉(zhuǎn)載自微信公眾號(hào)「一線(xiàn)碼農(nóng)聊技術(shù)」，可以通過(guò)以下二維碼關(guān)注。轉(zhuǎn)載本文請(qǐng)聯(lián)系一線(xiàn)碼農(nóng)聊技術(shù)公眾號(hào)。