記一次 .NET 某電商無貨源後端服務死鎖分析

一線碼農發表於2021-11-18

後端

一：背景

1. 講故事

這個月初，星球裡的一位朋友找到我，說他的程式出現了死鎖，懷疑是自己的某些寫法導致mongodb出現瞭如此尷尬的情況，截圖如下：

說實話，看過這麼多dump，還是第一次遇到真實的死鎖，這tmd的頓時就有了興趣。。。上 windbg 說話。

二：Windbg 分析

1. 真的是死鎖嗎

既然朋友說死鎖，我得先驗證一下,可以用命令 !syncblk 檢視同步塊表。


0:000> !syncblk
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner
   97 000000F7B77CA1B8          107         1 000000F7D37A7210 8848  25   000000f7b853d480 System.Object
  144 000000F7D39BA2A8          495         1 000000F7DA4CDA70 75e0  63   000000f7b853de48 System.Object
-----------------------------
Total           603
CCW             1
RCW             1
ComClassFactory 0
Free            490

從同步塊表中可得知如下資訊。

25號執行緒正持有 000000f7b853d480 鎖物件。
63號執行緒正持有 000000f7b853de48 鎖物件。

我們知道所謂的 死鎖 就是兩個執行緒都渴望得到對方持有的鎖資源，誰也不讓步所造成的一種僵局，如果不明白，我就畫一張圖：

上圖就是一種死鎖的僵局，順便提一下，在 sqlserver 中也常會遇到這種情況，那它會怎麼處理的呢？這就有點意思了，sqlserver 內部有一個調停的執行緒週期性執行，當檢測到這種死鎖僵局的時候，它會把優先順序低的執行緒kill掉，這樣另外一個執行緒就能順利獲取鎖，被 kill 掉的執行緒就會出現如下異常資訊：


System.Data.SqlClient.SqlException (0x80131904): 事務(程式 ID 112)與另一個程式被死鎖在 鎖 | 通訊緩衝區 資源上，並且已被選作死鎖犧牲品。請重新執行該事務。
   在 System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   在 System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   在 System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   在 System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   在 System.Data.SqlClient.SqlCommand.RunExecuteNonQueryTds(String methodName, Boolean async, Int32 timeout)
   在 System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean asyncWrite)
   在 System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
   在 Microsoft.ApplicationBlocks.Data.SqlHelper.ExecuteNonQuery(SqlConnection connection, CommandType commandType, String commandText, SqlParameter[] commandParameters)
   在 Microsoft.ApplicationBlocks.Data.SqlHelper.ExecuteNonQuery(String connectionString, CommandType commandType, String commandText, SqlParameter[] commandParameters)

哈哈，是不是似曾相識，好了，對死鎖有了一定認識之後，我們假設一下，如果存在

25號執行緒想獲取 000000f7b853de48 鎖物件。
63號執行緒想獲取 000000f7b853d480 鎖物件。

的情況下，必然就會死鎖，對吧，接下來怎麼用 windbg 驗證呢？切到 25 號執行緒檢視執行緒棧及棧物件。


0:000> ~25s
ntdll!NtWaitForMultipleObjects+0xa:
00007ffb`9f230c7a c3              ret

0:025> !clrstack 
OS Thread Id: 0x8848 (25)
        Child SP               IP Call Site
000000F782904838 00007ffb9f230c7a [HelperMethodFrame_1OBJ: 000000f782904838] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
000000F782904990 00007ffb1d5e4d5c MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder.Acquire()

0:025> !dso
OS Thread Id: 0x8848 (25)
RSP/REG          Object           Name
000000F782904648 000000f7b853de48 System.Object
000000F7829046D8 000000f7b84cb508 MongoDB.Driver.ReadPreference

可以清楚的看到 ReliableEnter 正在獲取 000000f7b853de48 鎖物件時被卡住，再切到 63號執行緒檢視。


0:025> ~63s
ntdll!NtWaitForMultipleObjects+0xa:
00007ffb`9f230c7a c3              ret
0:063> !clrstack 
OS Thread Id: 0x75e0 (63)
        Child SP               IP Call Site
000000F787774EE8 00007ffb9f230c7a [HelperMethodFrame_1OBJ: 000000f787774ee8] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
000000F787775040 00007ffb1d5e4d5c MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder.Acquire()
0:063> !dso
OS Thread Id: 0x75e0 (63)
RSP/REG          Object           Name
000000F787774A38 000000f7b82dc750 MongoDB.Bson.BsonBoolean
000000F787774BA0 000000f7b83a9a10 System.RuntimeType
000000F787774CF8 000000f7b853d480 System.Object

可以清楚的看到 ReliableEnter 正在獲取 000000f7b853d480，這就表明確實產生了死鎖，沒毛病。

2. 死鎖原因分析

要想追究死鎖的原因，只能仔細推敲 執行緒棧 + 執行緒棧物件。


0:063> !clrstack 
OS Thread Id: 0x75e0 (63)
        Child SP               IP Call Site
