欢迎光临
我的个人博客网站

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


一:背景

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 某电商无货源后端服务 死锁分析

赞(0) 打赏
未经允许不得转载:张拓的天空 » 记一次 .NET 某电商无货源后端服务 死锁分析
分享到: 更多 (0)

评论 抢沙发

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址

专业的IT技术经验分享 更专业 更方便

联系我们本站主机

觉得文章有用就打赏一下文章作者

支付宝扫一扫打赏

微信扫一扫打赏