.Net 调式案例—实验1 假死（hang）复习回顾
.Net 调式案例—实验1 假死（hang）复习回顾
这是10个实验中的第一个，这个实验中会使用叫“BuggyBits”的站点。要开始这个实验，如果你还束手无策，请看我前面发表的文章。
我感觉到这些“手边的实验”会产生很多的问题，虽然我会尽力来回答留言评论中的问题，但我不能保证我全部都回答，所以如果你看到别人的评论，你能够解答，那请你帮我解答疑一下。
注意：在实验中的问题（Q:…..）仅仅是查找问题所在的一个帮助性提示，我会节制一些包含答案的评论，直到我发布了对这个实验的一个复习（Review）的文章，在原实验发布的一周以后我会发布复习这个实验的文章，给大家一个简短的思考时间。
请自由的发表评论，无论好与坏，这样我才能知道哪些有用哪些是没有用的。
好了，没有其他的二话，开始第一个实验：
问题再现
1） 浏览http://localhost/BuggyBits/FeaturedProducts.aspx 。这大约会过5秒后显示，你可以在页面底部看到开始时间和执行时间。
2） 打开5个浏览器，指向同一个地址，然后同时的刷新他们。注意他们每一个的执行时间，你要保证他们每一个的开始时间都是几乎一致的。（如果不是，那你没有运行那个注册表文件）。
Q：执行时间是多少？
A：浏览器1：5.0s，浏览器2：9.1s，浏览器3：12.57s，浏览器4：16.07s，浏览器5： 18.61s，如果你没有看到执行时间的增长，那你要检查一下你是否运行了那个程序压缩包里面的reg 注册表文件，要不然，你会看到在所有的请求中的开始时间上都有5秒的延迟。
Q：w3wp.ext 的cpu的使用率是多少？高还是低？
A：非常低的cpu使用率，0-5%。
Q：出现假死（hang）症状的潜在原因是什么？
A：随着请求的时间增加，cpu使用率非常低，它表现出a）我们在等待某个独占的公用的资源，b）我们没有进程紧密地循环，所以被阻塞可能的可能是某个外部的资源。
得到一个内存dump文件
1）打开一个命令窗口，把路径指到调式器目录，输入下面的命令，但不要敲回车键。
adplus –hang –pn w3wp.exe –quiet
注意：quiet这个开关量是为了让命令在运行过程中不会弹出询问对话框，因为在请求结束前我们没有这么多的时间来处理这些然后得到dump文件，典型的，你遇到的对话框可能是询问你是“set cscript as your default script”、“set up your symbol path”、“you are about to gather a hang dump”，简单的，你可以都点“是（Yes）”。
2）重现问题，通过你前面浏览5个浏览器的方式，或者通过tinyget ，利用下面的命令 :
tinyget -srv:localhost -uri:/BuggyBits/FeaturedProducts.aspx -threads:30 -loop:50
注意：这个意思是启动30个线程，发送50个请求到FeaturedProducts.aspx。
3） 在adplus 的命令窗口敲回车键，当请求还在执行中的时候得到一个dump文件。
Q：在adplus 假死（hang）模式下，是什么触发了内存dump文件的产生？
A：这是一个有点疑惑的问题，dump文件的产生是你运行了adplus，它不是等到发生hang这种情况时才开始产生文件，这个和-crash 这个开关量不同，所以，你可以使用-hang这个开关量，在任何时候，而无须关注进程是否真的处于hang状态时。这个也是在高内存使用率时我们通常的做法。
Q：要抓取一个进程的内存dump文件，你需要什么权限？
Q：dump文件保存在了哪里？提示：查看WinDbg的帮助文件。
A：这两个问题，略过。如有需要再回答。
在WinDbg中打开dump文件
1） 打开WinDbg，通过菜单上的“open crash dump”来打开dump文件。
2） 设置符号文件的位置。
3） 加载SOS。
检查栈
1） 检查本地调用堆栈
~* kb 2000
2） 检查.net 的调用堆栈
~* e !clrstack
Q：你能看到一些式样或认出一些调用堆栈中那些暗示一个进程在等待同步机制的部分么？
A：dump文件里面有许多和下面图中类似的本地调用堆栈的线程，斜体字中的那一块不能得到具体的信息，因为他们是托管的。
0:066> k 2000
ChildEBP RetAddr
1156e9b4 79ed
1156ea10 79e78944 mscorwks!CLREvent::WaitEx+0xf7
1156ea24 79ed7b37 mscorwks!CLREvent::Wait+0x17
1156eab0 79ed
1156eacc
1156eb34 79fc6352 mscorwks!AwareLock::Contention+0x199
1156ebd4 0ff10dd3 mscorwks!JITutil_MonContention+0xa3
WARNING: Frame IP not in any known module. Following frames may be wrong.
1156ec34 793ae896 0xff10dd3
1156ee
1156eec4 6614d
1156ef00 6614d
00000000 00000000 mscorlib_ni+0x
下面是托管的调用堆栈：
0:066> !clrstack
OS Thread Id: 0x960 (66)
ESP EIP
1156ea
1156eb88 7d61d051 [HelperMethodFrame: 1156eb88]
System.Threading.Monitor.Enter(System.Object)
1156ebdc 0ff10dd3 DataLayer.GetFeaturedProducts()
1156ec18 0ff
1156ec58
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()
1156ec
1156ee98 6614d
1156eed0 6614d
把他们放在一起，看起来如下：
0:066> k 2000
ChildEBP RetAddr
1156e7b0 7d4e
1156e858 79ed98fd kernel32!WaitForMultipleObjectsEx+0x
1156e
1156e8e0 79ed9808 mscorwks!Thread::DoAppropriateAptStateWait+0x
1156e964 79ed
1156e9b4 79ed
1156ea10 79e78944 mscorwks!CLREvent::WaitEx+0xf7
1156ea24 79ed7b37 mscorwks!CLREvent::Wait+0x17
1156eab0 79ed
1156eacc
1156eb34 79fc6352 mscorwks!AwareLock::Contention+0x199
1156ebd4 0ff10dd3 mscorwks!JITutil_MonContention+0xa3
1156ea
1156eb88 7d61d051 [HelperMethodFrame: 1156eb88]
System.Threading.Monitor.Enter(System.Object)
1156ebdc 0ff10dd3 DataLayer.GetFeaturedProducts()
1156ec18 0ff
1156ec58
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()
1156ec
1156ee98 6614d
1156eed0 6614d
从这个调用堆栈中，我们从下往上读，可以看到 FeaturedProducts.Page_Load函数调用了DataLayer.GetFeaturedProducts() 这个函数，而这个函数调用了Monitor.Enter()，这是 .net 中尝试得到一个锁（lock）的象征。这个代码应该看起来和下面的类似：
void GetFeaturedProducts(){
...
lock(...){
// do something
}
...
}
我们在lock(….)这个地方卡住了，因为其他人已经占有了这块东西。
寻找假死（hang）的问题点
1） 找到拥有锁（lock）的线程ID
!syncblk
Q：那一个线程有锁？
A：我的 !syncblk 报告如下：
0:066> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
20
-----------------------------
Total 22
CCW 2
RCW 0
ComClassFactory 0
Free 5
拥有这个锁（lock）的线程是在最后几列（Owning Thread Info），这里是30，这个线程就是GetFeaturedProducts() 正在做些事情的部分，或者说拥有了我们都要进取的锁的部分。
Q：有多少线程在等待这个锁？提示：MonitorHeld =1 代表拥有者，2代表等待者。
A：MonitorHeld 这里的值是85，意味着我们有一个拥有者和84/2=42个等待者，有42个等待着的请求要这个锁（lock）如果我们运行：
.shell -ci "~* e !clrstack" FIND /C "Monitor.Enter"
看看在这些调用堆栈中有多少个Monitor.Enter，它返回42，这个我们刚才的值吻合。
2）拿一个等待者（提示：等待者会被标志为AwareLock::Enter），然后看看它在干什么。
~5s （切换到5号线程）
kb 2000 （检查本地栈）
!clrstack （检查.net 栈）
Q：哪一个.net 的函数在等待锁？
A：DataLayer.GetFeaturedProducts()
3） 看看锁拥有者在干什么
~30s （切换到30号线程，上面我们看到是30号线程是拥有者）
kb 2000 （检查本地栈）
!clrstack （检查.net 栈）
Q：为什么会堵塞？
A：30号线程中DataLayer.GetFeaturedProducts() 调用 Thread.Sleep()，所以这个可以解释为什么会阻塞。
0:030> !clrstack
OS Thread Id: 0x1ea0 (30)
ESP EIP
1036ec88 7d61cca8 [HelperMethodFrame: 1036ec88] System.Threading.Thread.SleepInternal(Int32)
1036ecdc 0ff10ddd DataLayer.GetFeaturedProducts()
1036ed18 0ff
4） 检查.net 源代码，看看占有锁的函数，然后验证你的理论。
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 = new DataTable();
DataRow dr;
...
}
...
}
和希望的一样，GetFeaturedProducts() 拿了一个锁，让线程延迟了5秒，这里只说一个很长时间操作的占位符，使用了一个sleep来简化类似的操作。要使这个效果减弱在很大程度上依赖于应用程序，进一步说，就是依赖于这个操作的时间有多长，要找出它们，如果线程阻塞得比想象中的要长，通过重复的寻找来确保我们仅仅锁住了最小一部分的代码来避免很多请求等待单个资源。
提示
这里还有一些英文的非常有用的文章：
Things to ignore when debugging an ASP.NET Hang - Update for .NET 2.0
A Hang Scenario, Locks and Critical Sections
