65.9K
CodeProject 正在变化。 阅读更多。
Home

A Case of a Deadlock in a .NET Application

Sebastian Solnica
starIconstarIconstarIconstarIcon
emptyStarIcon
starIcon

4.63/5 (9投票s)

2015 年 5 月 1 日

MIT

4分钟阅读

viewsIcon

18423

一个 .NET 应用程序中的死锁案例

我最近在我们一个应用程序中遇到了一个有趣的问题。负责发送和接收 SMS 的 SMS 路由器挂起（hang）了——没有 CPU 使用率，我们也未观察到应用程序日志中有任何活动。我收集了一个完整的内存转储，然后重启了该服务，服务似乎恢复了正常。出于好奇，我在 WinDbg 中打开了转储文件，加载了 PDE 和 SOS，并开始进行调查。

在分析挂起的应用程序时，我通常会先列出所有进程线程及其调用堆栈：~*e!CLRStack。如果您在堆栈中看不到任何 Monitor.Wait，您可能需要检查本机堆栈（使用 !DumpStack 或 k 命令）。在我们的案例中，堆栈似乎表明是托管代码中的挂起。

...
OS Thread Id: 0xdb4 (5)
Child SP       IP Call Site
04f9ed60 778aca2c [GCFrame: 04f9ed60]
04f9ef00 778aca2c [GCFrame: 04f9ef00]
04f9eeb0 778aca2c [HelperMethodFrame: 04f9eeb0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
04f9ef40 73a2d887 System.Threading.Monitor.Enter(System.Object, Boolean ByRef)
04f9ef50 73483b89 System.Diagnostics.TraceSource.TraceEvent(System.Diagnostics.TraceEventType, Int32, System.String)
...
OS Thread Id: 0x1220 (6)
Child SP       IP Call Site
050ded18 778aca2c [GCFrame: 050ded18]
050deebc 778aca2c [GCFrame: 050deebc]
050dee6c 778aca2c [HelperMethodFrame: 050dee6c] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
050deefc 72e3b9fa System.Diagnostics.DiagnosticsConfiguration.Initialize()
050def2c 72e3c06c System.Diagnostics.DiagnosticsConfiguration.get_SwitchSettings()
050def34 72e3c01a System.Diagnostics.Switch.InitializeConfigSettings()
050def40 72e3be34 System.Diagnostics.Switch.InitializeWithStatus()
050def84 72e3bd99 System.Diagnostics.Switch.get_SwitchSetting()
050def90 72e38594 System.Diagnostics.SourceSwitch.ShouldTrace(System.Diagnostics.TraceEventType)
050def98 72e43e64 System.Diagnostics.TraceSource.TraceEvent(System.Diagnostics.TraceEventType, Int32, System.String, System.Object[])
050deff0 049cf16f MySql.Data.MySqlClient.MySqlTrace.LogWarning(Int32, System.String)
050df008 049ce938 MySql.Data.MySqlClient.MySqlConnection.HandleTimeoutOrThreadAbort(System.Exception)
050df100 03a8d7c7 MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(System.Data.CommandBehavior)
050df218 0479219f MySql.Data.MySqlClient.MySqlCommand.ExecuteNonQuery()
050df248 0556a7cf Dapper.SqlMapper.ExecuteCommand(System.Data.IDbConnection, Dapper.CommandDefinition ByRef, System.Action`2)
050df280 0556777e Dapper.SqlMapper.ExecuteImpl(System.Data.IDbConnection, Dapper.CommandDefinition ByRef)
050df2e4 05567460 Dapper.SqlMapper.Execute(System.Data.IDbConnection, System.String, System.Object, System.Data.IDbTransaction, System.Nullable`1, System.Nullable`1)
...
OS Thread Id: 0xdf0 (7)
Child SP       IP Call Site
0521ea44 778aca2c [GCFrame: 0521ea44]
0521eb1c 778aca2c [GCFrame: 0521eb1c]
0521eb38 778aca2c [HelperMethodFrame_1OBJ: 0521eb38] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0521ebb4 72e3bdf9 System.Diagnostics.Switch.InitializeWithStatus()
0521ebf8 72e3bd99 System.Diagnostics.Switch.get_SwitchSetting()
0521ec04 72e38594 System.Diagnostics.SourceSwitch.ShouldTrace(System.Diagnostics.TraceEventType)
0521ec0c 72e43e64 System.Diagnostics.TraceSource.TraceEvent(System.Diagnostics.TraceEventType, Int32, System.String, System.Object[])
0521ec64 049cf16f MySql.Data.MySqlClient.MySqlTrace.LogWarning(Int32, System.String)
0521ec7c 049ce938 MySql.Data.MySqlClient.MySqlConnection.HandleTimeoutOrThreadAbort(System.Exception)
0521ed74 03a8d7c7 MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(System.Data.CommandBehavior)
0521ee8c 0479219f MySql.Data.MySqlClient.MySqlCommand.ExecuteNonQuery()
0521eebc 03a842dd NLog.Targets.DatabaseTarget.WriteEventToDatabase(NLog.LogEventInfo)
0521eef0 03a83fd8 NLog.Targets.DatabaseTarget.Write(NLog.LogEventInfo)
0521ef1c 03a83def NLog.Targets.Target.Write(NLog.Common.AsyncLogEventInfo)
0521ef44 03a83cb6 NLog.Targets.Target.WriteAsyncLogEvent(NLog.Common.AsyncLogEventInfo)
0521ef7c 03a83ad1 NLog.LoggerImpl.WriteToTargetWithFilterChain(NLog.Internal.TargetWithFilterChain, NLog.LogEventInfo, NLog.Common.AsyncContinuation)
0521ef94 03a839f6 NLog.LoggerImpl.Write(System.Type, NLog.Internal.TargetWithFilterChain, NLog.LogEventInfo, NLog.LogFactory)
0521efbc 04607c2f NLog.Logger.WriteToTargets(NLog.LogEventInfo)
0521efd0 04601801 NLog.Logger.Log(NLog.LogEventInfo)
0521efe0 046015d1 NLog.NLogTraceListener.ProcessLogEventInfo(NLog.LogLevel, System.String, System.String, System.Object[], System.Nullable`1, System.Nullable`1, System.Nullable`1)
0521f044 04600efc NLog.NLogTraceListener.TraceEvent(System.Diagnostics.TraceEventCache, System.String, System.Diagnostics.TraceEventType, Int32, System.String, System.Object[])
0521f08c 73483d61 System.Diagnostics.TraceSource.TraceEvent(System.Diagnostics.TraceEventType, Int32, System.String, System.Object[])
...
OS Thread Id: 0xb08 (8)
Child SP       IP Call Site
0538efd4 778aca2c [GCFrame: 0538efd4]
0538f084 778aca2c [HelperMethodFrame_1OBJ: 0538f084] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
0538f108 73aa5d16 System.Threading.Monitor.Wait(System.Object, Int32, Boolean)
0538f118 04de1d85 Quartz.Simpl.SimpleThreadPool+WorkerThread.Run()
0538f158 73a1ab43 System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
...

在您的转储文件中，您可能会看到更多等待的线程，对于大多数应用程序来说，这是正常的。所以在我们得出任何结论之前，我们需要再进行两个步骤：分析这些等待线程已获取的锁，并找出导致死锁的干扰锁。

查找锁

要列出我们应用程序中的所有 Monitor 锁，我们可以使用 SOS 扩展中的 !SyncBlk 命令。

0:000> !syncblk
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner
  306 0101284c            3         1 04cfe690 df0   7   017489b8 System.Object
  326 01012540            3         1 04cfe158 1220   6   0187258c System.Object
  329 010123a0            5         1 04cfe690 df0   7   0176d584 System.Object
  339 04cf3784            1         1 04cfdc20 db4   5   017b1bec System.Object
  340 04cf37b8            1         1 04cfe690 df0   7   017b1e44 System.Object
  342 04cf3820            1         1 04cfe158 1220   6   017b1d38 System.Object
-----------------------------
Total           344
CCW             0
RCW             1
ComClassFactory 0
Free            320

然后，我们将上述命令的结果与线程堆栈上引用的对象（使用 !dso 命令）进行匹配。我们将从线程 6 和 7 开始，因为它们似乎在锁方面最为活跃。

blocked-stacks

我用颜色标记了线程正在等待的对象，很明显我们这里有一个经典的死锁。尽管我们还没有回答这个问题：是什么操作导致了这种情况？

时间线分析

我们发现第 7 个线程正在等待在地址 0x0187258c 的对象上获取的锁（其堆栈中最顶层的锁）。我们也知道，在过去某个时候，线程 6 成功获取了该锁并且仍然持有它。通过检查负责这些等待的 C# 代码，我们可能会获得更好的理解。对于第 7 个线程来说，这是直接的——在反编译了 System.Diagnostics.Switch.InitializeWithStatus（即，在 System.Threading.Monitor.ReliableEnter 之后，最顶层的堆栈帧指向的方法）之后，我们得到：

namespace System.Diagnostics {
    ...
    public abstract class Switch {
        ...
        private object m_intializedLock;
        ...
        private object IntializedLock {
            [SuppressMessage("Microsoft.Concurrency", "CA8001", Justification = "Reviewed for thread-safety")]
            get {
                if (m_intializedLock == null) {
                    Object o = new Object();
                    Interlocked.CompareExchange<Object>(ref m_intializedLock, o, null);
                }

                return m_intializedLock;
            }
        }
        ...
        private bool InitializeWithStatus() {
            if (!initialized) {

                lock (IntializedLock) {

                    if (initialized || initializing) {
                        return false;
                    }
                    ....

所以我们在这里等待一个 private SourceSwitch 锁。我们知道 SourceSwitch 的地址（来自 !dso 命令的输出），所以我们可以转储它。

0:007> !DumpObj /d 01778978
Name:        System.Diagnostics.SourceSwitch
MethodTable: 72ebe134
EEClass:     72c9d164
Size:        44(0x2c) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System\v4.0_4.0.0.0__b77a5c561934e089\System.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
72ebf520  4000547        4 ...lementsCollection  0 instance 00000000 switchSettings
73b23e18  4000548        8        System.String  0 instance 01721228 description
73b23e18  4000549        c        System.String  0 instance 017788ec displayName
...
73b241b8  4000550       1c        System.Object  0 instance 0187258c m_intializedLock
...

0:007> !DumpObj /d 017788ec
Name:        System.String
MethodTable: 73b23e18
EEClass:     737238f0
Size:        24(0x18) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String:      mysql
...

很明显，第 7 个线程正在尝试记录与 mysql 相关的内容。通过检查其调用堆栈，我们可以猜测 MySql 驱动程序试图记录连接超时异常的警告。我们需要找出线程 6 是何时获得给定锁的。我们知道被锁定的对象在线程 6 的堆栈中地址 0x050DEF4C 被引用，这与对 System.Diagnostics.Switch.InitializeWithStatus() 函数的调用（子 SP 在 0x050def40）匹配。

050def34 72e3c01a System.Diagnostics.Switch.InitializeConfigSettings()
050def40 72e3be34 System.Diagnostics.Switch.InitializeWithStatus()
050def84 72e3bd99 System.Diagnostics.Switch.get_SwitchSetting()

通过检查 SourceSwitch 实例地址，我们可以确定它是阻塞了第 7 个线程的同一个实例。此外，情况也是一样的——MySql 驱动程序试图记录连接超时。

现在是时候对线程 6 正在等待的对象进行类似的调查了。线程 6 堆栈中最顶层的方法，紧跟在 System.Threading.Monitor.ReliableEnter 之后，是 System.Diagnostics.DiagnosticsConfiguration.Initialize，并且有一个容易识别的锁语句。

namespace System.Diagnostics {
    ...
    internal static class DiagnosticsConfiguration {
        ...
        internal static void Initialize() {
            // Initialize() is also called by other components outside of Trace 
            // (such as PerformanceCounter)
            // as a result using one lock for this critical section 
            // and another for Trace API critical sections
            // (such as Trace.WriteLine) could potentially lead to deadlock between 2 threads that are
            // executing these critical sections 
            // (and consequently obtaining the 2 locks) in the reverse order.
            // Using the same lock for DiagnosticsConfiguration as well as TraceInternal avoids this issue.
            // Sequential locks on TraceInternal.critSec by the same thread 
            // is a non issue for this critical section.
            lock (TraceInternal.critSec) {
                ...
            }
        }
        ...
    }
    ...
}

我们可以看到线程 6 正在等待一个全局锁，该锁用于初始化 System.Diagnostics 类中的跟踪。在第 7 个线程堆栈中，该对象在地址 0x0521F090 被引用，这指向 System.Diagnostics.TraceSource.TraceEvent 方法。


0521f044 04600efc NLog.NLogTraceListener.TraceEvent(System.Diagnostics.TraceEventCache, System.String, ...
0521f08c 73483d61 System.Diagnostics.TraceSource.TraceEvent(System.Diagnostics.TraceEventType, Int32 ...
0521f0e4 04604e45 ...SmsRouter.SmsProcessing.SmsReceiveJob.CollectSmsMessagesFromProvider(...

反编译后，我们可以轻松找到 lock 语句。

public void TraceEvent(TraceEventType eventType, int id, string format, params object[] args)
{
  this.Initialize();
  TraceEventCache eventCache = new TraceEventCache();
  if (!this.internalSwitch.ShouldTrace(eventType) || this.listeners == null)
    return;
  if (TraceInternal.UseGlobalLock)
  {
    lock (TraceInternal.critSec)
    ...

总而言之，导致故障的假设场景可能如下：

  1. 在第 7 个线程上运行的代码尝试使用 TraceSource.TraceEvent 方法保存日志，并获取了全局跟踪日志。然后将调用转发给 NLogTraceListener，后者调用了 DatabaseTarget.Write。
  2. 在第 6 个线程上运行的代码在将数据保存到 MySql 数据库时失败，ADO.NET 驱动程序尝试将警告记录到 System.Diagnostics 跟踪中——为了检查 mysql SwitchSource 值，需要初始化该开关（获取内部开关锁），这需要获得全局跟踪锁的所有权——**被第 7 个线程阻塞**。
  3. 在第 7 个线程上运行的代码在将日志保存到 MySql 数据库时失败，ADO.NET 驱动程序尝试将警告保存到 System.Diagnostics 跟踪中——为了检查 mysql SwitchSource 值，需要初始化该开关——**被第 6 个线程阻塞并死锁**。

如果数据库响应正常，问题可能就不会发生，因为 MySql 驱动程序永远不会生成日志。解决此问题的一种方法是禁用跟踪侦听器的全局锁定——这可以通过应用程序配置文件来实现，例如。

<configuration>
  <system.diagnostics>
    <trace useGlobalLock="false" />
  </system.diagnostics>
</configuration>

这是安全的，因为即使此设置关闭且跟踪侦听器不支持多线程（IsThreadSafe 属性返回 false），全局锁仍将被使用。在我们的例子中，NLogTraceListener 支持多线程，因此不会获取锁。

我希望您从这篇帖子中找到一些有关调试 .NET 代码中线程问题的有用技巧。如果您有任何关于调试锁问题的有趣技巧，请在评论中分享。

Filed under: CodeProject, 诊断线程问题

© . All rights reserved.