000000F787774EE8 00007ffb9f230c7a [HelperMethodFrame_1OBJ: 000000f787774ee8] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
000000F787775040 00007ffb1d5e4d5c MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder.Acquire()
...
000000F78777BD10 00007ffb1e2fc69f System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean) [/_/src/System.Private.CoreLib/shared/System/Threading/CancellationTokenSource.cs @ 724]
000000F78777BDA0 00007ffb1e2fc69f System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean) [/_/src/System.Private.CoreLib/shared/System/Threading/CancellationTokenSource.cs @ 724]
000000F78777BE30 00007ffb1e2fc69f System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean) [/_/src/System.Private.CoreLib/shared/System/Threading/CancellationTokenSource.cs @ 724]
000000F78777BEC0 00007ffb1e325d55 MongoDB.Driver.Core.Misc.SemaphoreSlimSignalable.Signal()
000000F78777BF10 00007ffb1e35b98e MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder.Return(PooledConnection)
000000F78777BF70 00007ffb1e35b728 MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool.ReleaseConnection(PooledConnection)
000000F78777C0A0 00007ffb1e35b4f9 MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+AcquiredConnection.Dispose()
000000F78777C0D0 00007ffb1e384164 MongoDB.Driver.Core.Operations.RetryableReadContext.Dispose()
000000F78777C100 00007ffb1e37ee31 MongoDB.Driver.Core.Operations.FindOperation`1+d__120[[System.__Canon, System.Private.CoreLib]].MoveNext()
...
000000F78777E980 00007ffb1dd807bf System.Net.Sockets.Socket+AwaitableSocketAsyncEventArgs.InvokeContinuation(System.Action`1<System.Object>, System.Object, Boolean, Boolean) [/_/src/System.Net.Sockets/src/System/Net/Sockets/Socket.Tasks.cs @ 1019]
000000F78777E9F0 00007ffb1dd80519 System.Net.Sockets.Socket+AwaitableSocketAsyncEventArgs.OnCompleted(System.Net.Sockets.SocketAsyncEventArgs) [/_/src/System.Net.Sockets/src/System/Net/Sockets/Socket.Tasks.cs @ 858]
000000F78777EA50 00007ffb1dd7f751 System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*) [/_/src/System.Private.CoreLib/src/System/Threading/Overlapped.cs @ 59]

0:063> !dso
OS Thread Id: 0x75e0 (63)
RSP/REG          Object           Name
000000F787774A38 000000f7b82dc750 MongoDB.Bson.BsonBoolean
000000F787774BA0 000000f7b83a9a10 System.RuntimeType
000000F787774CF8 000000f7b853d480 System.Object
...
000000F78777B658 000000f7be3407c8 System.String    OperationCanceled
000000F78777B670 000000f7b82c07e0 System.Resources.RuntimeResourceSet
000000F78777B698 000000f7b82bff38 System.Globalization.CultureInfo
000000F78777B730 000000f7a36525c8 System.Char[]
000000F78777B7E0 000000f7be3407c8 System.String    OperationCanceled
...
000000F78777BEF8 000000f7b853de10 MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder
000000F78777BF10 000000f79f79e398 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[MongoDB.Driver.IAsyncCursor`1[[Czkj.AlibabaTools.Models.mongo.CopyRecords, Czkj.AlibabaTools.Models]], MongoDB.Driver.Core],[MongoDB.Driver.Core.Operations.FindOperation`1+<ExecuteAsync>d__120[[Czkj.AlibabaTools.Models.mongo.CopyRecords, Czkj.AlibabaTools.Models]], MongoDB.Driver.Core]]
000000F78777BF40 000000f7b853de48 System.Object
...

由於這程式碼到處都是 await,async ，所以看這反編譯後的執行緒棧真的頭大，經過仔細比對，發現程式碼流程大概是：

從處理 Mongodb 的非同步請求回撥開始 (System.Threading.OverlappedData)。
在 MongoDB.Driver.Core.Operations.FindOperation 時不知為啥拋了取消異常 OperationCanceled，然後呼叫 RetryableReadContext.Dispose()。

在 ListConnectionHolder.Return() 方法中獲取 000000f7b853de48 鎖物件。

在 SignalOrReset() -> SemaphoreSlimSignalable.Signal() 方法中執行一些註冊handler邏輯。

注意：在事件觸發中並沒有退出 lock 區域。

在幾個handler痙攣過程中進入了另外一個執行緒池的 ListConnectionHolder.Acquire() 方法中，希望能得到該池中的 000000f7b853d480 鎖物件。

同時 25號執行緒正在反向做這個操作，由於大家都是雙重 lock，所以最終導致死鎖的發生。

三：有幾個需要解答的問題

1. 為什麼會有兩個執行緒池？

從執行緒棧物件看，應該也看到了有兩個執行緒池 ExclusiveConnectionPool。


0:000> !dumpheap -type ExclusiveConnectionPool -stat
Statistics:
              MT    Count    TotalSize Class Name
