记一次 .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
从同步块表中可得知如下信息。
-
25号线程正持有
000000f7b853d480
锁对象。 -
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)
哈哈,是不是似曾相识,好了,对死锁有了一定认识之后,我们假设一下,如果存在
-
25号线程想获取
000000f7b853de48
锁对象。 -
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
,所以看这反编译后的线程栈真的头大,经过仔细比对,发现代码流程大概是:
-
从处理 Mongodb 的异步请求回调开始 (System.Threading.OverlappedData)。
-
在
MongoDB.Driver.Core.Operations.FindOperation
时不知为啥抛了取消异常OperationCanceled
,然后调用RetryableReadContext.Dispose()
。
- 在
ListConnectionHolder.Return()
方法中获取000000f7b853de48
锁对象。
- 在
SignalOrReset() -> SemaphoreSlimSignalable.Signal()
方法中执行一些注册handler逻辑。
注意:在事件触发中并没有退出 lock
区域。
- 在几个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
吧。
![图片名称](https://images.cnblogs.com/cnblogs_com/huangxincheng/345039/o_210929020104最新消息优惠促销公众号关注二维码.jpg)