ASP.NET Tips: How to use DebugDiag to track down where a performance problem is coming from
We recently had a case where the customer was having performance problems. They were seeing requests take a few minutes to return and didn’t know what was happening. So they took some dumps while the problem was happening. So we ran this dump through DebugDiag using the Crash/Hang script and looked at the output. The first thing we noticed was this:
1 client connection(s) in IIS_COM+__...Dump.dmp have been executing a request for more than 90 seconds.
So we had a long running request. So we looked to see what it was and saw:
Client connection from xxx.xxx.xxx.xxx:2449 to xxx.xxx.xxx.xxx:443 POST request for /xxxx/xxxx HTTP Version HTTP/1.1 SSL Request False Time alive 00:02:46 QueryString Request mapped to HTTP Request State HTR_READING_CLIENT_REQUEST Native Request State NREQ_STATE_PROCESS
So we have a request that ran for 2 minutes and 46 seconds before the dump was taken. So we go to dig into this and we see in the summary this:
The following threads in IIS_COM+__...Dump.dmp are making a COM call to thread with system id 3760 in process 3428 ( 74 77 ) 1.92% of threads blocked
So these threads are calling another process. Since it is a dllhost.exe process that we captured when we got the IIS hang dumps from DebugDiag, we can analyze that also. With this dump, we do the same thing and find in the summary:
The following threads in IIS_COM+__...Dump.dmp are waiting on data to be returned from another server via WinSock. The call to WinSock originated from mseidrda!DRDASectionSetParameter+22b2 and is destined for port 5021 at IP address 10.254.1.12 ( 10 11 ) 1.53% of threads blocked
Looking at this thread we see:
Thread 10 - System ID 204 Entry point comsvcs!CSTAThread::WorkerLoop Create time 4/25/2008 5:58:00 AM Time spent in user mode 0 Days 00:01:20.734 Time spent in kernel mode 0 Days 00:00:17.578 This thread is waiting on data to be returned from another server via WinSock. The call to WinSock originated from mseidrda!xxxx+22b2 and is destined for port 5021 at IP address xxx.xxx.xxx.xxx Function Source ntdll!KiFastSystemCallRet ntdll!NtWaitForSingleObject+c mswsock!SockWaitForSingleObject+19d mswsock!WSPRecv+203 ws2_32!WSARecv+77 wsock32!recv+31 mseidrda!xxxx+22b2 mseidrda!xxxx+2920 Socket properties: Source Port 1058 Destination IP xxx.xxx.xxx.xxx Destination Port 5021
So this doesn’t get us to the actual answer of what is happening, but it does allow us to see that our web server is calling COM and COM is making a call across a socket to another server and we are waiting on that. So now what is left is to track down what this IP address maps to and see why the calls around returning right away.
I may update this post with the rest if people are interested. But the important part is being able to narrow down where the problem is. Then you can use the right tools and troubleshoot the correct area.
