ASP.NET Debug系列之二: Hang调试

原文作者：Tess

原文链接：http://blogs.msdn.com/tess/archive/2008/02/06/net-debugging-demos-lab-1-hang-review.aspx

译者：Wencui http://www.cnblogs.com/David-Qian

前几天我翻译了Tess debug系列的第一篇文章以及和大家介绍了一些debugger tools的基本命令。今天我们将一起讨论Tess关于debug 系列的第二篇文章。Tess在每个系列中都使用了问题+结果的结构，为了简化，我将把问题和结果一起给大家。此外，大家在自己机器上重现这些问题的时候，由于机器的差异，许多问题的结果都可能和Tess的不一样，这个不要紧，只要大家能够掌握原理就可以了。同时，由于blog的尺寸问题，图片显示的内容并不十分清晰，大家可以从Tess的链接上去找。



1.问题重现

1.浏览页面：http://localhost/BuggyBits/FeaturedProducts.aspx

大概需要5秒左右的时间来呈现这个页面，大家也可以从页面下脚的开始和结束时间来判断。

2. 打开5个浏览器，并同时浏览刚才的页面。

这里需要注意的是，如果你几乎同时刷新刚才的页面了，但并没有看到这5个页面上显示相近的开始时间，那么很有可能你没有运行InternetConnections.reg文件。如果没有，双击它使它修改注册表，然后重新测试。

问题1：5个页面各自的运行时间是多少？

结果1：5个浏览器的结果分别是：1-5.0s，2-9.1s，3-12.57s，4-16.07s，5-18.61s。如果你看到每个request的时间间隔在5秒左右，那么你很可能是没有运行InternetConnections.reg文件。

问题2：w3wp.exe的CPU占用率是多少，高还是低？

结果2：非常低的CPU占用率，只有0～5%。

问题3：对于这种低CPU占用率的hang问题有什么潜在原因呢？

结果3：对于这种处理request时间在不断增加并且CPU占用率低的情况来说一般有如下两个原因：1) 所有的request在等待一个单thread独占的资源，即这个资源只能被1个thread单独使用。这样的话，其他所有thread就需要等待。2) 我们在等待一个资源，由于该资源仍未可用，导致所有需要该资源的thread阻塞。

2.获取dump

1. 打开一个命令行窗口，并切换到debugger tools的安装目录。输入以下命令，但请注意，不要立即按enter。

Adplus –hang –pn w3wp.exe –quiet

2. 重新打开一个命令行窗口，同样切换到debugger tools目录，使用tinyget脚本来对页面进行并发访问。

tinyget -srv:localhost -uri:/BuggyBits/FeaturedProducts.aspx -threads:30 -loop:50

这个命令将启动30个threads并发送50个requests到FeaturedProducts页面。

3. 在request仍然被发送的时候，可以在adplus窗口按enter以获取dump文件。

问题1：在-hang参数下，是什么触发dump文件的产生呢？

结果1：这个问题有点隐蔽，dump文件是在你运行adplus的时刻立即产生的，它不同于-crash参数。-crash参数是需要程序满足crash的条件时才会产生dump文件。

问题2：在产生dump文件的时，你需要有什么权限呢？

结果2：在权限方面，windbg和adplus和其他的debuggers没有什么不同，你需要有占有的权限或更高的权限。在hang mode下，由于我们并非真正插入到process中进行调试，因而我们不一定需要和process在同一端上，也正因如此，我们可以很容易的通过终端来进行service的调试。然而在crash mode下，我们需要在同一端进行process的调试。同样，如果是调试service的话，我们需要使用/console命令来从终端或远程桌面登录。

问题3：dump文件被保存在哪里？

结果3：默认情况下，dump文件会被保存在debugger tools的安装目录下。文件夹的命名如C:"debuggers"32bit"Hang_Mode__Date_02-06-2008__Time_11-15-0505。该文件夹包含如下文件：

CDBScripts – 包含一个config文件，config文件保存了一些windbg使用的命令。

ADPlus_report.txt – 包含一些信息，如adplus attach到哪个process等。

PID-5656__W3WP.EXE__Date_02-06-2008__Time_11-15-0505.log – 一些log信息。

PID-5656__W3WP.EXE__full_1c38_2008-02-06_11-15-08-005_1618.dmp – dump文件。

Process_List.txt – tlist.exe程序一些输出信息，显示在dump文件生成时系统中所有正在运行的process。

3.使用windbg查看dump文件

1. 打开windbg.exe，通过file/open crash dump菜单打开刚才获取的dump文件(.dmp)。

2. 设置symbols，这个我们已经在第一篇译文中介绍过。

3. Load sos，这个也在第二篇文章中介绍过，只需要使用 .load sos命令。

查看堆栈

1) 查看native的callstack

~* kb 2000

这个命令是用来查看所有thread的native的callstack。当我们想查看某一特定thread的native callstack时，我们可以先切换到该thread(~[id]s)，然后使用

kb 2000命令。

2) 查看.net的callstack

~* e !clrstack

这个命令是用来查看所有thread的.net的callstack。同上，如果我们想查看某一特定thread的.net callstack，我们可以使用 !clrstack命令。

问题1：在刚才的callstack中，你有没有发现某些thread在等待一些同步化的机制？

结果1：先看看native callstack的一些片段，斜体的表明是.net的callstack显示不出



现在看看.net callstack：



从.net的callstack我们可以看出(从下往上)，FeaturedProducts.Page_Load调用了DataLayer.GetFeaturedProducts()方法，进一步又调用了Monitor.Enter()方法，该

方法表明去尝试得到一个.net的lock。正因为有了lock，才使得其它的threads处于等待状态根据我们的推测，GetFeaturedProducts页面的代码应类似于：



4.查看hang的原因

1) 判断哪个thread在占有lock。

!syncblk 这个命令可以帮助我们查看具体哪个thread在独占着lock？

问题1：哪个线程在独占着lock呢？

结果1：这是使用!syncblk的结果，由此我们可以看出是ID为30(看Info值)的thread在独占着lock。



问题2：还有多少线程在等待着lock的释放？

结果2：这里有个小技巧，占有lock的线程在MonitorHeld上的值为1，等待的为2。这样的话，我们可以算出(85-1)/2=42，还有42个threads在等待Lock的释放。

2) 从callstack中显示AwareLock::Enter的线程中挑选一个，看看究竟发生了什么。

从它的.net callstack中，我们可以轻易的发现，由于调用DataLayer.GetFeaturedProducts()方法时导致了等待。

3) 看看正在拥有lock的thread在做什么。

刚才我们使用!syncblk命令已经知道ID为30的thread在拥有lock。现在切换到ID为30的thread，使用!clrstack看看它的.net callstack。



从图中我们可以看出，此thread正在sleep，这也就是为什么其他thread一直等不到lock释放的原因。

4) 好了，大概的原因我们已经查出了，现在我们可以打开Tess的源代码来验证下我们的想法。打开DataLayer的GetFeaturedProducts方法：



果真，它调用了sleep方法，使得每次调用这个方法时，thread都要sleep 5秒钟。这也就是为什么其它的threads要等待很长一段时间的原因了。

这篇文章比较长，但是内容非常的有价值，还是耐心的看吧 J 如果你有什么疑问的话可以给我留言。周末了，祝大家玩的开心！

Have a nice day!