Here's some more information on troubleshooting a High CPU Issue.

I'm using a Test Scenario which means that my CPU goes high whenever I browse to the default.htm with a Query String of sf=cpu1_v1.

If you go back to Part 1 then you'll understand why I approach the issue like this.

If I look in Task Manager I can see this behaviour.



So then I use Performance Monitor to look at the process and see where the Processor time is being used.

As I only have one IIS 6 Worker Process I'll use the following counters.

Process -> % Processor Time for W3WP.exe
Thread -> % Processor Time for all the threads in W3WP.exe.

So I go ahead and reproduce the issue and I see the following in the Performance Monitor Data.

% Processor Time	Process W3WP.exe	Thread 7
06/25/2008 18:30:38.622	57.187134	57.187134
06/25/2008 18:30:53.622	97.603542	97.603542
06/25/2008 18:31:08.622	39.791412	39.791412
06/25/2008 18:31:23.622	21.87486	21.87486
06/25/2008 18:31:38.622	82.81197	82.81197

When we look at the threads we can see that Thread 7 is taking most of the Processor time.

So I've taken a dump file of the IIS Worker Process so I know that I need to look at Thread 7.

So I open the dump file in WinDBG and I'm using http://msdl.microsoft.com/download/symbols as my symbol path.

I'll start by going straight to Thread 7 to check what that is doing.

0:007> kL
ChildEBP RetAddr 
0166f5f8 021c191b kernel32!GetTickCount+0x1d
0166f820 5a398894 badfil!HttpFilterProc+0x671
0166f9b4 5a398757 w3core!W3_FILTER_CONTEXT::NotifyFilters+0x52d
0166f9dc 5a397598 w3core!W3_FILTER_CONTEXT::NotifyPreProcHeaderFilters+0x32
0166f9f4 5a3990ad w3core!W3_MAIN_CONTEXT::NotifyFilters+0xe0
0166feec 5a392264 w3core!W3_STATE_START::DoWork+0x4c8
0166ff10 5a3965ea w3core!W3_MAIN_CONTEXT::DoWork+0xa6
0166ff2c 5a36169f w3core!W3_MAIN_CONTEXT::OnNewRequest+0x55
0166ff38 5a361650 w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x48
0166ff48 5a3616ca w3dt!UL_NATIVE_REQUEST::DoWork+0x7f
0166ff5c 5a3024de w3dt!OverlappedCompletionRoutine+0x1a
0166ff8c 5a3026bc w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x73
0166ffa0 5a301db9 w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x24
0166ffb8 7d4dfe21 w3tp!THREAD_MANAGER::ThreadManagerThread+0x39
0166ffec 00000000 kernel32!BaseThreadStart+0x34

As the offset for badfil!HttpFilterProc is so large I think that I don't have matching symbols for the badfil component.

0:007> lmv mbadfil
start    end        module name
021c0000 021c6000   badfil     (export symbols)       badfil.dll
    Loaded symbol image file: badfil.dll
    Image path: D:\DebugDiagLabs\www\App\badfil.dll

The export symbols means that I don't have matching symbols. So normally at this point you would ask the company who developed this component to send you the symbols.

In this case I've got the symbols already locally.

I'll start by using the public Symbols and so now my call stack looks like this.

0:007> kL
ChildEBP RetAddr 
0166f5f8 021c191b kernel32!GetTickCount+0x1d
0166f820 5a398894 badfil!doCPU1+0x23
0166f9b4 5a398757 w3core!W3_FILTER_CONTEXT::NotifyFilters+0x52d
0166f9dc 5a397598 w3core!W3_FILTER_CONTEXT::NotifyPreProcHeaderFilters+0x32
0166f9f4 5a3990ad w3core!W3_MAIN_CONTEXT::NotifyFilters+0xe0
0166feec 5a392264 w3core!W3_STATE_START::DoWork+0x4c8
0166ff10 5a3965ea w3core!W3_MAIN_CONTEXT::DoWork+0xa6
0166ff2c 5a36169f w3core!W3_MAIN_CONTEXT::OnNewRequest+0x55
0166ff38 5a361650 w3dt!UL_NATIVE_REQUEST::DoStateProcess+0x48
0166ff48 5a3616ca w3dt!UL_NATIVE_REQUEST::DoWork+0x7f
0166ff5c 5a3024de w3dt!OverlappedCompletionRoutine+0x1a
0166ff8c 5a3026bc w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x73
0166ffa0 5a301db9 w3tp!THREAD_POOL_DATA::ThreadPoolThread+0x24
0166ffb8 7d4dfe21 w3tp!THREAD_MANAGER::ThreadManagerThread+0x39
0166ffec 00000000 kernel32!BaseThreadStart+0x34

But that's not enough information to help me fix the code for the BadFil Component so I'll switch to using the private symbols instead.

(You'll find a lot more information about Symbol files here.)

Now the stack contains line Numbers about my code files.

E.G
badfil!doCPU1+0x23 (CONV: stdcall) [H:\filDBG\badfil.cpp @ 681]

This has meant that I have identified where in my code the Processor utilisation is coming from.

In this case the code looked like this.

DWORD doCPU1(int Variation)
{
    if (1 == Variation)
    {
        DWORD dwStartTime = GetTickCount();
        while( GetTickCount() - dwStartTime <= 30000 )
            {

            }

    }

    return 1;
}

There's one more thing I'd like to add on this topic. If you haven't been able to gather Performance data then there is one more tool you can use to assist in these kinds of issues.

0:007> !runaway
User Mode Time
  Thread       Time
   7:1518      0 days 0:01:33.234
   0:13c0      0 days 0:00:00.093
   8:1688      0 days 0:00:00.015
  14:1404      0 days 0:00:00.000
  13:124c      0 days 0:00:00.000
  12:1310      0 days 0:00:00.000
  11:15e4      0 days 0:00:00.000
  10:9a4       0 days 0:00:00.000
   9:1528      0 days 0:00:00.000
   6:16f4      0 days 0:00:00.000
   5:178       0 days 0:00:00.000
   4:1610      0 days 0:00:00.000
   3:f38       0 days 0:00:00.000
   2:1460      0 days 0:00:00.000
   1:9b0       0 days 0:00:00.000

The !runaway command is documented here.

"The !runaway extension displays information about the time consumed by each thread."

Tess uses the same command in her .Net Debugging Labs Demo 4.

Raymond Chen also talks about this in this post.

That's all for now. I hope that this was a useful example of debugging a High CPU utilisation within IIS.