If broken it is, fix it you should

Using the powers of the debugger to solve the problems of the world - and a bag of chips    by Tess Ferrandez, ASP.NET Escalation Engineer (Microsoft)

.NET Debugging Demos Lab 1: Hang - Review

.NET Debugging Demos Lab 1: Hang - Review

Rate This
  • Comments 54

Earlier this week I published the first .NET Debugging Demos Lab. If you haven't downloaded and tried it out you can get it here.

This is a review of this lab with answers to the questions and comments inline in red.

Note: results and thread IDs will vary depending on how fast you click and what machine you have and what threads the request happen to run on, so I will answer with the results from my dual-proc W2k3 machine.

Reproduce the problem:

1. Browse to http://localhost/BuggyBits/FeaturedProducts.aspx
This should take about 5 seconds to show, you can see the start time and execution time the bottom of the page.

2. Open up 5 browsers, all browsing to this site and refresh them simultaneously

Note the execution time for each of them and make sure that the start time is pretty much the same on all (otherwise you probably didn’t run the reg file)

Q:  What are the execution times?

A:   Browser 1 - 5.0 s, Browser 2 - 9.1 s, Browser 3 - 12.57 s, Browser 4 - 16.07 s, Browser 5 - 18.61 s (if you don't see increasing execution times check that you ran the reg. file, otherwise there will be a 5 sec delay between the starttimes for all requests)

Q:  What is the CPU usage of the w3wp.exe process when reproing the problem? High or low CPU?

A:  Very low CPU usage, 0-5%

Q:  What are some potential reasons for a hang with these symptoms?

A:  Since the request times are increasing and CPU usage is low it appears that a) we are waiting on some common resource which can only be used by one thread at a time, and b) we are not in a tight loop so we are likely blocked waiting for some external resource or similar

Get a memory dump:

1. Start a command window and browse to your debuggers directory.  Type the following command to prepare taking the dump but don’t hit enter quiet yet.
adplus –hang –pn w3wp.exe –quiet

Note: The quiet switch is used so that we won't get popup boxes asking for more info since we don't have that much time to get the dump before the requests finish.  You will typically get a message box asking you to set cscript as your default script, one telling you that you haven't set up your symbol path in the environment variables and one informing you that you are about to gather a hang dump.  You can simply click yes to all of these.

2. Reproduce the problem either by browsing with 5 browsers as you did before or by stressing the site with tinyget with the following command line

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

Note: This will start 30 threads and send 50 requests to the FeaturedProducts.aspx

3. Hit enter in the adplus command window to take the memory dump while the requests are still executing.

Q: In adplus hang mode, what triggers the generation of the memory dump?

A:  This is a bit of a trick question. The generation of the dump is triggered by you running adplus,  i.e. it doesn't wait for a hang condition of any kind (unlike the -crash switch) so you can take a dump with -hang anytime without the process actually hanging and this is what you do in high memory situations for example.


Q: What permissions do you need to take a memory dump of a process?

A: Debugging with windbg/adplus is no different than debugging with other debuggers in terms of permissions.  You need to own the process or have higher permissions.  In hang mode dumps are taken in non-invasive mode meaning that we don't actually break in to the process.  Therefore you don't need to be on the same winstation where the process started to take a -hang dump which is useful when debugging services through terminal server.  In crash mode on the other hand you need to be in the same winstation where the process started so for services this means you need to log in with /console if you log in with terminal server or remote desktop.


Q: Where are the dumps created? Hint: check the windbg help for adplus/hang mode

A: The default location for dumps is in the debuggers directory where a new folder will be created everytime you run adplus with -hang or -crash.  The folder will be named something like C:\debuggers\32bit\Hang_Mode__Date_02-06-2008__Time_11-15-0505. 

