.NET调试实例实验1:死锁回顾(原创翻译)

-原文地址&＃xff1a;http://blogs.msdn.com/tess/archive/2008/02/06/net-debugging-demos-lab-1-hang-review.aspx 译者注释 (Just do it)1、这篇文章是作者对上篇文章的回顾和总结&＃xff0c;作者详细解答了在上篇文章里留给读者思考的问题&＃xff0c;并循序渐进地将问题逐层展开。
2、关于死锁&＃xff0c;这两篇文章提到的都是比较基础的内容&＃xff0c;稍后我准备结合这个实验的问题对这部分内容做一定的扩展&＃xff0c;敬请期待&＃xff01;
希望大家能真正亲自动手实践&＃xff0c;然后踊跃留言啊&＃xff01;

本周早些时候&＃xff0c;我发布了第一个.NET调试实例。如果你还没有下载和动手实践这个实验&＃xff0c;你可以从<这里>获得。

这篇文章是这个实验的回顾&＃xff0c;在这里解答了上篇提出的问题&＃xff0c;答案都标识为红色。

提示:实验结果和线程ID都取决于你刷新页面时点的多快和你机器的配置以及当时还有其它什么线程的请求正在执行&＃xff0c;所以我将依据在我的双核&＃43;Win2003的机器上得到的结果来回答上篇文章的问题。

重现问题:

1.浏览 http://localhost/BuggyBits/FeaturedProducts.aspx 这个页面将延时5秒显示&＃xff0c;你能在页面底部看到开始时间和执行时间。

2.打开5个以上的浏览器同时浏览这个页面&＃xff0c;并且同时刷新。

注意每一个页面的执行时间并确保它们的开始时间几乎都完全一样。(如果开始时间不同&＃xff0c;你有可能是没有执行那个reg文件)

Q:执行时间怎么样&＃xff1f;

A: 浏览器1 - 5.0s&＃xff0c;浏览器2 - 9.1s&＃xff0c;浏览器3 - 12.57s&＃xff0c;浏览器4 - 16.07s&＃xff0c;浏览器5 - 18.61s (如果你没有看到执行时间是逐渐增长的&＃xff0c;那就应该检查一下是否执行了那个reg文件&＃xff0c;如果没有执行&＃xff0c;看到的结果就是所有的请求的开始时间都有5秒钟的延时)

Q:问题重现的时候&＃xff0c;w3wp.exe进程的CPU利用率怎么样&＃xff1f;高还是低&＃xff1f;

A: 非常低的CPU利用率&＃xff0c;大约 0-5%

Q:出现死锁症状的潜在原因是什么&＃xff1f;

A:根据请求时间是逐渐增长的和CPU的利用率一直都很低&＃xff0c;这说明&＃xff1a;a)我们正在等待某些一次只能被一个线程使用的公共资源。b)我们并没有在一个死循环中&＃xff0c;看起来我们像是因为等待某些外部的资源而被阻塞的。

获取内存转储文件:

1.打开一个命令行窗口&＃xff0c;然后进入到你的调试器工具集目录。输入下面的命令行准备获取转储文件&＃xff0c;但是暂时先不要执行。
adplus –hang –pn w3wp.exe –quiet

提示: quiet开关是用来让我们不必处理那些询问信息的弹出提示框&＃xff0c;因为在请求结束前我们没有那么多时间处理完这些后再得到内存转储文件。你一般会得到一个消息提示框询问你是否要把当前的脚本(script)设置为你的默认脚本&＃xff0c;或者是提示你还没有在系统默认环境变量里设置符号文件路径&＃xff0c;或者是提示你正在收集一个挂起模式的内存转储文件。一般情况下&＃xff0c;对于这些提示信息&＃xff0c;你都可以简单地点yes。

2.重现问题&＃xff0c;使用刚才同时刷新5个浏览器的方法或者通过下面的命令行使用tinyget给那个网页施压的方法。
tinyget -srv:localhost -uri:/BuggyBits/FeaturedProducts.aspx -threads:30 -loop:50

提示:这个命令将启动30个线程&＃xff0c;并且发送50个请求到 FeaturedProducts.aspx

