学习Tess的Windbg调试：（一）线程Hang住分析

一、准备工作

1、下载例子：BuggyBits.zip

使用IIS将下载的下来的站点架设起来。访问下主页，确保网站正常运行。

本地可以使用主机头+HOST表，建立虚拟域名，比如：www.buggybits.com

2、下载并发测试工具：IIS6 资源工具

对于本实验，该资源工具安装时，只需要勾选安装TinyGet工具。

二、模拟网站Hang住的状态

1、请求地址：http://www.buggybits.com/FeaturedProducts.aspx

查看网站底部：

[start time: 11:59:54] [execution time: 5.161 seconds]              

2、同时开启5个浏览器窗口，同时访问该网页，并查看任务管理，查看w3wp.exe进程的CPU。页面执行完成后，查看各网页底部执行的时间：

应该是每个页面都差不多有4-5秒的递增。但在页面请求过程中，CPU却使用率依然很低。

由此可以推断，程序同步过程中，有大量线程在等着同一个锁的释放。

 三、抓取DUMP包

1、准备好windbg的抓包脚本：

运行一个Command，并将目录定位到windbg安装目录，输入下面脚本，但不立即运行：

adplus –hang –pn w3wp.exe –quiet

2、使用TinyGet模拟并发请求：

再运行一个Command，并将目录定位到TinyGet的安装目录，运行以下脚本：

tinyget -srv:www.buggybits.com -uri:/FeaturedProducts.aspx -threads:30 -loop:50

如下图：

现在已有30个线程，做50次并发请求。

3、抓包：

运行步骤1 所准备下的脚本。

此时，若包无法抓下，可使用windbg直接附加到w3wp.exe去做分析。

四、分析DUMP包

1、输入~* kb 2000 查看本地资源的callstack

可看出大量线程执行，都在等待一个同步锁，如下:

27  Id: 1200.1100 Suspend: 1 Teb: 7ff90000 Unfrozen
ChildEBP RetAddr  Args to Child              
10e3e998 77d36a04 760b6a36 00000001 10e3e9ec ntdll!KiFastSystemCallRet
10e3e99c 760b6a36 00000001 10e3e9ec 00000001 ntdll!ZwWaitForMultipleObjects+0xc
10e3ea38 77a4bd1e 10e3e9ec 10e3ea60 00000000 KERNELBASE!WaitForMultipleObjectsEx+0x100
10e3ea80 584745a2 00000001 7ffd7000 00000000 kernel32!WaitForMultipleObjectsExImplementation+0xe0
10e3eae8 584741cf 00000001 0145b748 00000000 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0x6f
10e3eb08 584742d8 00000001 0145b748 00000000 mscorwks!Thread::DoAppropriateAptStateWait+0x3c
10e3eb8c 5847436d 00000001 0145b748 00000000 mscorwks!Thread::DoAppropriateWaitWorker+0x13c
10e3ebdc 584744f1 00000001 0145b748 00000000 mscorwks!Thread::DoAppropriateWait+0x40
10e3ec38 58315402 ffffffff 00000001 00000000 mscorwks!CLREvent::WaitEx+0xf7
10e3ec4c 584498ea ffffffff 00000001 00000000 mscorwks!CLREvent::Wait+0x17

但可以查找到一个线程是正在睡眠或是即将启动睡眠：

28  Id: 1200.14e0 Suspend: 1 Teb: 7ff2f000 Unfrozen
ChildEBP RetAddr  Args to Child              
1094e7fc 77d357d4 760b1876 00000001 1094e844 ntdll!KiFastSystemCallRet
1094e800 760b1876 00000001 1094e844 749940b2 ntdll!ZwDelayExecution+0xc
1094e868 583280b0 00001388 00000001 7487be37 KERNELBASE!SleepEx+0x65
1094e89c 5844834f 00001388 00000001 1094e8c0 mscorwks!EESleepEx+0xbb
1094e8ac 5844833d 58877df0 00001388 00000001 mscorwks!CExecutionEngine::ClrSleepEx+0xe
1094e8c0 584482fc 00001388 00000001 7487be57 mscorwks!ClrSleepEx+0x14
1094e8fc 584483fd 00001388 7487bf37 1094e9c8 mscorwks!Thread::UserSleep+0x63
1094e99c 0e460e85 00000000 00000001 00000000 mscorwks!ThreadNative::Sleep+0xce

2、输入~*e !clrstack， 查看.net的callstack

有很多线程，都在做System.Threading.Monitor.Enter(System.Object)

