摘要：的情況下，必然就會(huì)死鎖，對(duì)吧，接下來怎么用驗(yàn)證呢切到號(hào)線程查看線程棧及棧對(duì)象。死鎖原因分析死鎖原因分析要想追究死鎖的原因，只能仔細(xì)推敲線程棧線程棧對(duì)象。在幾個(gè)痙攣過程中進(jìn)入了另外一個(gè)線程池的方法中，希望能得到該池中的鎖對(duì)象。

一：背景

1. 講故事

這個(gè)月初，星球里的一位朋友找到我，說他的程序出現(xiàn)了死鎖，懷疑是自己的某些寫法導(dǎo)致mongodb出現(xiàn)了如此尷尬的情況，截圖如下：

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

二：Windbg 分析

1. 真的是死鎖嗎

既然朋友說死鎖，我得先驗(yàn)證一下,可以用命令 !syncblk 查看同步塊表。

0:000> !syncblkIndex         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           603CCW             1RCW             1ComClassFactory 0Free            490

從同步塊表中可得知如下信息。

1. 25號(hào)線程正持有 000000f7b853d480 鎖對(duì)象。

2. 63號(hào)線程正持有 000000f7b853de48 鎖對(duì)象。

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

上圖就是一種死鎖的僵局，順便提一下， 在 sqlserver 中也常會(huì)遇到這種情況，那它會(huì)怎么處理的呢？ 這就有點(diǎn)意思了，sqlserver 內(nèi)部有一個(gè)調(diào)停的線程周期性執(zhí)行，當(dāng)檢測(cè)到這種死鎖僵局的時(shí)候，它會(huì)把優(yōu)先級(jí)低的線程kill掉，這樣另外一個(gè)線程就能順利獲取鎖，被 kill 掉的線程就會(huì)出現(xiàn)如下異常信息：

System.Data.SqlClient.SqlException (0x80131904): 事務(wù)(進(jìn)程 ID 112)與另一個(gè)進(jìn)程被死鎖在 鎖 | 通信緩沖區(qū) 資源上，并且已被選作死鎖犧牲品。請(qǐng)重新運(yùn)行該事務(wù)。   在 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)

哈哈，是不是似曾相識(shí)，好了，對(duì)死鎖有了一定認(rèn)識(shí)之后，我們假設(shè)一下，如果存在

1. 25號(hào)線程想獲取 000000f7b853de48 鎖對(duì)象。

2. 63號(hào)線程想獲取 000000f7b853d480 鎖對(duì)象。

的情況下，必然就會(huì)死鎖， 對(duì)吧，接下來怎么用 windbg 驗(yàn)證呢？ 切到 25 號(hào)線程查看線程棧及棧對(duì)象。

0:000> ~25sntdll!NtWaitForMultipleObjects+0xa:00007ffb`9f230c7a c3              ret0:025> !clrstack OS Thread Id: 0x8848 (25)        Child SP               IP Call Site000000F782904838 00007ffb9f230c7a [HelperMethodFrame_1OBJ: 000000f782904838] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)000000F782904990 00007ffb1d5e4d5c MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder.Acquire()0:025> !dsoOS Thread Id: 0x8848 (25)RSP/REG          Object           Name000000F782904648 000000f7b853de48 System.Object000000F7829046D8 000000f7b84cb508 MongoDB.Driver.ReadPreference

可以清楚的看到 ReliableEnter 正在獲取 000000f7b853de48 鎖對(duì)象時(shí)被卡住，再切到 63號(hào)線程查看。

0:025> ~63sntdll!NtWaitForMultipleObjects+0xa:00007ffb`9f230c7a c3              ret0:063> !clrstack OS Thread Id: 0x75e0 (63)        Child SP               IP Call Site000000F787774EE8 00007ffb9f230c7a [HelperMethodFrame_1OBJ: 000000f787774ee8] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)000000F787775040 00007ffb1d5e4d5c MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder.Acquire()0:063> !dsoOS Thread Id: 0x75e0 (63)RSP/REG          Object           Name000000F787774A38 000000f7b82dc750 MongoDB.Bson.BsonBoolean000000F787774BA0 000000f7b83a9a10 System.RuntimeType000000F787774CF8 000000f7b853d480 System.Object

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