3.在刚才的adplus窗口敲回车就可以在所有请求正在执行的时候获得内存转储文件。

Q:adplus处于挂起模式的时候&＃xff0c;什么触发了生成内存转储文件&＃xff1f;

A:这是一个带点欺骗性的问题。之所以会产生Dump文件是因为你正在运行adplus&＃xff0c;它并不是在等待满足一个死锁的条件或者其他条件而触发生成Dump文件(不同于-crash开关)&＃xff0c;所以你可以在任何时候使用-hang开关来得到一个Dump文件&＃xff0c;而不需要考虑线程是否真的处于死锁中&＃xff0c;这种方式也是在诊断高内存使用率问题的时候常用的方法。

Q:你需要有什么样的权限才可以获取到一个进程的内存转储文件&＃xff1f;

A:在权限方面&＃xff0c;使用windbg/adplus进行调试跟使用其它的调试器没有什么区别&＃xff0c;你需要能持有那个进程或更高的权限。在hang模式下&＃xff0c;因为内存转储文件是以非侵入方式被抓取的&＃xff0c;这意味着我们根本没有中断进入线程&＃xff0c;所以你不需要跟启动进程有相同的身份&＃xff0c;在客户端调试服务器时&＃xff0c;以hang模式抓取内存转储文件的方式很实用。在crash模式下&＃xff0c;正好相反&＃xff0c;你需要跟启动进程等帐号有相同的身份&＃xff0c;这意味着如果你是在客户端或远程桌面登录到服务器端&＃xff0c;那么你需要在控制台登录到服务器端。

Q:转储文件被创建在那里? 提示:查阅一下Windbg的帮助文件&＃xff0c;关于adplus/挂起模式部分。

A:内存转储文件默认保存在每次你运行adplus时(使用-hang或-crash模式)在调试器的目录里新建的文件夹中&＃xff0c;这个文件夹将以这样的格式命名&＃xff1a;“C:\debuggers\32bit\Hang_Mode__Date_02-06-2008__Time_11-15-0505”。

文件夹里包含下面这些东西&＃xff1a;
    * CDBScripts - 包含用来通知windbg/cdb运行什么命令的配置文件的文件夹。
    * ADPlus_report.txt - 记录adplus附加到进程以后的信息
    * PID-5656__W3WP.EXE__Date_02-06-2008__Time_11-15-0505.log - adplus的运行时日志&＃xff0c;在hang模式下&＃xff0c;这个文件里包括堆栈里所有线程、已经加载的模块的信息和等同于执行!runaway命令的输出结果。如果内存转储文件创建失败&＃xff0c;那么你可以到这个文件的底部去查找原因。
    * PID-5656__W3WP.EXE__full_1c38_2008-02-06_11-15-08-005_1618.dmp - 这就是内存转储文件。
    * Process_List.txt - tlist.exe 的输出&＃xff0c;显示在抓取内存转储文件的时候&＃xff0c;系统中有多少进程在同时运行。

使用windbg.exe打开转储文件

1.启动Windbg&＃xff0c;使用"File/Open Crash dump"菜单打开刚才获得的内存转储文件。

2.设置符号文件的路径 (具体参考&＃xff1a;信息和安装说明)

3.加载SOS (具体参考&＃xff1a;信息和安装说明)

检查堆栈

1.检查本地调用堆栈
~* kb 2000
 
2.检查.NET调用堆栈
~* e !clrstack

Q:你是否发现了一些某个线程正在等待其它同步机制的典型迹象或者在调用堆栈上看出某些可能性&＃xff1f;

A:内存转储文件里有很多类似下面这样的本地调用堆栈的线程&＃xff0c;斜体部分因为是托管的调用堆栈&＃xff0c;Windbg不能显示其完整信息。

