Learning Tess WinDbg Debugging: (i) thread hang dwell analysis

First, preparatory work

1, download example: Buggybits.zip

Use IIS to set up the downloaded site. Visit the home page to make sure the site is working.

Local can use the main header +host table, set up virtual domain name, such as: www.buggybits.com

2. Download concurrent Test tools: IIS6 Resource Tools

For this experiment, when the resource tool is installed, you only need to check the installation Tinyget tool.

second, simulate the status of the site hang live

1. Request Address: Http://www.buggybits.com/FeaturedProducts.aspx

View the bottom of the site:

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

2. Open 5 browser windows at the same time, access the Web page, and view task management to view the CPU of the w3wp.exe process. When the page finishes, view the time at the bottom of each page:

It should be that every page is incremented by almost 4-5 seconds. But in the page request process, the CPU usage rate is still very low.

It can be inferred that there are a large number of line thread waiting for the release of the same lock during program synchronization.

third, grab dump bag

1, ready to WinDbg grab package script:

Run a command and locate the directory in the WinDbg installation directory, enter the following script, but do not run immediately:

ADPLUS–HANG–PN W3wp.exe–quiet

2. Use Tinyget to simulate concurrent requests:

Run a command again and locate the directory in the Tinyget installation directory and run the following script:

Tinyget-srv:www.buggybits.com-uri:/featuredproducts.aspx-threads:30-loop:50

The following figure:

There are now 30 threads, making 50 concurrent requests.

3, grasping the bag:

Run the script that you prepared in step 1.

At this point, if the package can not be caught, use WinDbg directly attached to w3wp.exe to do analysis.

iv. Analysis of dump packages

1, enter ~* KB 2000 View callstack of local resources

You can see that a large number of thread executions are waiting for a synchronous lock, as follows:

27 id:1200.1100 suspend:1 teb:7ff90000 unfrozen childebp retaddr Args to child 10e3e 998 77d36a04 760b6a36 00000001 10e3e9ec ntdll! Kifastsystemcallret  10e3e99c 760b6a36 00000001 10e3e9ec 00000001 ntdll! ZWWAITFORMULTIPLEOBJECTS+0XC 10e3ea38 77a4bd1e 10e3e9ec 10e3ea60 00000000 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 Thread::D oappropriateaptstatewait+0x3c 10e3eb8c 5847436d 00000001 0145b748 00000000 mscorwks! Thread::D oappropriatewaitworker+0x13c 10e3ebdc 584744f1 00000001 0145b748 00000000 mscorwks! Thread::D oappropriatewait+0x40 10e3ec38 58315402 ffffffff 00000001 00000000 mscorwks! Clrevent::waitex+0xf7 10e3ec4c 584498ea ffffffff 00000001 00000000 mscorwks! clrevent::wait+0x17 

But you can find out if a thread is sleeping or about to start sleeping:

  id:1200.14e0 suspend:1 teb:7ff2f000 unfrozen childebp retaddr to child              
Args 1094E7FC-77d357d4 876 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 Threadnative::sleep+0xce

2, enter ~*e!clrstack, view the callstack of. Net

There are a lot of threads that are doing System.Threading.Monitor.Enter (System.Object)

OS Thread id:0x1534 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 [Ndirectmethodframestand ALONE: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] 
 

But there's a thread, still sleep

OS Thread id:0x14e0 ESP EIP1094e950 77d37094 [helpermethodframe:1094e950] System.Threading.Thread.SleepInternal (Int32)1094e9a40e460e85 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] 
 

It is this thread that occupies the sync lock, but does not work in bed. Basically can locate, the synchronization here, there is a problem.

3, input!syncblk, view the thread, the lock information.

0:022>!syncblk
Index syncblock monitorheld recursion owning Thread Info  syncblock Owner
   0145b734         1 10c5e5e8  14e0   0590fc98 System.Object
-----------------------------
Total           Panax Notoginseng
CCW             2
RCW             2
comclassfactory 0
Free            11

To view the Info column, the line one thread with ID 28 occupies the lock. To view the Monitorheld and recursion columns, you can draw a total of (17-1)/2 = 9 threads in the preemption 0590fc98 of the sync lock.

4, the use of!IP2MD 0e460e85, to find access to the lock, the implementation of the relevant methods of model information.

0:022>!ip2md 0e460e85
methoddesc:008b9520 method
Name:DataLayer.GetFeaturedProducts ()
Class: 01231a20
methodtable:008b9538
mdtoken:06000008
module:008b8b28
isjitted:yes
codeaddr: 0e460e50

5, you can use the following three methods for further analysis of module:

1 Use!dumpil 008b9520 to view the IL code of the method, which is the intermediate language code. Where 008b9520 is the value of MethodDesc. (Here you can try it yourself).

2 Use!u 0e460e50 to view the disassembly code of the method, where the 0e460e50 is the CODEADDR value. (Here you can try it yourself)

3 Use!dumpmodule 008b8b28 to view the information of the module in which the method is located, and the 008b8b28 is the value for module, this method is used here.

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. Use the!savemodule 008b8b28 D:\dump\hang.dll to save the module to the D:\dump\hang.dll path.

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
, Filead DR=2C00, filesize=200

7, use the. NET reflector to view the Hang.dll and navigate to the DataLayer method after obtaining the Sync Lock: getfeaturedproducts ()

So, after getting the sync lock, the thread does sleep for 5 seconds.

To this end, the entire thread hang analysis has been completed.