Viewing active and non-active ASP.NET requests from a dump
When you have a dump of a ASP.NET process and you want to look at what was happening at the time the dump was collected, you have a few options. The first is to look at all the callstacks in the dump and go through each one and try to figure out what was running on each thread.
A much easier way is to use the clr10\sos.dll extension that comes with the debugger and let it do the work for you.
0:000> !clr10\sos.aspxpages
Going to dump the HttpContexts found in the heap.
HttpContext Timeout Completed Running ThreadId ReturnCode Verb RequestPath+QueryString
0x013bd1f4 90 Sec yes XXX 200 POST /Test/service1.asmx
0x013bec78 90 Sec no 15016 Sec 4 200 POST /Test/service1.asmx
0x013c59ac 19200 Sec no 15003 Sec XXX 200 POST /Test2/Logon.aspx
0x013cab48 19200 Sec no 14913 Sec 14 200 POST /Test2/Logon.aspx
0x013cdf70 19200 Sec no 14993 Sec XXX 200 POST /Test2/Logon.aspx
0x01405d18 19200 Sec yes XXX 302 POST /Test2/logon.aspx
0x0140c7c4 90 Sec no 14991 Sec 26 200 POST /Test/service1.asmx
0x01410728 19200 Sec no 14915 Sec 16 200 POST /Test2/Logon.aspx
0x01413d6c 90 Sec no 14967 Sec 28 200 POST /Test/service1.asmx
0x0141d270 90 Sec no 14915 Sec 29 200 POST /Test/service1.asmx
0x014215ac 90 Sec no 14912 Sec 30 200 POST /Test/service1.asmx
0x0142ce30 19200 Sec no 14859 Sec 19 200 POST /Test2/Logon.aspx
0x053f6bb0 90 Sec yes XXX 200 POST /Test/service1.asmx
0x05416718 90 Sec no 15013 Sec 12 200 POST /Test/service1.asmx
0x05421e20 90 Sec no 14999 Sec 24 200 POST /Test/service1.asmx
0x05425ea8 19200 Sec yes XXX 302 POST /Test2/logon.aspx
0x0542db50 19200 Sec yes XXX 200 GET /Test2/Error.aspx Err=1
0x05443fd4 90 Sec no 14859 Sec 27 200 POST /Test/service1.asmx
Total 18 HttpContext objects
There is a lot of useful information here. You can see what the timeout is set to for each request, if the request has completed or not. If it hasn't, how long it has been running for. What thread the request is currently on. You can also see the request and the return code for the request, including the querystring.
To see where some of this data is coming from, let's look at the timeout and how long the request has been running. If you dump out the HttpContext object you will see:
0:000> !clr10\sos.do 0x053f6bb0
Name: System.Web.HttpContext
MethodTable 0x0daf5c78
EEClass 0x0d937d6c
Size 124(0x7c) bytes
GC Generation: 2
mdToken: 0x02000051 (c:\winnt\assembly\gac\system.web\1.0.3300.0__b03f5f7f11d50a3a\system.web.dll)
FieldDesc*: 0x0daf55c4
MT Field Offset Type Attr Value Name
0x0daf5c78 0x400054c 0x4 CLASS instance 0x00000000 _asyncAppHandler
0x0daf5c78 0x400054d 0x8 CLASS instance 0x00000000 _appInstance
0x0daf5c78 0x400054e 0xc CLASS instance 0x00000000 _handler
0x0daf5c78 0x400054f 0x10 CLASS instance 0x053f6c2c _request
0x0daf5c78 0x4000550 0x14 CLASS instance 0x053f6cc0 _response
0x0daf5c78 0x4000551 0x18 CLASS instance 0x00000000 _server
0x0daf5c78 0x4000552 0x1c CLASS instance 0x00000000 _traceContextStack
0x0daf5c78 0x4000553 0x20 CLASS instance 0x00000000 _topTraceContext
0x0daf5c78 0x4000554 0x24 CLASS instance 0x00000000 _items
0x0daf5c78 0x4000555 0x28 CLASS instance 0x00000000 _errors
0x0daf5c78 0x4000556 0x2c CLASS instance 0x00000000 _tempError
0x0daf5c78 0x4000557 0x58 System.Boolean instance 0 _errorCleared
0x0daf5c78 0x4000558 0x30 CLASS instance 0x053f6e04 _user
0x0daf5c78 0x4000559 0x5c VALUETYPE instance start at 053f6c0c _timestamp
0x0daf5c78 0x400055a 0x34 CLASS instance 0x053f695c _wr
0x0daf5c78 0x400055b 0x64 VALUETYPE instance start at 053f6c14 _root
0x0daf5c78 0x400055c 0x38 CLASS instance 0x053f6a10 _configPath
0x0daf5c78 0x400055d 0x59 System.Boolean instance 0 _skipAuthorization
0x0daf5c78 0x400055e 0x3c CLASS instance 0x00000000 _dynamicCulture
0x0daf5c78 0x400055f 0x40 CLASS instance 0x00000000 _dynamicUICulture
0x0daf5c78 0x4000560 0x44 CLASS instance 0x053f6d40 _impersonation
0x0daf5c78 0x4000561 0x68 VALUETYPE instance start at 053f6c18 _timeoutStartTime
0x0daf5c78 0x4000562 0x5a System.Boolean instance 1 _timeoutSet
0x0daf5c78 0x4000563 0x70 VALUETYPE instance start at 053f6c20 _timeout
0x0daf5c78 0x4000564 0x54 System.Int32 instance 0 _timeoutState
0x0daf5c78 0x4000565 0x48 CLASS instance 0x00000000 _timeoutLink
0x0daf5c78 0x4000566 0x4c CLASS instance 0x053c0824 _configrecord
0x0daf5c78 0x4000567 0x50 CLASS instance 0x00000000 BeforeDoneWithSession
To see the timeout, you take the value of the _timeout field and look at it. Because this is a value type, we can't just dump it out like we do other things. But luckily, sos.dll has a command that will show us the value:
0:000> !clr10\sos.cvtdd 053f6c20
As a TimeSpan: 000.00:01:30
As a DateTime: 120/00/44768 10:00:27
Since the timeout is a TimeSpan, we can see it is set to 1:30 or 90 seconds. For how long a page has been running, we do the same thing with the _timeoutStartTime field:
0:000> !clr10\sos.cvtdd 053f6c18
As a TimeSpan: 730999.16:54:06.0390625
As a DateTime: 05/30/2007 16:54:06
To see how long it has been running, we subtract from the time of the dump:
0:000> .time
Debug session time: Thu May 30 16:57:18.000 2007 (GMT-5)
System Uptime: 0 days 0:35:01.718
Process Uptime: not available
So we can see this had this request still been running, it would be now be running for 3 minutes and 12 seconds.
This type of data is really useful when you are dealing with a long running request and you want to see how long it has been active. You can also see if there are a lot of requests all coming in at once and what their state is. If you see the return code 500 for some requests, then the request was rejected by IIS because the site is too busy.
Comments
Anonymous
March 24, 2010
I am confused. " 0x01413d6c 90 Sec no 14967 Sec 28 200 POST /Test/service1.asmx " Does it mean that the request has been processed for 14967 Sec ?Anonymous
March 24, 2010
Yes. Typically there are a few things that can cause a number that big. If the call hangs or doesn't return correctly it can show up like that.