The folder will contain the following items

  • CDBScripts - a folder with a config file used to instruct windbg/cdb on what commands to run
  • ADPlus_report.txt - information about what happened, i.e. adplus attached to the process etc.
  • PID-5656__W3WP.EXE__Date_02-06-2008__Time_11-15-0505.log - log file of the run, in hang mode this includes stacks of all threads, loaded modules info and !runaway output.  If no dumpfile was created you should look at the bottom of this log to see why
  • PID-5656__W3WP.EXE__full_1c38_2008-02-06_11-15-08-005_1618.dmp - the dump file
  • Process_List.txt - tlist.exe output, showing all processes running on the system at the time the dump was taken

Open the dump in Windbg.exe

1. Open windbg and open the memory dump (.dmp file) with File/Open Crash dump.

2. Set up the symbol path (see Information and Setup Instructions for more info)

3. Load sos (see Information and Setup Instructions for more info)

Examine the stacks

1. Examine the native callstacks

~* kb 2000

2. Examine the .net callstacks

~* e !clrstack

Q:  Do you see any patterns or recognize any of the callstacks that suggests a thread is waiting for a synchronization mechanism?

A:  There are a lot of threads with the following native callstacks where the frames in italic are frames that windbg could not interpret because they are managed/.net

0:066> k 2000
ChildEBP RetAddr  
1156e7b0 7d4e286c ntdll!ZwWaitForMultipleObjects+0x15 
1156e858 79ed98fd kernel32!WaitForMultipleObjectsEx+0x11a 
1156e8c0 79ed9889 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0x6f
1156e8e0 79ed9808 mscorwks!Thread::DoAppropriateAptStateWait+0x3c
1156e964 79ed96c4 mscorwks!Thread::DoAppropriateWaitWorker+0x13c
1156e9b4 79ed9a62 mscorwks!Thread::DoAppropriateWait+0x40
1156ea10 79e78944 mscorwks!CLREvent::WaitEx+0xf7
1156ea24 79ed7b37 mscorwks!CLREvent::Wait+0x17
1156eab0 79ed7a9e mscorwks!AwareLock::EnterEpilog+0x8c
1156eacc 79f59024 mscorwks!AwareLock::Enter+0x61
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
1156ee8c 6614d8c3 mscorlib_ni+0x2ee896
1156eec4 6614d80f System_Web_ni+0x22d8c3
1156ef00 6614d72f System_Web_ni+0x22d80f
1156ef20 65fe6bfb System_Web_ni+0x22d72f
1156ef54 65fe3f51 System_Web_ni+0xc6bfb
1156ef90 65fe7733 System_Web_ni+0xc3f51
1156efe4 65fccbfe System_Web_ni+0xc7733
1156eff8 65fd19c5 System_Web_ni+0xacbfe
1156f01c 7938111c System_Web_ni+0xb19c5
00000000 00000000 mscorlib_ni+0x2c111c

And the following .NET callstacks

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+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1156ef5c 65fe3f51 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1156ef9c 65fe7733 System.Web.HttpApplication+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] 

If we put them together, the stacks for these threads would look something like this

0:066> k 2000
ChildEBP RetAddr  
1156e7b0 7d4e286c ntdll!ZwWaitForMultipleObjects+0x15 
1156e858 79ed98fd kernel32!WaitForMultipleObjectsEx+0x11a 
1156e8c0 79ed9889 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0x6f
1156e8e0 79ed9808 mscorwks!Thread::DoAppropriateAptStateWait+0x3c
1156e964 79ed96c4 mscorwks!Thread::DoAppropriateWaitWorker+0x13c
1156e9b4 79ed9a62 mscorwks!Thread::DoAppropriateWait+0x40
1156ea10 79e78944 mscorwks!CLREvent::WaitEx+0xf7
1156ea24 79ed7b37 mscorwks!CLREvent::Wait+0x17
1156eab0 79ed7a9e mscorwks!AwareLock::EnterEpilog+0x8c
1156eacc 79f59024 mscorwks!AwareLock::Enter+0x61
1156eb34 79fc6352 mscorwks!AwareLock::Contention+0x199
1156ebd4 0ff10dd3 mscorwks!JITutil_MonContention+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+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1156ef5c 65fe3f51 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1156ef9c 65fe7733 System.Web.HttpApplication+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] 

