萬萬沒想到，一個 MongoDB.Driver 的 bug 導致 .NET5 程式死鎖！

一線碼農發表於2021-11-22
MongoDB

一：背景

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

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

  1. 25號執行緒正持有 000000f7b853d480 鎖物件。
  2. 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)

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

  1. 25號執行緒想獲取 000000f7b853de48 鎖物件。
  2. 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 ，所以看這反編譯後的執行緒棧真的頭大，經過仔細比對，發現程式碼流程大概是：

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

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

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

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

  1. 在幾個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 吧。

相關文章