00007ffb1d25eca0        2          464 MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool

這是由於朋友的 mongodb 連線串 用的是雙IP的副本集模式。


{
  "mongo": {
    "Connection": "mongodb://xxx.aliyuncs.com:3717,xxx.aliyuncs.com:3717/admin?replicaSet=mgset-500180544&readPreference=secondaryPreferred&maxPoolSize=1000&wtimeoutMS=10000"
  }
}

2. 是程式設計師的鍋嗎？

從堆疊資訊看並不是程式設計師的鍋，是 mongodb 在接收非同步回撥時，由於某種情況發生了 OperationCanceled 異常，面對異常的後續處理邏輯時出現了死鎖bug。

3. 當前的 mognodb sdk版本是多少？

這個mongodb 官方驅動是 2.13.1.0，也就是 2021-8-15 釋出的，截至最新的是 10月份釋出的 2.13.2.0。

4. 反饋

瞭解這些資訊後，和朋友做了溝通，朋友說他給 mongodb 社群提交 issue，幾天後，官方給的回答是在最新的 v2.14.beta1 中做了處理。

也就是說在未來的 release v2.14.0 版本中會得到解決，目前也只能等一等啦！期待中。。。哈哈???

四：總結

總的來說，這是 mongodb 底層的一個 bug 導致的死鎖問題，dump的分析過程也幾經波折，雖是官方權威的 MongoDB.Driver 包，但同樣值得懷疑，而不要一味的深深懷疑自己... 最後期待即將釋出的 release v2.14.0 吧。

記一次 .NET 某HIS系統後端服務記憶體洩漏分析
2021-05-21
後端記憶體
記一次 .NET 某裝置監控系統死鎖分析
2023-04-06
記一次 .NET 某智慧交通後臺服務 CPU爆高分析
2022-01-28
記一次 .NET 某消防物聯網後臺服務記憶體洩漏分析
2022-01-12
記憶體
記一次 .NET 某雲採購平臺API 掛死分析
2021-07-28
API
記一次 .NET 某電商交易平臺Web站 CPU爆高分析
2021-05-28
Web
記一次 .NET 某電力系統記憶體暴漲分析
2023-09-18
記憶體
記一次 .NET 車聯網雲端服務 CPU爆高分析
2021-05-19
記一次 .NET 某工控電池檢測系統卡死分析
2023-11-13
記一次 .NET 某電廠Web系統記憶體洩漏分析
2022-07-14
Web記憶體
記一次 .NET 某藥廠業務系統 CPU爆高分析
2023-12-20
記一次 .NET 某智慧服裝智造系統記憶體洩漏分析
2021-12-01
記憶體
記一次 .NET 某工控MES程式崩潰分析
2022-12-16
記一次 .NET 某化妝品 webapi 卡死分析
2021-12-06
WebAPI
MySQL升級WRITE_SET後的一次死鎖分析
2020-02-12
MySql
記一次 .NET 某券商論壇系統卡死分析
2023-11-14
記一次 .NET 某外貿ERP 記憶體暴漲分析
2023-04-23
記憶體
記一次 .NET 某工控軟體記憶體洩露分析
2022-12-06
記憶體洩露
記一次線上mysql死鎖
2021-10-10
MySql
記一次Oracle死鎖/阻塞排查
2019-01-15
Oracle
記一次 .NET 某電子廠OA系統非託管記憶體洩露分析
2022-12-02
記憶體洩露
記一次 .NET WPF布草管理系統掛死分析
2021-04-27
記一次 .NET 某拍攝監控軟體卡死分析
2023-09-26
記一次 .NET 某醫院門診軟體卡死分析
2023-05-15
記一次 .NET某醫療器械清洗系統卡死分析
2023-04-18
記一次 .NET 某醫保平臺 CPU 爆高分析
2023-02-21
記一次 .NET 某遊戲網站 CPU爆高分析
2023-02-13
遊戲網站
記一次 .NET 某資訊論壇 CPU爆高分析
2021-10-27
記一次 .NET 某餐飲小程式記憶體暴漲分析
2023-09-21
記憶體
記一次 .NET 某外貿Web站記憶體洩漏分析
2021-09-09
Web記憶體
記一次 WinDbg 分析 .NET 某工廠MES系統記憶體洩漏分析
2022-01-10
記憶體
記一次神奇的Mysql死鎖排查
2019-02-27
MySql
記一次 .NET某裝潢ERP系統記憶體暴漲分析
2023-02-27
記憶體
記一次 .NET 某風控管理系統記憶體洩漏分析
2021-11-02
記憶體
記一次 .NET 某婦產醫院 WPF記憶體溢位分析
2021-12-10
記憶體溢位
記一次 .NET某新能源檢測系統崩潰分析
2023-10-16
記一次 .NET 某公交卡扣費系統程式卡死分析
2021-11-15
記一次 .NET 某旅行社Web站 CPU爆高分析
2021-05-17
Web

記一次 .NET 某電商無貨源後端服務 死鎖分析