Re: IISState log help

From: Pat [MSFT] (patfilot_at_online.microsoft.com)
Date: 08/11/04 

Date: Wed, 11 Aug 2004 16:10:50 -0700

Basically, what is happening is there is severe lock contention which
induces excessive thread context switching, which in turn causes a high CPU.

To understand, we can start with thread 15 (which is a victim and not the
root cause):

Thread ID: 15
System Thread ID: 8a8
Kernel Time: 0:0:12.390
User Time: 0:1:25.734
*** ERROR: Symbol file could not be found. Defaulted to export symbols for
-
Other information: Thread is waiting for a lock to be released. Looking for
lock owner.
Owning thread System ID: b7c
Thread Type: ASP
Executing Page: E:\INETPUB\ANGELROOT\SIDEBAR.ASP

 # ChildEBP RetAddr
00 0218df28 77f8822a ntdll!ZwWaitForSingleObject+0xb
01 0218df9c 77f8819b ntdll!RtlpWaitForCriticalSection+0x9e
02 0218dfa4 749f48da ntdll!RtlEnterCriticalSection+0x46
03 0218dfd0 749f46b2 asp!CScriptManager::GetEngine+0x41
04 0218e028 749f4539 asp!AllocAndLoadEngines+0x171
05 0218e064 749f43ef asp!ExecuteRequest+0x147
06 0218e0ac 74a16f7e asp!Execute+0x17e
07 0218e10c 74a23e71 asp!CHitObj::ExecuteChildRequest+0x12f
08 0218e334 779d7d5d asp!CServer::Execute+0x96
09 0218e350 77a2310e OLEAUT32!DispCallFunc+0x15d
0a 0218e3e0 74a2407d OLEAUT32!CTypeInfo2::Invoke+0x244
0b 0218e408 6b614279 asp!CDispatchImpl<IServer>::Invoke+0x4b
WARNING: Stack unwind information not available. Following frames may be
wrong.
0c 0218e484 6b61866f vbscript!DllCanUnloadNow+0x8e24
0d 00000000 00000000 vbscript!DllCanUnloadNow+0xd21a

This thread is trying to begin execution of Sidebar.asp, but is blocked
waiting for a lock in ASP.dll. That lock is owned by thread b7c (36):

Thread ID: 36
System Thread ID: b7c
Kernel Time: 0:0:0.93
User Time: 0:0:0.390
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
Executing Page: E:\INETPUB\ANGELROOT\SIDEBAR.ASP

 # ChildEBP RetAddr
00 07c7ddd8 77f8822a ntdll!ZwWaitForSingleObject+0xb
01 07c7de4c 77f8819b ntdll!RtlpWaitForCriticalSection+0x9e
02 07c7de54 77fcc74d ntdll!RtlEnterCriticalSection+0x46
03 07c7def4 78001e00 ntdll!RtlFreeHeap+0x11b
04 07c7df3c 6b602567 MSVCRT!free+0xda
WARNING: Stack unwind information not available. Following frames may be
wrong.
05 07c7dfdc 74a2277c vbscript!DllRegisterServer+0x91a
06 07c7dfe8 749f5cfa asp!CScriptManager::CheckFSQLRU+0x56
07 07c7dff4 749f5a84 asp!CScriptManager::AddToFSQ+0x5c
08 07c7e014 749f597d asp!CScriptManager::ReturnEngineToCache+0x12a
09 07c7e030 749f45b0 asp!DeAllocAndFreeEngines+0x35
0a 07c7e064 749f43ef asp!ExecuteRequest+0x278
0b 07c7e0ac 74a16f7e asp!Execute+0x17e
0c 07c7e10c 74a23e71 asp!CHitObj::ExecuteChildRequest+0x12f
0d 07c7e334 779d7d5d asp!CServer::Execute+0x96
0e 07c7e350 77a2310e OLEAUT32!DispCallFunc+0x15d
0f 07c7e3e0 74a2407d OLEAUT32!CTypeInfo2::Invoke+0x244
10 07c7e408 6b614279 asp!CDispatchImpl<IServer>::Invoke+0x4b
11 07c7e484 6b61866f vbscript!DllCanUnloadNow+0x8e24
12 00000000 00000000 vbscript!DllCanUnloadNow+0xd21a

This thread an example of the problem. It is blocked waiting for a lock
that protects memory allocations (i.e. 'new', 'free', etc.) within the
C-Runtime (MSVCRT.dll).

So, the question then is why is the lock contention so high? I would start
by looking at Home.asp and Sidebar.asp. The way the script engines work is
that every variable declaration involves a 'new' and 'free' coupling, each
locking/unlocking a chunk of memory. This is no big deal, unless you have
an excessive number of variable declarations (e.g. you include the
adovbs.inc file). I suspect that this is the issue here. It may also be
related to the use of the scripting.dictionary object. For every item you
add to the dictionary, a 'new' occurs, for every removal, a 'free'. Again,
not a big deal unless you are creating and destroying a large number of
items in the dictionary. There was at least 1 thread working on the
dictionary object, but it may have just been a victim of circumstance.

Another way is to do excessive string concatenations, but I don't see any
evidence of that.

When the lock owner is 0, that means that we are basically contending for
the lock faster than the OS can update its (the lock's) status. This is
analogous to traffic jams that occur on the freeway for no apparent reason
(i.e. things are moving fast, then there is a section where things are
really slow, which dissipates for no reason). Starting with Windows XP (and
in Windows 2003) we modified the lock behavior to include some
'anti-convoying' logic, which basically makes it a lot harder to induce, but
it is still possible. On any system, the best solution is to ensure the
code is clean (it will help perf in general, eliminating excessive code
paths).

Pat

Relevant Pages

  • IISState log help
    ... I do notice that quite a few threads have this message: "Thread is waiting ... Looking for lock owner. ... System Thread ID: 8a8 ... Stack unwind information not available. ...
    (microsoft.public.inetserver.iis)
  • Re: [PATCH RFC] smt nice introduces significant lock contention
    ... kernel/sched.c:dependent_sleeperwas responsible for most of the lock ... we are hitting on lock contention, but by the large amount of code it ... dependent_sleeper by only doing trylock on the smt sibling runqueues. ... * Try to lock all the siblings of a cpu that is already locked. ...
    (Linux-Kernel)
  • Re: Advice on a multithreaded netisr patch?
    ... It seems ridiculous to avoid using queues ... the first is lock contention, ... other thread is waiting on the lock, ...
    (freebsd-net)
  • [ckpatch][2/29] sched-revise_smt_nice_locking
    ... Initial report and lock contention fix from Chris Mason: ... convert wake_sleeping_dependent to use trylock ... * Called with interrupt disabled and this_rq's runqueue locked. ...
    (Linux-Kernel)
  • RE: [PATCH RFC] smt nice introduces significant lock contention
    ... Recent benchmarks showed some performance regressions between 2.6.16 and ... kernel/sched.c:dependent_sleeperwas responsible for most of the lock ... this also sort of echo a recent discovery on one of our benchmarks ... we are hitting on lock contention, but by the large amount of code it ...
    (Linux-Kernel)