High cpu Utilization - IISState dump logs

Tech-Archive recommends: Fix windows errors by optimizing your registry

From: DaveS (anonymous_at_discussions.microsoft.com)
Date: 03/17/04 

Date: Wed, 17 Mar 2004 13:16:06 -0800

I have been testing a new application and have been hitting some performance problems. The server seems to be going along fine as users are being added to the load test. The cpu utilization is averaging in the high 30s, ASP requests executing is around 7 or 8, context switching is in the 5000 range and there is no queuing of ASP requests. Then, all of a sudden, in the 720 user range the wheels just fly off the cart.

It is like someone suddenly turned on a switch. CPU utilization shoots to the high 90's. The ASP requests executing instantly goes to the maximum level allowed by the ASPProcessorThreadMax value set on the system, the ASP request queue begins building rapidly. Obviously, response time of the applicatin increases dramatically at this point.

Checking the running processes, it is the InetInfo.exe process that is hogging all the cpu. It seems to be something that triggers all of a sudden and I am not sure what it is. Reviewing the IISStae dump log I found 10 threads that had an unusual message on them. They stated that "Thread Status: Thread is in a WAIT state.
Other information: Thread is waiting for a lock to be released. Looking for lock owner.
The owning thread is 0. This usually indicates that the lock has either been leaked or is in a 'convoy' state
Thread Type: ASP"

By the huge jump in the cpu and the context switching I am guessing the system is just constantly trying to execute these threads and is switch ing back and forth waiting for one to unlock.

If someone could maybe take a look at the dump log I have attached below and see if anythig rings a bell with them. Maybe give me some idea of what is going on. I am a hardware/server guy and need to explain to th programmers that there is a problem and where they need to look for it. Any help would be greatly appreciated.

Thanks, (Log begins below)
Dave

********
Opened log file 'C:\iisstate\output\IISState-2612.log'

***********************
Starting new log output
IISState version 3.3.1

Tue Mar 16 15:37:19 2004

OS = Windows 2000
Executable: inetinfo.exe
PID = 2612

Note: Thread times are formatted as HH:MM:SS.ms

***********************

Thread ID: 0
System Thread ID: 974
Kernel Time: 0:0:0.15
User Time: 0:0:0.0
Thread Type: Other
 # ChildEBP RetAddr
00 0006f89c 77e96156 ntdll!ZwReadFile+0xb
01 0006f910 77dd8752 KERNEL32!ReadFile+0x181
02 0006f93c 77dd7fdc ADVAPI32!ScGetPipeInput+0x28
03 0006f9b8 77dd7e0c ADVAPI32!ScDispatcherLoop+0x4a
04 0006fbf4 01002884 ADVAPI32!StartServiceCtrlDispatcherA+0x7d
05 0006fd30 01001e94 inetinfo!StartDispatchTable+0x2f1
06 0006ff70 01002fbf inetinfo!main+0x654
07 0006ffc0 77ea847c inetinfo!mainCRTStartup+0xff
08 0006fff0 00000000 KERNEL32!BaseProcessStart+0x3d

Thread ID: 1
System Thread ID: b28
Kernel Time: 0:0:0.62
User Time: 0:0:0.62
Thread Status: Thread is in a WAIT state.
Thread Type: Other
 # ChildEBP RetAddr
00 005dfd1c 77ea9b35 ntdll!NtWaitForSingleObject+0xb
01 005dfd44 77e8b32b KERNEL32!WaitForSingleObjectEx+0x71
02 005dfd54 6e6f1fe8 KERNEL32!WaitForSingleObject+0xf
03 005dfd70 01002440 iisadmin!ServiceEntry+0x156
04 005dffa4 77dd8943 inetinfo!InetinfoStartService+0x2bd
05 005dffb4 77e8b2d8 ADVAPI32!ScSvcctrlThreadW+0xe
06 005dffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 2
System Thread ID: 948
Kernel Time: 0:0:3.625
User Time: 0:0:0.687
Thread Type: Other
 # ChildEBP RetAddr
00 0071fe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0071feb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 0071ff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 0071ff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 0071ff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 0071ffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 0071ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 3
System Thread ID: b50
Kernel Time: 0:0:4.62
User Time: 0:0:0.578
Thread Type: Other
 # ChildEBP RetAddr
00 0075fe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0075feb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 0075ff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 0075ff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 0075ff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 0075ffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 0075ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 4
System Thread ID: 97c
Kernel Time: 0:0:3.765
User Time: 0:0:0.796
Thread Type: Other
 # ChildEBP RetAddr
00 0079fe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0079feb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 0079ff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 0079ff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 0079ff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 0079ffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 0079ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 5
System Thread ID: 8c0
Kernel Time: 0:0:3.750
User Time: 0:0:0.515
Thread Type: Other
 # ChildEBP RetAddr
00 007dfe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 007dfeb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 007dff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 007dff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 007dff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 007dffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 007dffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 6
System Thread ID: 764
Kernel Time: 0:0:3.968
User Time: 0:0:0.468
Thread Type: Other
 # ChildEBP RetAddr
