记一次 .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

4. 反馈

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

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

四:总结

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

图片名称
posted @ 2021-11-18 09:47  一线码农  阅读(2572)  评论(14编辑  收藏  举报