记一次 .NET 某电商无货源后端服务 死锁分析

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。

了解这些信息后，和朋友做了沟通，朋友说他给 mongodb 社区提交 issue，几天后，官方给的回答是在最新的 v2.14.beta1 中做了处理。

也就是说在未来的 release v2.14.0 版本中会得到解决，目前也只能等一等啦！ 期待中。。。哈哈😁😁😁

总的来说，这是 mongodb 底层的一个 bug 导致的死锁问题，dump的分析过程也几经波折，虽是官方权威的 MongoDB.Driver 包，但同样值得怀疑，而不要一味的深深怀疑自己... 最后期待即将发布的 release v2.14.0 吧。