OS Thread Id: 0x1534 (30)
ESP       EIP     
1090ea14 77d37094 [GCFrame: 1090ea14] 
1090eb50 77d37094 [HelperMethodFrame: 1090eb50] System.Threading.Monitor.Enter(System.Object)
1090eba4 0e460e7b DataLayer.GetFeaturedProducts()
1090ebe0 0e460cdf FeaturedProducts.Page_Load(System.Object, System.EventArgs)
1090ec6c 66e0a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
1090ec7c 50c85d04 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
1090ec90 50c7f204 System.Web.UI.Control.OnLoad(System.EventArgs)
1090eca4 50c7f243 System.Web.UI.Control.LoadRecursive()
1090ecbc 50c7b2f4 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
1090ee14 50c7af24 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
1090ee4c 50c7ae51 System.Web.UI.Page.ProcessRequest()
1090ee84 50c7ade6 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
1090ee90 50c7adc2 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
1090eea4 0e460215 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)
1090eea8 50c81296 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1090eedc 50c53aac System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1090ef1c 5124cb6a System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
1090ef20 512437dc [InlinedCallFrame: 1090ef20] 
1090efc4 5122d2d1 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
1090f034 513022c6 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
1090f038 5130208f [InlinedCallFrame: 1090f038] 
1090f584 008d6e8b [NDirectMethodFrameStandalone: 1090f584] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
1090f594 51302373 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
1090f61c 5130208f System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
1090f71c 008d6e8b [ContextTransitionFrame: 1090f71c] 

但有一个线程，还在sleep

OS Thread Id: 0x14e0 (28)
ESP       EIP     
1094e950 77d37094 [HelperMethodFrame: 1094e950] System.Threading.Thread.SleepInternal(Int32)
1094e9a4 0e460e85 DataLayer.GetFeaturedProducts()
1094e9e0 0e460cdf FeaturedProducts.Page_Load(System.Object, System.EventArgs)
1094ea6c 66e0a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
1094ea7c 50c85d04 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
1094ea90 50c7f204 System.Web.UI.Control.OnLoad(System.EventArgs)
1094eaa4 50c7f243 System.Web.UI.Control.LoadRecursive()
1094eabc 50c7b2f4 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
1094ec14 50c7af24 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
1094ec4c 50c7ae51 System.Web.UI.Page.ProcessRequest()
1094ec84 50c7ade6 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
1094ec90 50c7adc2 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
1094eca4 0e460215 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)
1094eca8 50c81296 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1094ecdc 50c53aac System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1094ed1c 5124cb6a System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
1094ed20 512437dc [InlinedCallFrame: 1094ed20] 
1094edc4 5122d2d1 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
1094ee34 513022c6 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
1094ee38 5130208f [InlinedCallFrame: 1094ee38] 
1094f384 008d6e8b [NDirectMethodFrameStandalone: 1094f384] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
1094f394 51302373 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
1094f41c 5130208f System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
1094f51c 008d6e8b [ContextTransitionFrame: 1094f51c] 

正是这个线程，占据了同步锁，但却在睡觉不干活。基本可以定位，此处的同步，有问题。

3、输入!syncblk，查看线程中，锁的信息。

0:022> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
   35 0145b734           17         1 10c5e5e8  14e0  28   0590fc98 System.Object
-----------------------------
Total           37
CCW             2
RCW             2
ComClassFactory 0
Free            11

查看Info列，ID为28的线程正占据着这个锁。查看MonitorHeld列和Recursion列，可以得出，总共有（17-1）/ 2 = 9个线程在抢占0590fc98的同步锁。

4、使用!ip2md 0e460e85，找到进入得到锁后，执行相关方法的model信息。

0:022> !ip2md 0e460e85
MethodDesc: 008b9520
Method Name: DataLayer.GetFeaturedProducts()
Class: 01231a20
MethodTable: 008b9538
mdToken: 06000008
Module: 008b8b28
IsJitted: yes
CodeAddr: 0e460e50

5、可以使用以下三种方法对Module进一步分析：

1）使用!dumpil 008b9520，查看方法的IL代码，即中间语言代码。其中008b9520为MethodDesc的值。（此处可以自己试试）。

2）使用!u 0e460e50，查看方法的反汇编代码，其中的0e460e50为CodeAddr的值。（此处可以自己一试）

3）使用!dumpmodule 008b8b28，查看方法所在模块的信息，其中的008b8b28为Module的值，此处使用这个方法。

0:022> !dumpmodule 008b8b28
Name: C:\Windows\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\root\8e889acd\9c75063f\App_Code.h2r81bty.dll
Attributes: PEFile 
Assembly: 014982e0
LoaderHeap: 00000000
TypeDefToMethodTableMap: 008b0ad4
TypeRefToMethodTableMap: 008b0b00
MethodDefToDescMap: 008b0b80
FieldDefToDescMap: 008b0be4
MemberRefToDescMap: 008b0c0c
FileReferencesMap: 008b0ccc
AssemblyReferencesMap: 008b0cd0
MetaData start address: 62ca29a0 (6660 bytes)

6、使用!savemodule  008b8b28 d:\dump\hang.dll，将module保存到d:\dump\hang.dll路径。

0:022> !savemodule 008b8b28 d:\dump\hang.dll
3 sections in file
section 0 - VA=2000, VASize=2404, FileAddr=200, FileSize=2600
section 1 - VA=6000, VASize=2c8, FileAddr=2800, FileSize=400
section 2 - VA=8000, VASize=c, FileAddr=2c00, FileSize=200

7、使用.net Reflector查看hang.dll，并定位到DataLayer获取同步锁后的方法：GetFeaturedProducts()

由此可知，在获取同步锁后，线程确实sleep了5秒。

到此，整个线程Hang的分析已全部完成。