沒想到，錯誤的單例寫法，讓 RabbitMQ 大量超時導致程序掛死！
作者：一線碼農聊技術
既然無響應了，那必然是程序的大量線程被主動或者被動的掛起，朋友也很及時的從程序上抽了一管血下來，接下來就上 windbg 一起探究下到底發生了什么?
一、背景
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 來判斷的。
接下來看看 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
從輸出信息中可以很清楚的看到當前托管堆有兩個 RabbitMqConnection 對象，其中一個果然是失敗了(_closeReason=00000279ccc56e28)，還有一個正在努力的new k__BackingField=0000000000000000， 這也就驗證了假設。
4. 后續
有了這些信息，和朋友做了下溝通，建議再優化一下 IsOpen=false 時的異常處理邏輯，比如 return 或者 throw new，或者干脆不要用懶檢測， 千萬不要硬著來。
至于造成 RabbitMQ 不響應的一系列誘因，朋友通過參考的開源項目，發現將別人的 AddSingleton 改成了 AddScoped。
這也就造成了每一次Http請求都要試探性的判斷單例邏輯, 別人的解法是一旦上層單例化了，下層就不會再次處理了，也就不會走 IsOpen 邏輯。
三、總結
造成本次程序卡死的事故，主要有兩點：
- RabbitMQ 生成單例化中的 IsOpen 判斷問題，建議改用自動重連屬性 AutomaticRecoveryEnabled 和 TopologyRecoveryEnabled，或者用靜態構造函數替代雙檢鎖。
- 過多的 http 請求對單例邏輯的試探，按照朋友的改發將 Scoped 改成 Singleton 來規避。
本文轉載自微信公眾號「一線碼農聊技術」，可以通過以下二維碼關注。轉載本文請聯系一線碼農聊技術公眾號。
責任編輯：武曉燕
來源：
一線碼農聊技術
