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

  • A+
所属分类：.NET技术
摘要

这个月初，星球里的一位朋友找到我，说他的程序出现了死锁，怀疑是自己的某些写法导致mongodb出现了如此尴尬的情况，截图如下：
便宜好用的国外VPS推荐

一：背景

1. 讲故事

这个月初，星球里的一位朋友找到我，说他的程序出现了死锁，怀疑是自己的某些写法导致mongodb出现了如此尴尬的情况，截图如下：

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

说实话，看过这么多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 锁对象。

我们知道所谓的 死锁 就是两个线程都渴望得到对方持有的锁资源，谁也不让步所造成的一种僵局，如果不明白，我就画一张图：

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

上图就是一种死锁的僵局，顺便提一下， 在 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()。

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

  1. 在 ListConnectionHolder.Return() 方法中获取 000000f7b853de48 锁对象。

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

  1. 在 SignalOrReset() -> SemaphoreSlimSignalable.Signal() 方法中执行一些注册handler逻辑。

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

注意：在事件触发中并没有退出 lock 区域。

  1. 在几个handler痉挛过程中进入了另外一个线程池的 ListConnectionHolder.Acquire() 方法中，希望能得到该池中的 000000f7b853d480 锁对象。

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

同时 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。

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

4. 反馈

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

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

四：总结

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

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

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

便宜好用的国外VPS推荐