00 0081fe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0081feb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 0081ff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 0081ff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 0081ff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 0081ffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 0081ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 7
System Thread ID: 6cc
Kernel Time: 0:0:3.640
User Time: 0:0:0.390
Thread Type: Other
 # ChildEBP RetAddr
00 0085fe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0085feb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 0085ff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 0085ff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 0085ff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 0085ffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 0085ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 8
System Thread ID: 6c4
Kernel Time: 0:0:3.984
User Time: 0:0:0.562
Thread Type: Other
 # ChildEBP RetAddr
00 0089fe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0089feb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 0089ff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 0089ff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 0089ff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 0089ffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 0089ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 9
System Thread ID: 7ec
Kernel Time: 0:0:3.453
User Time: 0:0:0.656
Thread Type: Other
 # ChildEBP RetAddr
00 008dfe60 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 008dfeb0 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 008dff0c 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 008dff28 6e5abc1d USER32!MsgWaitForMultipleObjects+0x1d
04 008dff80 780060ce IisRTL!SchedulerWorkerThread+0xa7
05 008dffb4 77e8b2d8 MSVCRT!_beginthreadex+0xca
06 008dffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 10
System Thread ID: bbc
Kernel Time: 0:0:0.78
User Time: 0:0:0.78
Thread Type: Other
 # ChildEBP RetAddr
00 00fffc1c 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 00fffc6c 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 00fffcc8 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 00fffce4 769c4f9f USER32!MsgWaitForMultipleObjects+0x1d
04 00fffd30 65f2d8b6 INFOCOMM!IIS_SERVICE::StartServiceOperation+0x209
05 00fffd70 01002440 w3svc!ServiceEntry+0x1b5
06 00ffffa4 77dd8943 inetinfo!InetinfoStartService+0x2bd
07 00ffffb4 77e8b2d8 ADVAPI32!ScSvcctrlThreadW+0xe
08 00ffffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 11
System Thread ID: b3c
Kernel Time: 0:0:0.78
User Time: 0:0:0.46
Thread Type: SMTP Service Worker Thread
 # ChildEBP RetAddr
00 0104fc1c 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0104fc6c 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 0104fcc8 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 0104fce4 769c4f9f USER32!MsgWaitForMultipleObjects+0x1d
04 0104fd30 6b561462 INFOCOMM!IIS_SERVICE::StartServiceOperation+0x209
05 0104fd70 01002440 SMTPSVC!ServiceEntry+0x136
06 0104ffa4 77dd8943 inetinfo!InetinfoStartService+0x2bd
07 0104ffb4 77e8b2d8 ADVAPI32!ScSvcctrlThreadW+0xe
08 0104ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 12
System Thread ID: 8e0
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: HTTP Listener
 # ChildEBP RetAddr
00 011cff5c 77e95244 ntdll!NtRemoveIoCompletion+0xb
01 011cff88 6d70b2fa KERNEL32!GetQueuedCompletionStatus+0x27
02 011cffb4 77e8b2d8 ISATQ!I_AtqOplockThreadFunc+0x32
03 011cffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 13
System Thread ID: 910
Kernel Time: 0:0:2.296
User Time: 0:0:3.0
Thread Type: HTTP Listener
 # ChildEBP RetAddr
00 0120ff50 77e95244 ntdll!NtRemoveIoCompletion+0xb
01 0120ff7c 6d7088db KERNEL32!GetQueuedCompletionStatus+0x27
02 0120ffb4 77e8b2d8 ISATQ!AtqPoolThread+0x40
03 0120ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 14
System Thread ID: 9d0
Kernel Time: 0:0:3.265
User Time: 0:0:3.687
Thread Type: HTTP Listener
 # ChildEBP RetAddr
00 0124ff50 77e95244 ntdll!NtRemoveIoCompletion+0xb
01 0124ff7c 6d7088db KERNEL32!GetQueuedCompletionStatus+0x27
02 0124ffb4 77e8b2d8 ISATQ!AtqPoolThread+0x40
03 0124ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 15
System Thread ID: a50
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: Possible ASP page. Possible DCOM activity
Executing Page: Unable to locate ASP page

No remote call being made

 # ChildEBP RetAddr
00 013cfeb8 77e95244 ntdll!NtRemoveIoCompletion+0xb
01 013cfee4 77d809da KERNEL32!GetQueuedCompletionStatus+0x27
02 013cff20 77d50ede RPCRT4!COMMON_ProcessCalls+0x9e
03 013cff74 77d50d17 RPCRT4!LOADABLE_TRANSPORT::ProcessIOEvents+0x99
04 013cff78 77d39a00 RPCRT4!ProcessIOEventsWrapper+0x9
05 013cffa8 77d41c6c RPCRT4!BaseCachedThreadRoutine+0x4f
06 013cffb4 77e8b2d8 RPCRT4!ThreadStartRoutine+0x18
07 013cffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 16
System Thread ID: 8c8
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: Other
 # ChildEBP RetAddr
00 0174fd20 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0174fd70 77ea9c13 KERNEL32!WaitForMultipleObjectsEx+0xea
02 0174fd88 778322b2 KERNEL32!WaitForMultipleObjects+0x17
03 0174ffb4 77e8b2d8 RTUTILS!TraceServerThread+0xde
04 0174ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 17
System Thread ID: b64
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: Other
 # ChildEBP RetAddr
