I think I found the problem and the bug in our filter driver.
The thread that was blocking all 26 threads to complete nt!ExFreePoolWithTag
has a calling stack:
THREAD 81769da0 Cid 8.8ec Teb: 00000000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
8204752c SynchronizationEvent
Not impersonating
Owning Process 820215e0
WaitTime (seconds) 894553
Context Switch Count 38324
UserTime 0:00:00.0000
KernelTime 0:00:03.0953
Start Address srv!WorkerThread (0xf184c040)
Stack Init f1b66000 Current f1b65980 Base f1b66000 Limit f1b63000
Call 0
Priority 9 BasePriority 9 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr Args to Child
f1b65998 8042bd4d 82047080 e129d440 00000000 nt!KiSwapThread+0x1b1
f1b659c0 8006554b 8204752c 00000000 00000000
nt!KeWaitForSingleObject+0x1a3
f1b659e0 8046bd50 f1b65a48 815c2cc8 81804b60
hal!ExAcquireFastMutex+0x2b
f1b65a08 8046bb4d e129d448 00000000 804f0b31
nt!ExFreePoolWithTag+0x180
f1b65a14 804f0b31 e129d448 81804b60 f7bca7fd nt!ExFreePool+0xb
f1b65a20 f7bca7fd f1b65a48 81804b60 815c2cc8
nt!RtlFreeUnicodeString+0x13
f1b65a70 f7bc6bf4 00000001 81f36b08 81804c18 MyFSFD+0x67fd
f1b65af4 f7bc54fa 81804b60 815c2cc8 f1b65b2c MyFSFD+0x2bf4
f1b65b04 8041d915 81804b60 815c2cc8 81f36b08 MyFSFD+0x14fa
f1b65b18 8041ecad 00000000 00000000 816657a8 nt!IopfCallDriver+0x35
f1b65b2c 80440d0e 81f36b08 816657e0 816657c0 nt!IoPageRead+0xb1
f1b65b68 8044a144 00000001 e2271bec c03889c4
nt!MiDispatchFault+0x24c
f1b65bb8 804689af 00000001 00000000 00000000 nt!MmAccessFault+0x702
f1b65bb8 8046b9e6 00000001 00000000 00000000 nt!KiTrap0E+0xc7
f1b65c68 80415e6d 00000001 00000004 7274534c
nt!ExAllocatePoolWithTag+0x4a6
f1b65c84 f184d9ed 00000001 0000038c 7274534c
nt!ExAllocatePoolWithTagPriority+0x67
f1b65cb0 f184cb20 81c62c50 81c0cb70 81c0cb50
srv!SrvAllocatePagedPool+0xce
f1b65cd0 f184c5f4 f1b65d60 f1b65d5c 81a06ab0
srv!SrvAllocateTransaction+0xda
f1b65d68 f183f91e 81c62c50 f183fb86 81c62c58
srv!SrvSmbTransaction+0x33b
f1b65d70 f183fb86 81c62c58 81c67be0 f1b65da8 srv!SrvProcessSmb+0x46
f1b65d84 f184c0ea 00000000 00000000 00000000
srv!SrvRestartReceive+0xa2
f1b65da8 80454fde 81c62c50 00000000 00000000 srv!WorkerThread+0x115
f1b65ddc 8046a302 f184c040 81c67be0 00000000
nt!PspSystemThreadStartup+0x54
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
The bug in our filter driver was that (in one rarely executed code path), a
call to nt!RtlFreeUnicodeString was done at IRQL>PASSIVE_LEVEL and the
request in process was a Paging IO for system page file. So this thread ends
to wait on event 0x8204752c, which was (very likely) already acquired by the
same thread in previous call to nt!ExAllocatePoolWithTag.
Thank you very much for your suggestions.
WBR Primoz
-----Original Message-----
From: Jonathan Borden [mailto:xxxxx@L5sg.com]
Sent: Tuesday, September 17, 2002 5:17 PM
To: Kernel Debugging Interest List
Subject: [windbg] RE: Finding owner of KEVENT
Here’s what I can suggest…
I am assuming that the locks are being caused by something within your code.
If this is the case, the locks might be happening on locks you create and
own. If this is also the case, then my suggestion is to wrap your locks
within a structure with contextual information. This information should
include a tag (like 'a5a5a5a5) and the creating thread and any other data
you like. Then, when you’re in a deadlock you can look at the memory
surrounding the lock and see if it’s yours (via the tag) and look at the
associcated owning thread.
Maybe this will shed some light?
============================================
Jonathan Borden
L5 Software Group, LLC
-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Primoz Beltram
Sent: Tuesday, September 17, 2002 6:11 AM
To: Kernel Debugging Interest List
Subject: [windbg] RE: Finding owner of KEVENT
The W2K-SP2 testing system is not “clean”. The application we are
developing/testing is composed by user mode and kernel mode (file system
filter) driver. Our application adds some more load to the system, to the
one generated by LAN clients (blocking the client request, do some work and
then release the blocked request).
It is also not so easy to reproduce this blocked condition of testing system
(~1 per month) .
The lines below are only what we are guessing the problem might be.
It seams that the system enters in this blocked state when it hits some
“high water mark” and it starts to flush and free resources in order to keep
its resource stock big enough.
Another thing that we have seen in each(!) of analyzed blocked conditions
was that there was always at least one thread that was holding a shared lock
to “nt!CmpRegistryLock” ERESOURCE. This one is interesting because there is
a Microsoft KB article Q317357 describing a similar (blocking) condition we
are facing and it is referencing CmpRegistryLock. But it is only similar(!),
we don’t have or use Terminal server and our system remains blocked much
much longer than just a couple of seconds.
But this are only guesses. If I could locate the threads that are in dead
lock chain, the picture “Why” would be much clearer.
WBR Primoz
-----Original Message-----
From: Jonathan Borden [mailto:xxxxx@L5sg.com]
Sent: Tuesday, September 17, 2002 10:55 AM
To: Kernel Debugging Interest List
Subject: [windbg] RE: Finding owner of KEVENT
Ah, right. my bad.
Is this happening from a driver that you are writing or is this just
happening on a normal system?
============================================
Jonathan Borden
L5 Software Group, LLC
-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Primoz Beltram
Sent: Monday, September 16, 2002 11:33 AM
To: Kernel Debugging Interest List
Subject: [windbg] Finding owner of KEVENT
Hello,
I’m analyzing a blocked state of my W2K-SP2 testing system. The system
entered this state after some time it was put under heavy load from LAN
clients, accessing files over network share.
The track I’m following, is that there are quite some (blocked) threads, 26
in total, that are trying to free memory and all have a call stack ending
like this:
!process 0 7
…
…
f7b83878 8042bd4d 82047080 e1edb3c0 00000000 nt!KiSwapThread+0x1b1
f7b838a0 8006554b 8204752c 00000000 00000000 nt!KeWaitForSingleObject+0x1a3
f7b838c0 8046bd50 82014f80 f7b83bf4 f7b83c10 hal!ExAcquireFastMutex+0x2b
f7b838e8 8046bb4d e1edb3c8 00000000 8044fbd3 nt!ExFreePoolWithTag+0x180
f7b838f4 8044fbd3 e1edb3c8 8044f89c e1edb3c8 nt!ExFreePool+0xb
…
The state of those 26 blocked threads doesn’t change, if I ‘go’ the system
again and then break-in with WinDbg after some minutes, so I suppose they
are blocked and this also results in whole blocked system.
All of those 26 threads are waiting on the same SynchronizationEvent at
0x8204752c.
This is what I get when I display the content of SynchronizationEvent:
dt -b _KEVENT 0x8204752c
+0x000 Header :
+0x000 Type : 0x1 ‘’
+0x001 Absolute : 0 ‘’
+0x002 Size : 0x4 ‘’
+0x003 Inserted : 0 ‘’
+0x004 SignalState : 0
+0x008 WaitListHead : [0x81769e0c - 0x81773b8c]
+0x000 Flink : 0x81769e0c
+0x004 Blink : 0x81773b8c
And if I look in WaitListHead, I can see all of 26 waiting threads there
too.
0: kd> dl 0x81769e0c 30 3
81769e0c 8201676c 82047534 81769da0
8201676c 819034cc 81769e0c 82016700
819034cc 81a3554c 8201676c 81903460
81a3554c 8179e08c 819034cc 81a354e0
8179e08c 818cd8ac 81a3554c 8179e020
818cd8ac 818ed5ec 8179e08c 818cd840
818ed5ec 8176508c 818cd8ac 818ed580
8176508c 8170b28c 818ed5ec 81765020
8170b28c 819707ec 8176508c 8170b220
819707ec 8201a88c 8170b28c 81970780
8201a88c 816e458c 819707ec 8201a820
816e458c 8201890c 8201a88c 816e4520
8201890c 8176708c 816e458c 820188a0
8176708c 816f6ccc 8201890c 81767020
816f6ccc 819b738c 8176708c 816f6c60
819b738c 8201ab0c 816f6ccc 819b7320
8201ab0c 8197caac 819b738c 8201aaa0
8197caac 81cdad6c 8201ab0c 8197ca40
81cdad6c 81a3654c 8197caac 81cdad00
81a3654c 816537ac 81cdad6c 81a364e0
816537ac 81958e0c 81a3654c 81653740
81958e0c 8185086c 816537ac 81958da0
8185086c 81cb6a2c 81958e0c 81850800
81cb6a2c 819cbb8c 8185086c 81cb69c0
819cbb8c 81773b8c 81cb6a2c 819cbb20
81773b8c 82047534 819cbb8c 81773b20
82047534 81769e0c 81773b8c 00000000
The problem that I’m dealing from here on, is how to locate the “owner”
thread of KEVENT(0x8204752c), the one that was last succeeded in calling
nt!KeWaitForSingleObject(0x8204752c, …).
The waiting threads, from the WaitListHead list of KEVENT(0x8204752c), are
themselves exclusive owners of some ERESOURCEs and have also waiters for
those ERESOURCEs. The “!locks” command gives a great help in listing and
finding “owners” and “waiters” for a particular ERESOURCE.
Unfortunately I don’t know how (if) I could locate the owner of
KEVENT(0x8204752c). If this is possible, then I could check and search for
dead lock situation.
Here is also a dump from memory location 0x8204752c and above, if the
locations above 0x8204752c have any sense to somebody out there.
820474ec 00040001 00000000 820474f4 820474f4
820474fc 00000000 00000001 f245bcfc 00000308
8204750c 00040001 00000000 82047514 82047514
8204751c 00000000 ffffffe6 f1b65854 00000368
8204752c 00040001 00000000 81769e0c 81773b8c
8204753c 00000000 00000000 00000000 00000000
8204754c 00000000 00000000 00000000 00000000
Any hint would be of great help, since I’m now in deadlock :-(.
WBR Primoz
Primoz Beltram
e-mail: xxxxx@hermes.si
www: http: http://www.hermes.si
HERMES SoftLab, Office Nova Gorica
Erjavceva 2, 5000 Nova Gorica, Slovenia
phone: (++386 5) 33 30 510, (++386 1) 58 65 710
fax: (++386 5) 33 32 656, (++386 1) 58 65 270
-----------------------------------------------
—
You are currently subscribed to windbg as: xxxxx@L5sg.com
To unsubscribe send a blank email to %%email.unsub%%
—
You are currently subscribed to windbg as: xxxxx@hermes.si
To unsubscribe send a blank email to %%email.unsub%%
—
You are currently subscribed to windbg as: xxxxx@L5sg.com
To unsubscribe send a blank email to %%email.unsub%%
—
You are currently subscribed to windbg as: xxxxx@hermes.si
To unsubscribe send a blank email to %%email.unsub%%</http:>