0:066> k 2000
ChildEBP RetAddr
1156e7b0 7d4e286c ntdll!ZwWaitForMultipleObjects&＃43;0x15
1156e858 79ed98fd kernel32!WaitForMultipleObjectsEx&＃43;0x11a
1156e8c0 79ed9889 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT&＃43;0x6f
1156e8e0 79ed9808 mscorwks!Thread::DoAppropriateAptStateWait&＃43;0x3c
1156e964 79ed96c4 mscorwks!Thread::DoAppropriateWaitWorker&＃43;0x13c
1156e9b4 79ed9a62 mscorwks!Thread::DoAppropriateWait&＃43;0x40
1156ea10 79e78944 mscorwks!CLREvent::WaitEx&＃43;0xf7
1156ea24 79ed7b37 mscorwks!CLREvent::Wait&＃43;0x17
1156eab0 79ed7a9e mscorwks!AwareLock::EnterEpilog&＃43;0x8c
1156eacc 79f59024 mscorwks!AwareLock::Enter&＃43;0x61
1156eb34 79fc6352 mscorwks!AwareLock::Contention&＃43;0x199
1156ebd4 0ff10dd3 mscorwks!JITutil_MonContention&＃43;0xa3
WARNING: Frame IP not in any known module. Following frames may be wrong.
1156ec34 793ae896 0xff10dd3
1156ee8c 6614d8c3 mscorlib_ni&＃43;0x2ee896
1156eec4 6614d80f System_Web_ni&＃43;0x22d8c3
1156ef00 6614d72f System_Web_ni&＃43;0x22d80f
1156ef20 65fe6bfb System_Web_ni&＃43;0x22d72f
1156ef54 65fe3f51 System_Web_ni&＃43;0xc6bfb
1156ef90 65fe7733 System_Web_ni&＃43;0xc3f51
1156efe4 65fccbfe System_Web_ni&＃43;0xc7733
1156eff8 65fd19c5 System_Web_ni&＃43;0xacbfe
1156f01c 7938111c System_Web_ni&＃43;0xb19c5
00000000 00000000 mscorlib_ni&＃43;0x2c111c

下面的是托管调用堆栈

0:066> !clrstack
OS Thread Id: 0x960 (66)
ESP       EIP     
1156ea4c 7d61d051 [GCFrame: 1156ea4c]
1156eb88 7d61d051 [HelperMethodFrame: 1156eb88] System.Threading.Monitor.Enter(System.Object)
1156ebdc 0ff10dd3 DataLayer.GetFeaturedProducts()
1156ec18 0ff10c6c FeaturedProducts.Page_Load(System.Object, System.EventArgs)
1156ec58 66f12980 System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
1156ec68 6628efd2 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
1156ec78 6613cb04 System.Web.UI.Control.OnLoad(System.EventArgs)
1156ec88 6613cb50 System.Web.UI.Control.LoadRecursive()
1156ec9c 6614e12d System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
1156ee98 6614d8c3 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
1156eed0 6614d80f System.Web.UI.Page.ProcessRequest()
1156ef08 6614d72f System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
1156ef10 6614d6c2 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
1156ef24 0ff10205 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)
1156ef28 65fe6bfb System.Web.HttpApplication&＃43;CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1156ef5c 65fe3f51 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1156ef9c 65fe7733 System.Web.HttpApplication&＃43;ApplicationStepManager.ResumeSteps(System.Exception)
1156efec 65fccbfe System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
1156f008 65fd19c5 System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
1156f03c 65fd16b2 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
1156f048 65fcfa6d System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
1156f258 79f047fd [ContextTransitionFrame: 1156f258]
1156f28c 79f047fd [GCFrame: 1156f28c]
1156f3e8 79f047fd [ComMethodFrame: 1156f3e8]

如果将它们放在一起&＃xff0c;这些线程的调用堆栈看起来像下面这样