So we can see from this stack (reading it from the bottom up just like in visual studio) that FeaturedProducts.Page_Load calls a method DataLayer.GetFeaturedProducts(). 
This in turn calls Monitor.Enter() which is done when trying to get a .net lock

The code for GetFeaturedProducts should look something like this

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


and we are stuck on the lock(...) line because someone else has grabbed the lock

Troubleshoot the hang

1. Determine the ID of the thread owning the lock
!syncblk

Q: What thread owns the lock?

A: My !syncblk reports the following after reproing with tinyget

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

The thread that owns the lock is the last column under Owning Thread Info (In this case thread 30), so this is the thread that is in the //do something portion
of the GetFeaturedProducts() above, or otherwise holds the lock that we are trying to enter
 

Q: How many threads are waiting for the lock?
Hint: MonitorHeld = 1 for each owner and 2 for each waiter.

A: MonitorHeld here is 85 which means that we have one owner and 84/2=42 waiters, i.e. 42 requests waiting for the lock, if i run

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

to see how many callstacks are sitting in a Monitor.Enter it returns 42 which jives well with this.

The fact that 42 is the answer to Life, the Universe and Everything is pure coincidence:)

2. Pick one of the waiters (Hint: waiters will sit in AwareLock::Enter) and take a look at what it is doing.

~5s                          (move to thread 5, replace 5 with actual thread ID)
kb 2000                    (examine native stack)
!clrstack                    (examine .net stack)

Q: In which .net function is it waiting for the lock?

A: DataLayer.GetFeaturedProducts()

3. Determine what the owning thread is doing 

~5s                          (move to thread 5, replace 5 with actual thread ID)
kb 2000                    (examine native stack)
!clrstack                    (examine .net stack)

Q: Why is it blocking?

Thread 30 appears to be sitting in a Thread.Sleep() called from DataLayer.GetFeaturedProducts() so this would explain why we are blocking there (while holding the lock)

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+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
1036f05c 65fe3f51 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
1036f09c 65fe7733 System.Web.HttpApplication+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. Examine the code for .NET method owning the lock to verify your theory.

    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;
             ...
        }
        ...
    }

As expected GetFeaturedProducts() takes a lock and then sits in a sleep for 5 seconds,  this is of course a place holder for a long running operation, but a sleep is easier to use to get a consistent repro in a demo.  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.

Hope you found the lab interesting, I will try to get the next lab (a crash scenario) out by the end of the week. 

Feel free to add your own comments if you think I missed something in my answers or if your answers differ from mine (other than thread ids, number of waiters etc.) or if you didn't like the lab format at all and think it would be better to have more or for that matter less details in the instructions...

Have fun,