00 0179ff20 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 0179ff70 77ea9c13 KERNEL32!WaitForMultipleObjectsEx+0xea
02 0179ff88 701224fa KERNEL32!WaitForMultipleObjects+0x17
03 0179ffb4 77e8b2d8 exstrace!RegNotifyThread+0x6f
04 0179ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 18
System Thread ID: 73c
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: Other
 # ChildEBP RetAddr
00 017dff24 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 017dff74 77ea9c13 KERNEL32!WaitForMultipleObjectsEx+0xea
02 017dff8c 70121e6a KERNEL32!WaitForMultipleObjects+0x17
03 017dffb4 77e8b2d8 exstrace!WriteTraceThread+0x2f
04 017dffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 19
System Thread ID: 96c
Kernel Time: 0:0:0.15
User Time: 0:0:0.46
Thread Status: Thread is in a WAIT state.
Thread Type: Other
 # ChildEBP RetAddr
00 01adff64 77ea9b35 ntdll!NtWaitForSingleObject+0xb
01 01adff8c 77e8b32b KERNEL32!WaitForSingleObjectEx+0x71
02 01adff9c 6ff283ee KERNEL32!WaitForSingleObject+0xf
03 01adffb4 77e8b2d8 FCACHDLL!CScheduleThread::ScheduleThread+0x22
04 01adffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 20
System Thread ID: b30
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: SMTP Service Worker Thread
 # ChildEBP RetAddr
00 01c1ff18 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 01c1ff68 77ea9c13 KERNEL32!WaitForMultipleObjectsEx+0xea
02 01c1ff80 6b579fbd KERNEL32!WaitForMultipleObjects+0x17
03 01c1ffb4 77e8b2d8 SMTPSVC!TcpRegNotifyThread+0x136
04 01c1ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 21
System Thread ID: 8d4
Kernel Time: 0:0:0.15
User Time: 0:0:0.0
Thread Status: Thread is in a WAIT state.
Thread Type: SMTP Service Worker Thread
 # ChildEBP RetAddr
00 01c5ff68 77ea9b35 ntdll!NtWaitForSingleObject+0xb
01 01c5ff90 77e8b32b KERNEL32!WaitForSingleObjectEx+0x71
02 01c5ffa0 6b579df1 KERNEL32!WaitForSingleObject+0xf
03 01c5ffb4 77e8b2d8 SMTPSVC!FreeLibThread+0x1d
04 01c5ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 22
System Thread ID: ae0
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Status: Thread is in a WAIT state.
Thread Type: HTTP Compression Thread
 # ChildEBP RetAddr
00 01c9ff5c 77ea9b35 ntdll!NtWaitForSingleObject+0xb
01 01c9ff84 77e8b32b KERNEL32!WaitForSingleObjectEx+0x71
02 01c9ff94 732c3366 KERNEL32!WaitForSingleObject+0xf
03 01c9ffb4 77e8b2d8 compfilt!CompressionThread+0x29
04 01c9ffc0 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 23
System Thread ID: 894
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: Possible ASP page. Possible DCOM activity
Executing Page: Unable to locate ASP page

No remote call being made

 # ChildEBP RetAddr
00 01ddfe24 77d574d4 ntdll!NtReplyWaitReceivePortEx+0xb
01 01ddff74 77d56d9e RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0x74
02 01ddff78 77d39ad0 RPCRT4!RecvLotsaCallsWrapper+0x9
03 01ddffa8 77d41c6c RPCRT4!BaseCachedThreadRoutine+0x11f
04 01ddffb4 77e8b2d8 RPCRT4!ThreadStartRoutine+0x18
05 01ddffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 24
System Thread ID: 83c
Kernel Time: 0:0:0.15
User Time: 0:0:0.15
Thread Type: Other
 # ChildEBP RetAddr
00 01e1fe74 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 01e1fec4 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 01e1ff20 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 01e1ff3c 65f38a88 USER32!MsgWaitForMultipleObjects+0x1d
04 01e1ff80 7800c9eb w3svc!CMTACallbackThread::Thread+0x42
05 01e1ffb4 77e8b2d8 MSVCRT!_beginthread+0xce
06 01e1ffec 00000000 KERNEL32!BaseThreadStart+0x52

Thread ID: 25
System Thread ID: ab0
Kernel Time: 0:0:0.0
User Time: 0:0:0.0
Thread Type: Other
 # ChildEBP RetAddr
00 01e5fea8 77ea9d00 ntdll!ZwWaitForMultipleObjects+0xb
01 01e5fef8 77e1e97b KERNEL32!WaitForMultipleObjectsEx+0xea
02 01e5ff54 77e1e9c8 USER32!MsgWaitForMultipleObjectsEx+0x153
03 01e5ff70 65f2e673 USER32!MsgWaitForMultipleObjects+0x1d
04 01e5ffb4 77e8b2d8 w3svc!OleHackThread+0x88
05 01e5ffec 00000000 KERNEL32!BaseThreadStart+0x52

Relevant Pages