0:066> k 2000
ChildEBP RetAddr  
1156e7b0 7d4e286c ntdll!ZwWaitForMultipleObjects&＃43;0x15
1156e858 79ed98fd kernel32!WaitForMultipleObjectsEx&＃43;0x11a
1156e8c0 79ed9889 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT&＃43;0x6f
1156e8e0 79ed9808 mscorwks!Thread::DoAppropriateAptStateWait&＃43;0x3c
1156e964 79ed96c4 mscorwks!Thread::DoAppropriateWaitWorker&＃43;0x13c
1156e9b4 79ed9a62 mscorwks!Thread::DoAppropriateWait&＃43;0x40
1156ea10 79e78944 mscorwks!CLREvent::WaitEx&＃43;0xf7
1156ea24 79ed7b37 mscorwks!CLREvent::Wait&＃43;0x17
1156eab0 79ed7a9e mscorwks!AwareLock::EnterEpilog&＃43;0x8c
1156eacc 79f59024 mscorwks!AwareLock::Enter&＃43;0x61
1156eb34 79fc6352 mscorwks!AwareLock::Contention&＃43;0x199
1156ebd4 0ff10dd3 mscorwks!JITutil_MonContention&＃43;0xa3
1156ea4c 7d61d051 [GCFrame: 1156ea4c]
1156eb88 7d61d051 [HelperMethodFrame: 1156eb88] System.Threading.Monitor.Enter(System.Object)
1156ebdc 0ff10dd3 DataLayer.GetFeaturedProducts()
1156ec18 0ff10c6c FeaturedProducts.Page_Load(System.Object, System.EventArgs)
1156ec58 66f12980 System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
1156ec68 6628efd2 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
1156ec78 6613cb04 System.Web.UI.Control.OnLoad(System.EventArgs)
1156ec88 6613cb50 System.Web.UI.Control.LoadRecursive()
1156ec9c 6614e12d System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
1156ee98 6614d8c3 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
1156eed0 6614d80f System.Web.UI.Page.ProcessRequest()
1156ef08 6614d72f System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
1156ef10 6614d6c2 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
1156ef24 0ff10205 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)
1156ef28 65fe6bfb System.Web.HttpApplication&＃43;CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1156ef5c 65fe3f51 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1156ef9c 65fe7733 System.Web.HttpApplication&＃43;ApplicationStepManager.ResumeSteps(System.Exception)
1156efec 65fccbfe System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
1156f008 65fd19c5 System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
1156f03c 65fd16b2 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
1156f048 65fcfa6d System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
1156f258 79f047fd [ContextTransitionFrame: 1156f258]
1156f28c 79f047fd [GCFrame: 1156f28c]
1156f3e8 79f047fd [ComMethodFrame: 1156f3e8]

那么我们可以从这个调用堆栈里看到(像在Visual Studio里查看调用堆栈一样&＃xff0c;从下往上看) FeaturedProducts.Page_Load 调用了一个DataLayer.GetFeaturedProducts()方法&＃xff0c;这个方法又调用了Monitor.Enter() 方法&＃xff0c;这是在.NET中使用锁(lock)的实现方式。

GetFeaturedProducts 方法的代码应该看起来像下面这样

void GetFeaturedProducts(){
 
  lock(){
    // do something
  }
 
}

因为已经有其他线程占用这个锁&＃xff0c;所以我们就卡在lock(...)这行。

定位并解决死锁

1.确定持有锁的线程的ID.
!syncblk

Q:什么线程拥有锁&＃xff1f;

A:我的!syncblk执行结果如下&＃xff1a;

0:066> !syncblk
Index  SyncBlock    MonitorHeld Recursion Owning Thread Info  SyncBlock  Owner
20      001c6f74     85              1              0f4a0a70 1ea0 30   02f07964   System.Object
-----------------------------
Total 22
CCW 2
RCW 0
ComClassFactory 0
Free 5 Free 5

拥有锁的线程是Owning Thread Info字段里最后一列(在这里是线程30)&＃xff0c;那么这就是上面的GetFeaturedProducts()方法里"// do something"那部分的线程&＃xff0c;或者是其它占用了我们需要的锁的线程。

Q:有多少线程在等待解锁&＃xff1f;
提示:MonitorHeld &＃61; 1时表示这个线程持有锁&＃xff0c;MonitorHeld &＃61; 2时表示这个线程被阻塞&＃xff01;

A:这里MonitorHeld字段的值是85&＃xff0c;这意味着我们有一个锁拥有者和84/2&＃61;42个等待者&＃xff0c;也就是说有42个请求都在等待这个锁&＃xff0c;如果我执行

.shell -ci "~* e !clrstack" FIND /C Monitor.Enter

看看有多少调用堆栈里有Monitor.Enter&＃xff0c;返回结果是42&＃xff0c;这与上面的推测一致。

事实上&＃xff0c;42是生活、宇宙和所有事情的答案&＃xff0c;这只是一个巧合 :)