2. 死鎖原因分析

要想追究死鎖的原因，只能仔細(xì)推敲 線程棧 + 線程棧對(duì)象。

0:063> !clrstack OS Thread Id: 0x75e0 (63)        Child SP               IP Call Site000000F787774EE8 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, 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> !dsoOS Thread Id: 0x75e0 (63)RSP/REG          Object           Name000000F787774A38 000000f7b82dc750 MongoDB.Bson.BsonBoolean000000F787774BA0 000000f7b83a9a10 System.RuntimeType000000F787774CF8 000000f7b853d480 System.Object...000000F78777B658 000000f7be3407c8 System.String    OperationCanceled000000F78777B670 000000f7b82c07e0 System.Resources.RuntimeResourceSet000000F78777B698 000000f7b82bff38 System.Globalization.CultureInfo000000F78777B730 000000f7a36525c8 System.Char[]000000F78777B7E0 000000f7be3407c8 System.String    OperationCanceled...000000F78777BEF8 000000f7b853de10 MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder000000F78777BF10 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+d__120[[Czkj.AlibabaTools.Models.mongo.CopyRecords, Czkj.AlibabaTools.Models]], MongoDB.Driver.Core]]000000F78777BF40 000000f7b853de48 System.Object...

由于這代碼到處都是 await,async ，所以看這反編譯后的線程棧真的頭大，經(jīng)過仔細(xì)比對(duì)，發(fā)現(xiàn)代碼流程大概是：

1. 從處理 Mongodb 的異步請(qǐng)求回調(diào)開始 (System.Threading.OverlappedData)。

2. 在 MongoDB.Driver.Core.Operations.FindOperation 時(shí)不知為啥拋了取消異常 OperationCanceled，然后調(diào)用 RetryableReadContext.Dispose()。

3. 在 ListConnectionHolder.Return() 方法中獲取 000000f7b853de48 鎖對(duì)象。

4. 在 SignalOrReset() -> SemaphoreSlimSignalable.Signal() 方法中執(zhí)行一些注冊(cè)handler邏輯。

注意：在事件觸發(fā)中并沒有退出 lock 區(qū)域。

5. 在幾個(gè)handler痙攣過程中進(jìn)入了另外一個(gè)線程池的 ListConnectionHolder.Acquire() 方法中，希望能得到該池中的 000000f7b853d480 鎖對(duì)象。

同時(shí) 25號(hào)線程正在反向做這個(gè)操作，由于大家都是雙重 lock，所以最終導(dǎo)致 死鎖 的發(fā)生。

三：有幾個(gè)需要解答的問題

1. 為什么會(huì)有兩個(gè)線程池？

從線程棧對(duì)象看，應(yīng)該也看到了有兩個(gè)線程池 ExclusiveConnectionPool。

0:000> !dumpheap -type ExclusiveConnectionPool -statStatistics:              MT    Count    TotalSize Class Name00007ffb1d25eca0        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 在接收異步回調(diào)時(shí)，由于某種情況發(fā)生了 OperationCanceled 異常，面對(duì)異常的后續(xù)處理邏輯時(shí)出現(xiàn)了死鎖bug。

3. 當(dāng)前的 mognodb sdk版本是多少？

這個(gè)mongodb 官方驅(qū)動(dòng)是 2.13.1.0，也就是 2021-8-15 發(fā)布的，截至最新的是 10月份發(fā)布的 2.13.2.0。

4. 反饋

了解這些信息后，和朋友做了溝通，朋友說他給 mongodb 社區(qū)提交 issue，幾天后，官方給的回答是在最新的 v2.14.beta1 中做了處理。

• https://github.com/mongodb/mongo-csharp-driver/commit/b961b81cb7dc1ffe7262c55a227afad0aab5a994

• https://jira.mongodb.org/browse/CSHARP-3815

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

四：總結(jié)

總的來說，這是 mongodb 底層的一個(gè) bug 導(dǎo)致的死鎖問題，dump的分析過程也幾經(jīng)波折，雖是官方權(quán)威的 MongoDB.Driver 包，但同樣值得懷疑，而不要一味的深深懷疑自己... 最后期待即將發(fā)布的 release v2.14.0 吧。