记一次 .NET 某电商无货源后端服务 死锁分析
<h2 id="一背景">一：背景</h2><h3 id="1-讲故事">1. 讲故事</h3>
<p>这个月初，星球里的一位朋友找到我，说他的程序出现了死锁，怀疑是自己的某些写法导致mongodb出现了如此尴尬的情况，截图如下：</p>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/8c35fdcb81b049dbb5dd6b9d4711fd62~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<p>说实话，看过这么多dump，还是第一次遇到真实的死锁，这tmd的顿时就有了兴趣。。。 上 windbg 说话。</p>
<h2 id="二windbg-分析">二：Windbg 分析</h2>
<h3 id="1-真的是死锁吗">1. 真的是死锁吗</h3>
<p>既然朋友说死锁，我得先验证一下,可以用命令 <code>!syncblk</code> 查看同步块表。</p>
<pre><code class="language-C#">
0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
97 000000F7B77CA1B8 107 1 000000F7D37A7210 884825 000000f7b853d480 System.Object
144 000000F7D39BA2A8 495 1 000000F7DA4CDA70 75e063 000000f7b853de48 System.Object
-----------------------------
Total 603
CCW 1
RCW 1
ComClassFactory 0
Free 490
</code></pre>
<p>从同步块表中可得知如下信息。</p>
<ol>
<li>
<p>25号线程正持有 <code>000000f7b853d480</code> 锁对象。</p>
</li>
<li>
<p>63号线程正持有 <code>000000f7b853de48</code> 锁对象。</p>
</li>
</ol>
<p>我们知道所谓的 <code>死锁</code> 就是两个线程都渴望得到对方持有的锁资源，谁也不让步所造成的一种僵局，如果不明白，我就画一张图：</p>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/6812d98d61d04113a3b2698f5b4b908b~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<p>上图就是一种死锁的僵局，顺便提一下， 在 sqlserver 中也常会遇到这种情况，那它会怎么处理的呢？ 这就有点意思了，sqlserver 内部有一个调停的线程周期性执行，当检测到这种死锁僵局的时候，它会把优先级低的线程kill掉，这样另外一个线程就能顺利获取锁，被 kill 掉的线程就会出现如下异常信息：</p>
<pre><code class="language-C#">
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)
</code></pre>
<p>哈哈，是不是似曾相识，好了，对死锁有了一定认识之后，我们假设一下，如果存在</p>
<ol>
<li>
<p>25号线程想获取 <code>000000f7b853de48</code> 锁对象。</p>
</li>
<li>
<p>63号线程想获取 <code>000000f7b853d480</code> 锁对象。</p>
</li>
</ol>
<p>的情况下，必然就会死锁， 对吧，接下来怎么用 windbg 验证呢？ 切到 25 号线程查看线程栈及栈对象。</p>
<pre><code class="language-C#">
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 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
</code></pre>
<p>可以清楚的看到 <code>ReliableEnter</code> 正在获取 <code>000000f7b853de48</code> 锁对象时被卡住，再切到 63号线程查看。</p>
<pre><code class="language-C#">
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 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
</code></pre>
<p>可以清楚的看到 <code>ReliableEnter</code> 正在获取 <code>000000f7b853d480</code>， 这就表明确实产生了死锁，没毛病。</p>
<h3 id="2-死锁原因分析">2. 死锁原因分析</h3>
<p>要想追究死锁的原因，只能仔细推敲 <code>线程栈</code> + <code>线程栈对象</code>。</p>
<pre><code class="language-C#">
0:063> !clrstack
OS Thread Id: 0x75e0 (63)
Child SP IP Call Site
000000F787774EE8 00007ffb9f230c7a System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
000000F787775040 00007ffb1d5e4d5c MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool+ListConnectionHolder.Acquire()
...
000000F78777BD10 00007ffb1e2fc69f System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean)
000000F78777BDA0 00007ffb1e2fc69f System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean)
000000F78777BE30 00007ffb1e2fc69f System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean)
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[].MoveNext()
...
000000F78777E980 00007ffb1dd807bf System.Net.Sockets.Socket+AwaitableSocketAsyncEventArgs.InvokeContinuation(System.Action`1<System.Object>, System.Object, Boolean, Boolean)
000000F78777E9F0 00007ffb1dd80519 System.Net.Sockets.Socket+AwaitableSocketAsyncEventArgs.OnCompleted(System.Net.Sockets.SocketAsyncEventArgs)
000000F78777EA50 00007ffb1dd7f751 System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
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.Core],], MongoDB.Driver.Core]]
000000F78777BF40 000000f7b853de48 System.Object
...
</code></pre>
<p>由于这代码到处都是 <code>await,async</code> ，所以看这反编译后的线程栈真的头大，经过仔细比对，发现代码流程大概是：</p>
<ol>
<li>
<p>从处理 Mongodb 的异步请求回调开始 (System.Threading.OverlappedData)。</p>
</li>
<li>
<p>在 <code>MongoDB.Driver.Core.Operations.FindOperation</code> 时不知为啥抛了取消异常 <code>OperationCanceled</code>，然后调用 <code>RetryableReadContext.Dispose()</code>。</p>
</li>
</ol>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/fe735f26989f479db0c3a003a1aa7484~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<ol start="3">
<li>在 <code>ListConnectionHolder.Return()</code> 方法中获取 <code>000000f7b853de48</code> 锁对象。</li>
</ol>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/38ea772accd94cac986f8ea66bd72bd1~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<ol start="4">
<li>在 <code>SignalOrReset() -> SemaphoreSlimSignalable.Signal()</code> 方法中执行一些注册handler逻辑。</li>
</ol>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/ee8e18044dd14be79740627000886dd1~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<p>注意：在事件触发中并没有退出 <code>lock</code> 区域。</p>
<ol start="5">
<li>在几个handler痉挛过程中进入了另外一个线程池的 <code>ListConnectionHolder.Acquire()</code> 方法中，希望能得到该池中的 <code>000000f7b853d480</code> 锁对象。</li>
</ol>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/f538d07286ae4fe29652878e7285d397~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<p>同时 25号线程正在反向做这个操作，由于大家都是双重 lock，所以最终导致 <strong>死锁</strong> 的发生。</p>
<h2 id="三有几个需要解答的问题">三：有几个需要解答的问题</h2>
<h3 id="1-为什么会有两个线程池">1. 为什么会有两个线程池？</h3>
<p>从<code>线程栈对象</code>看，应该也看到了有两个线程池 <code>ExclusiveConnectionPool</code>。</p>
<pre><code class="language-C#">
0:000> !dumpheap -type ExclusiveConnectionPool -stat
Statistics:
MT Count TotalSize Class Name
00007ffb1d25eca0 2 464 MongoDB.Driver.Core.ConnectionPools.ExclusiveConnectionPool
</code></pre>
<p>这是由于朋友的 <code>mongodb 连接串</code> 用的是双IP的副本集模式。</p>
<pre><code class="language-C#">
{
"mongo": {
"Connection": "mongodb://xxx.aliyuncs.com:3717,xxx.aliyuncs.com:3717/admin?replicaSet=mgset-500180544&readPreference=secondaryPreferred&maxPoolSize=1000&wtimeoutMS=10000"
}
}
</code></pre>
<h3 id="2-是程序员的锅吗">2. 是程序员的锅吗？</h3>
<p>从堆栈信息看并不是程序员的锅，是 mongodb 在接收异步回调时，由于某种情况发生了 <code>OperationCanceled</code> 异常，面对异常的后续处理逻辑时出现了死锁bug。</p>
<h3 id="3-当前的-mognodb-sdk版本是多少">3. 当前的 mognodb sdk版本是多少？</h3>
<p>这个mongodb 官方驱动是<code>2.13.1.0</code>，也就是 <code>2021-8-15</code> 发布的，截至最新的是 10月份发布的 <code>2.13.2.0</code>。</p>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/ddfb5adac9f942a3a5d97b114f8e178a~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<h3 id="4-反馈">4. 反馈</h3>
<p>了解这些信息后，和朋友做了沟通，朋友说他给 mongodb 社区提交 issue，几天后，官方给的回答是在最新的 <code>v2.14.beta1</code> 中做了处理。</p>
<ul>
<li>
<p>https://github.com/mongodb/mongo-csharp-driver/commit/b961b81cb7dc1ffe7262c55a227afad0aab5a994</p>
</li>
<li>
<p>https://jira.mongodb.org/browse/CSHARP-3815</p>
</li>
</ul>
<p>也就是说在未来的 <code>release v2.14.0</code> 版本中会得到解决，目前也只能等一等啦！ 期待中。。。哈哈😁😁😁</p>
<h2 id="四总结">四：总结</h2>
<p>总的来说，这是 mongodb 底层的一个 bug 导致的死锁问题，dump的分析过程也几经波折，虽是官方权威的 <code>MongoDB.Driver</code> 包，但同样值得怀疑，而不要一味的深深怀疑自己... 最后期待即将发布的 <code>release v2.14.0</code> 吧。</p>
<p><img src="https://p3-juejin.byteimg.com/tos-cn-i-k3u1fbpfcp/655a2717adfb417692ded9dbe594cf2a~tplv-k3u1fbpfcp-zoom-1.image" alt="" loading="lazy"></p>
<img src="https://images.cnblogs.com/cnblogs_com/huangxincheng/345039/o_210929020104最新消息优惠促销公众号关注二维码.jpg" width="700" height="300" alt="图片名称" align="center"><br><br>
来源：https://www.cnblogs.com/huangxincheng/p/15570854.html
頁:
[1]