2.挑选一个堵塞线程(提示:堵塞线程位于AwareLock::Enter)&＃xff0c;看看它在做什么&＃xff1f;
    ~5s              (切换到线程5)
    kb 2000         (检查本地堆栈)
    !clrstack        (检查.NET堆栈)

Q:堵塞线程等待的锁在那个.NET函数里&＃xff1f;

A: DataLayer.GetFeaturedProducts()

3.检查持有锁的线程在做什么&＃xff1f;
    ~5s             (切换到线程5)
    kb 2000        (检查本地堆栈)
    !clrstack       (检查.NET堆栈)

Q:为什么会发生死锁&＃xff1f;

从线程30可以看到&＃xff0c;DataLayer.GetFeaturedProducts()方法调用了Thread.Sleep()&＃xff0c;那么这就完全可以解释为什么我们都堵塞在那了(拥有锁的线程)。

0:030> !clrstack
OS Thread Id: 0x1ea0 (30)
ESP       EIP     
1036ec88 7d61cca8 [HelperMethodFrame: 1036ec88] System.Threading.Thread.SleepInternal(Int32)
1036ecdc 0ff10ddd DataLayer.GetFeaturedProducts()
1036ed18 0ff10c6c FeaturedProducts.Page_Load(System.Object, System.EventArgs)
1036ed58 66f12980 System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
1036ed68 6628efd2 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
1036ed78 6613cb04 System.Web.UI.Control.OnLoad(System.EventArgs)
1036ed88 6613cb50 System.Web.UI.Control.LoadRecursive()
1036ed9c 6614e12d System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
1036ef98 6614d8c3 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
1036efd0 6614d80f System.Web.UI.Page.ProcessRequest()
1036f008 6614d72f System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
1036f010 6614d6c2 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
1036f024 0ff10205 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)
1036f028 65fe6bfb System.Web.HttpApplication&＃43;CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1036f05c 65fe3f51 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1036f09c 65fe7733 System.Web.HttpApplication&＃43;ApplicationStepManager.ResumeSteps(System.Exception)
1036f0ec 65fccbfe System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
1036f108 65fd19c5 System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
1036f13c 65fd16b2 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
1036f148 65fcfa6d System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
1036f358 79f047fd [ContextTransitionFrame: 1036f358]
1036f38c 79f047fd [GCFrame: 1036f38c]
1036f4e8 79f047fd [ComMethodFrame: 1036f4e8]

4.检查代码&＃xff0c;看是否有方法使用了锁&＃xff0c;进一步证明你的假设。

    public DataTable GetFeaturedProducts()
    {
        lock (syncobj)
        {
            //faking a long running query to the database
            Thread.Sleep(5000);
            
             //populate a table with the featured products
             DataTable dt &＃61; new DataTable();
             DataRow dr;
             
        }        
     }

正如期望中的一样&＃xff0c;GetFeaturedProducts()方法设置了一个锁&＃xff0c;然后又让线程Sleep了5秒&＃xff0c;我们这里只是为了演示一个长时间运行的独占线程的操作而使用sleep来简单模拟实现这个效果。要解决这类问题主要还是靠应用程序的具体实现方式&＃xff0c;具体要看期望这个操作的执行时间有多长&＃xff0c;并确认是否这个线程阻塞的时间经常要比期望的时间长&＃xff0c;然后我们要尽可能只锁住尽量少的代码&＃xff0c;以防止有很多请求同时等待一个资源。(原文参考&＃xff1a;The resolution here will of course depend largely on the application but it would include looking into how long this operation is supposed to be and finding out if threads are blocking more often than expected, and after review finding ways to make sure we lock around as small a portion of code as possible to avoid having lots of requests waiting for a single resource. )

希望你能喜欢这个实验&＃xff0c;我将争取在周末以前完成下一个实验(崩溃方面)

如果你觉得我遗漏了什么、你的答案跟我的不同(除了线程ID,等待锁的线程个锁等)或者你根本不喜欢这个实验的形式并且你感觉如果能更详细地讲解某些细节就更好些&＃xff0c;都请在留言栏里自由回复。

-博客园.Debug探索团队
-By Justin/2008年7月18日 6:30:32