Tess

  • Baal,  for the error, see the answer to the comment...

    re, clicking as fast as possible, try putting the pages side by side, each page should take 5 seconds to load.

    For the .shell,  not sure where /c: /c: is comming from the command looks right

  • " the owner of the lock holds one monitor, that means that there are 84 monitors left for the waiters (threads waiting for the lock).  84/2 = 42, meaning we have 42 threads waiting for the lock"

    Can you explain why each waiting thread has two monitors?

  • To be honest I haven't really looked into the details.  I just know that this is always the case from looking at the number of waiting threads and the number of monitors that syncblk shows

  • Thank you for your reply. I may ask a too simple question. If somebody asks me why 1+1=2, I won't have any answer either. I learned a lot from your blogs, by far the best blog I have ever read.

  • Hey Tess,

    What's the difference between "~* e !clrstack" and "!clrstack"?

  • !clrstack shows you the .net stack of the current thread.  ~* e !clrstack shows you the .net stacks of all threads.

    ~ means thread

    * means all

    e means evaluate

  • You should use the aspnet_wp.exe on XP(IIS 5.X) to capture the dump

    adplus -hang -pn aspnet_wp.exe -quiet

  • 前几天我翻译了Tess debug系列的第一篇文章以及和大家介绍了一些debugger tools的基本命令。今天我们将一起讨论Tess关于debug 系列的第二篇文章。Tess在每个系列中都使用了问题 结果的结构,为了简化,我将把问题和结果一起给大家。此外,大家在自己机器上重现这些问题的时候,由于机器的差异,许多问题的结果都可能和Tess的不一样,这个不要紧,只要大家能够掌握原理就可以了。

  • Awesome.  The only resource I have ever found on windows debugging that is very lucid and easy to follow. Few suggestions. When I did the first lab, I did not know a lot about some of the command..for example..~ means thread,~. current thread, ~* all htreads in the process k means stack trace and e means commands enter into memory and so on..some basic tutorial of sorts on this as a first tutorial might help.. ofcourse it was not difficult to read from help...I suggest you write a book..Thank you

  • Hi Tess,

    I've just started your labs series. I am using Windows 2008 Server x64 and WinDbg 6.11.0001.404.

    My problem is that the stack traces are a bit different on this environment, and the most important stuff is not in the trace, e.g. the managed stack looks like this:

    OS Thread Id: 0x11b4 (21)

    Child-SP         RetAddr          Call Site

    0000000005fcdf80 000007ff001f151b DataLayer.GetFeaturedProducts()

    0000000005fce010 000007fef5433ec9 FeaturedProducts.Page_Load(System.Object, System.EventArgs)

    0000000005fce0a0 000007feedb36aea System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)

    0000000005fce0d0 000007feedb2d2c4 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)

    0000000005fce100 000007feedb2d322 System.Web.UI.Control.OnLoad(System.EventArgs)

    0000000005fce140 000007feedb298ac System.Web.UI.Control.LoadRecursive()

    0000000005fce190 000007feedb28db0 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)

    0000000005fce260 000007feedb28cdb System.Web.UI.Page.ProcessRequest(Boolean, Boolean)

    0000000005fce2c0 000007feedb28c70 System.Web.UI.Page.ProcessRequest()

    0000000005fce320 000007ff001f03e9 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)

    0000000005fce380 000007feedb30117 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)

    0000000005fce3b0 000007feedaf449b System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()

    0000000005fce460 000007feedb02215 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)

    0000000005fce500 000007feedaf3553 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)

    0000000005fce5b0 000007feedaf7874 System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)

    0000000005fce610 000007feedaf745c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)

    0000000005fce6a0 000007feedaf608c System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)

    0000000005fce6e0 000007fefa342322 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)

    As you see, it's missing the line with Monitor.Enter.

    Do you know what can cause this?

  • Not sure why it is missing to be honest, might be a difference of framework version... how does the native stack look (kb 2000)?

  • This is what returned by kb 2000:

    0:000> kb 2000

    RetAddr           : Args to Child                                                           : Call Site

    00000000`77b3c730 : 00000000`00000000 000007fe`fb6d7efb 00000000`00000000 000007fe`fc2f15c0 : ntdll!ZwWaitForSingleObject+0xa

    000007fe`fc2f3d04 : 00000000`00000148 00000000`ffa65de0 00000000`00000000 00000000`00000148 : kernel32!WaitForSingleObjectEx+0x9c

    00000000`ffa62332 : 00000000`fffffffe 00000000`00000001 00000000`001462a0 00000000`0000008c : w3wphost!AppHostInitialize+0x280

    00000000`ffa63b09 : 00000000`00000000 00000000`ffa63c7d 00000000`00000000 00000000`00000000 : w3wp!wmain+0x45e

    00000000`77b3466d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : w3wp!PerfStopProvider+0x199

    00000000`77c68791 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd

    00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

    I think this is more like what you are looking for:

    0:000> ~26 kb 2000

    RetAddr           : Args to Child                                                           : Call Site

    00000000`77b3c648 : 00000000`00000000 00000000`08ed43d1 00000000`ffffffff 00000000`0264e490 : ntdll!NtDelayExecution+0xa

    000007fe`fa5c897d : 00000000`00000000 00000000`00000001 ffffffff`fd050f80 00000000`0264e490 : kernel32!SleepEx+0x84

    000007fe`fa193af5 : 00000000`02577870 000007fe`fa2ca082 00000000`00001388 00000000`00001388 : mscorwks!EESleepEx+0x2d

    000007fe`fa7747a9 : 06000000`00000001 00000001`bfadecf0 00000001`bfae0130 00000000`00001388 : mscorwks!Thread::UserSleep+0x71

    000007ff`001f16c9 : 000007fe`00001388 00000000`00000000 000007fe`ed90b180 000007fe`ee1e0abd : mscorwks!ThreadNative::Sleep+0xf9

    000007ff`001f14fb : 00000001`3fa965a0 00000000`00000003 00000000`00000000 00000000`00000000 : 0x7ff`001f16c9

    000007fe`f5e33ec9 : 00000001`ffa7a8e0 00000001`bfae2500 00000001`bfae1978 000007fe`eda94078 : 0x7ff`001f14fb

    000007fe`edb36aea : 00000001`bfae0828 000007fe`ee2354d0 00000001`bfadecf0 00000001`3faef0c0 : System_Web_RegularExpressions_ni+0x33ec9

    000007fe`edb2d2c4 : 00000000`00000000 00000001`bfae0828 00000001`bfadecf0 00000001`bfae0828 : System_Web_ni+0x2a6aea

    000007fe`edb2d322 : 00000001`bfae0130 000007fe`edaf649b 00000001`bfadecf0 00000000`00000000 : System_Web_ni+0x29d2c4

    000007fe`edb298ac : 48cb906b`7f178aad 000007fe`edbf9388 00000001`bfadecf0 00000001`3fbf2508 : System_Web_ni+0x29d322

    000007fe`edb28db0 : 00000001`bfadecf0 00000001`ffa7c801 00000001`bfada101 000007fe`f156c8ff : System_Web_ni+0x2998ac

    000007fe`edb28cdb : 00000001`bfadecf0 00000001`ffa7c8f8 00000001`bfad9001 00000000`00000003 : System_Web_ni+0x298db0

    000007fe`edb28c70 : 00000001`bfadecf0 000007fe`f1c04be0 00000001`bfadf090 000007fe`edb06625 : System_Web_ni+0x298cdb

    000007ff`001f03c9 : 00000001`bfada8f0 00000001`bfad8f10 00000001`bfaddf10 00000000`053ce7e0 : System_Web_ni+0x298c70

    000007fe`edb30117 : 00000000`053ce780 000007fe`edaf649b 00000000`4190ab00 000007fe`edaf649b : 0x7ff`001f03c9

    000007fe`edaf449b : 00000001`7fb14678 000007fe`edb02ae9 00000000`00000000 ef000003`80000008 : System_Web_ni+0x2a0117

    000007fe`edb02215 : 00000001`bfad9f10 00000001`bfaddf10 00000000`053ce938 000007fe`edae2be2 : System_Web_ni+0x26449b

    000007fe`edaf3553 : 00000001`bfadda50 00000000`00000000 00000001`bfad8f10 000007fe`edaf649b : System_Web_ni+0x272215

    000007fe`edaf7874 : 000007fe`edc80bb0 000007fe`f15782f5 00000000`053cee18 00000000`00000000 : System_Web_ni+0x263553

    000007fe`edaf745c : 00000001`7fb144a0 00000001`bfad7048 00000000`00000035 00000000`00000005 : System_Web_ni+0x267874

    000007fe`edaf608c : 00000000`ffffffff 00000000`0296eeb0 00000000`053cee18 00000000`00000002 : System_Web_ni+0x26745c

    000007fe`fa342322 : 00000001`3faad3a0 00000000`0296eeb0 00000000`00000002 ffffffff`fffffffe : System_Web_ni+0x26608c

    000007fe`fa243bb3 : 00000000`053cecf0 00000000`053cedc0 ffffffff`fffffffe 00000000`00000000 : mscorwks!CallDescrWorker+0x82

    000007fe`fa2651f8 : 00000000`053cee00 00000000`053cf3c0 00000000`00000003 00000000`00000003 : mscorwks!CallDescrWorkerWithHandler+0xd3

    000007fe`fa265563 : 00000000`0199fc70 00000000`00081800 00000001`00000000 000007fe`00000004 : mscorwks!ForwardCallToManagedMethod+0x160

    000007fe`fa284738 : 00000000`0258dcd0 00000000`0264e490 00000000`02930158 00000000`02930220 : mscorwks!COMToCLRWorkerBody+0x35b

    000007fe`fa24c8ae : 00000000`00000000 000007ff`ffee6000 00000000`053cf400 00000000`00000000 : mscorwks!COMToCLRWorkerDebuggerWrapper+0x50

    000007fe`fa34249e : 00000000`0264e490 00000000`053cf400 ffffffff`ffffff00 00000000`00000000 : mscorwks!COMToCLRWorker+0x366

    00000642`fff58293 : 00000000`0129fda0 00000000`0296eeb0 00000000`00000002 00000000`053cf460 : mscorwks!GenericComCallStub+0x5e

    00000642`fff58633 : 00000000`00000000 00000000`0296eeb0 00000000`01dbd9a0 00000000`00000001 : webengine!HttpCompletion::ProcessRequestInManagedCode+0x2a3

    00000642`fff9abf4 : 000007fe`fa957c78 00000000`00000001 00000642`fff9abd0 00000000`00000001 : webengine!HttpCompletion::ProcessCompletion+0x63

    000007fe`fa1cdc77 : 00000000`00000000 00000000`00000001 00000000`00000000 00000000`00000001 : webengine!CorThreadPoolWorkitemCallback+0x24

    000007fe`fa1e289a : 00000000`00000000 00000000`00000000 00000000`00000002 00000000`0264e490 : mscorwks!UnManagedPerAppDomainTPCount::DispatchWorkItem+0x157

    000007fe`fa15f0ac : 00000000`00000000 00000000`00000000 00000000`053cfda0 00000000`00000000 : mscorwks!ThreadpoolMgr::WorkerThreadStart+0x1ba

    00000000`77b3466d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : mscorwks!Thread::intermediateThreadProc+0x78

    00000000`77c68791 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd

    00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d

    And the managed counterpart:

    0:000> ~26 e! clrstack

    OS Thread Id: 0x1014 (26)

    Child-SP         RetAddr          Call Site

    00000000053ce380 000007ff001f14fb DataLayer.GetFeaturedProducts()

    00000000053ce410 000007fef5e33ec9 FeaturedProducts.Page_Load(System.Object, System.EventArgs)

    00000000053ce4a0 000007feedb36aea System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)

    00000000053ce4d0 000007feedb2d2c4 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)

    00000000053ce500 000007feedb2d322 System.Web.UI.Control.OnLoad(System.EventArgs)

    00000000053ce540 000007feedb298ac System.Web.UI.Control.LoadRecursive()

    00000000053ce590 000007feedb28db0 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)

    00000000053ce660 000007feedb28cdb System.Web.UI.Page.ProcessRequest(Boolean, Boolean)

    00000000053ce6c0 000007feedb28c70 System.Web.UI.Page.ProcessRequest()

    00000000053ce720 000007ff001f03c9 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)

    00000000053ce780 000007feedb30117 ASP.featuredproducts_aspx.ProcessRequest(System.Web.HttpContext)

    00000000053ce7b0 000007feedaf449b System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()

    00000000053ce860 000007feedb02215 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)

    00000000053ce900 000007feedaf3553 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)

    00000000053ce9b0 000007feedaf7874 System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)

    00000000053cea10 000007feedaf745c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)

    00000000053ceaa0 000007feedaf608c System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)

    00000000053ceae0 000007fefa342322 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)

    Thanks!

    And a tip :)

    Apache (the web server) has a nice small load test tool called apache bench (ab). It has similar functionality as tinyget but it has a friendlier command line interface (http://httpd.apache.org/docs/2.0/programs/ab.html). It has a Windows port.

  • Ok, that explain why there was no monitor enter, this thread is sitting in a sleep, not waiting for a lock

  • Coincidentally, thread 26 owned the lock, here's another native stack trace which looks more like your example:

    0:000> ~27 kb

    RetAddr           : Args to Child                                                           : Call Site

    00000000`77b3b362 : 00000000`00000030 00000000`05a4dad0 00000000`05a4d860 00000000`00000000 : ntdll!ZwWaitForMultipleObjects+0xa

    000007fe`fa181299 : 00000000`055d0480 00000000`00000000 00000000`00000000 000007fe`fa18512f : kernel32!WaitForMultipleObjectsEx+0x10b

    000007fe`fa1869bd : ffffffff`00000001 00000000`02577888 00000000`055d0480 000007fe`fa1998b0 : mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0xc1

    000007fe`fa28af55 : 00000000`00000000 00000000`02577888 00000000`00000000 00000000`ffffffff : mscorwks!Thread::DoAppropriateAptStateWait+0x41

    000007fe`fa2b2724 : 00000001`00000000 000007fe`fa6f234d 00000000`02577888 000007fe`00000000 : mscorwks!Thread::DoAppropriateWaitWorker+0x191

    000007fe`fa1d2266 : 00000000`05a4dae8 000007fe`00000001 00000000`ffa7dd00 00000000`00000000 : mscorwks!Thread::DoAppropriateWait+0x5c

    000007fe`fa164251 : 00000000`02577870 00000000`ffffffff 00000000`055d0480 00000000`02577870 : mscorwks!CLREvent::WaitEx+0xbe

    000007fe`fa2ca082 : 00000000`02577870 00000000`02577870 00000000`ffffffff 00000000`00000000 : mscorwks!AwareLock::EnterEpilog+0xc9

    000007fe`fa1a49fb : 00000000`00000007 00000000`ffffffff 00000000`01e01900 00000000`02577870 : mscorwks!AwareLock::Enter+0x72

    000007fe`fa74970f : 00000000`055d0480 00000000`05a4de10 00000000`05a4dcb8 00000000`055d0480 : mscorwks!AwareLock::Contention+0x1fb

    000007ff`001f16be : 00000000`02577870 00000000`00000000 000007fe`ed90b180 000007fe`ee1e0abd : mscorwks!JITutil_MonContention+0xdf

    000007ff`001f14fb : 00000001`3fa965a0 00000000`00000003 00000000`00000000 00000000`00000000 : 0x7ff`001f16be

    000007fe`f5e33ec9 : 00000001`ffa7a8e0 00000000`ffa7fa10 00000000`ffa7ee88 000007fe`eda94078 : 0x7ff`001f14fb

    000007fe`edb36aea : 00000000`ffa7dd38 000007fe`ee2354d0 00000000`ffa7c200 00000001`3faef0c0 : System_Web_RegularExpressions_ni+0x33ec9

    000007fe`edb2d2c4 : 00000000`00000000 00000000`ffa7dd38 00000000`ffa7c200 00000000`ffa7dd38 : System_Web_ni+0x2a6aea

    000007fe`edb2d322 : 00000000`ffa7d640 000007fe`edaf649b 00000000`ffa7c200 00000000`00000000 : System_Web_ni+0x29d2c4

    000007fe`edb298ac : 48cb906b`7f595e0d 000007fe`edbf9388 00000000`ffa7c200 00000001`3fbf2508 : System_Web_ni+0x29d322

    000007fe`edb28db0 : 00000000`ffa7c200 00000001`ffa7c801 00000000`ffa77901 000007fe`f156c8ff : System_Web_ni+0x2998ac

    000007fe`edb28cdb : 00000000`ffa7c200 00000001`ffa7c8f8 00000000`ffa76801 00000000`00000003 : System_Web_ni+0x298db0

    000007fe`edb28c70 : 00000000`ffa7c200 000007fe`f1c04be0 00000000`ffa7c5a0 000007fe`edb06625 : System_Web_ni+0x298cdb

  • ok, so in that case i would recommend that you look at the native stack to see the locks, not sure why monitor.enter is not showing up there in the managed callstack,

    in reality a call to thread.sleep should also have shown up in the managed stack for thread 26

Page 3 of 4 (54 items) 1234
Leave a Comment
  • Please add 2 and 1 and type the answer here:
  • Post