Hang in storage filter and NFS

Rob_Green · August 30, 2004, 4:23pm

I have a hang that i can not solve in my storage filter driver using
the following:

server: Win2000 SP4 w/NFS server 3.0
client: Red hat linux 6

server has shared c:\share as a nfsshare
client copies about 500mb of data

If we send a private ioctl to start an operation (the driver is always
running in passthru mode) we hang, even before we do anything (ie we
have no threads running). It appears that we have lost an io but we
have no knowledge of it, but !Irpfind says we currently own it. I have
checked and double checked our completion routines and made sure that
IoMarkIrpPending was being called, and that they only return
STATUS_SUCCESS or SMPR. the thread that is dying is waiting for the
Registry (81fa4d40). I have driver verifier enabled with level 2 io
checking.

Any ideas what could be wrong? I can get a memory dump if any wants as it
is very easy to repro.

Symbol search path is:
srv*c:\websymbols*http://msdl.microsoft.com/download/symbols;E:\Driver\objch
k_w2k_x86\i386

Opened \.\com1
Waiting to reconnect…
Connected to Windows 2000 2195 x86 compatible target, ptr64 FALSE
Kernel Debugger connection established.
Symbol search path is:
srv*c:\websymbols*http://msdl.microsoft.com/download/symbols;E:\Driver\objch
k_w2k_x86\i386
Executable search path is: E:\Driver\objchk_w2k_x86\i386
Windows 2000 Kernel Version 2195 UP Free x86 compatible
Kernel base = 0x80400000 PsLoadedModuleList = 0x8046e8f0
System Uptime: not available

kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks…

Resource @ nt!CmpRegistryLock (0x8046dae0) Shared 1 owning threads
Contention Count = 2554
NumberOfSharedWaiters = 7
NumberOfExclusiveWaiters = 2
Threads: 81fc3020-01 81fa4d40-01<*> 81aea960-01 81411980-01
813b7bc0-01 81e51da0-01 81aeb020-01 81e58960-01

Threads Waiting On Exclusive Access:
8159c960 813be020
KD: Scanning for held locks…

Resource @ 0x81f717a8 Shared 1 owning threads
Threads: 81fa4d40-01<*>
KD: Scanning for held
locks…
…

Resource @ 0x81377440 Shared 1 owning threads
Threads: 81fc58a3-01<*> *** Actual Thread 81FC58A0

Resource @ 0x813710c0 Shared 1 owning threads
Threads: 81fc5123-01<*> *** Actual Thread 81FC5120
2681 total locks, 4 locks currently held
kd> !locks 8046dae0

Resource @ nt!CmpRegistryLock (0x8046dae0) Shared 1 owning threads
Contention Count = 2554
NumberOfSharedWaiters = 7
NumberOfExclusiveWaiters = 2
Threads: 81fc3020-01 81fa4d40-01<*> 81aea960-01 81411980-01
813b7bc0-01 81e51da0-01 81aeb020-01 81e58960-01

Threads Waiting On Exclusive Access:
8159c960 813be020
1 total locks, 1 locks currently held

kd> !thread 81fa4d40
THREAD 81fa4d40 Cid 8.6c Teb: 00000000 Win32Thread: 00000000 WAIT:
(Executive) KernelMode Non-Alertable
81424ca0 SynchronizationEvent
IRP List:
f5f1bdb8: (0006,0244) Flags: 40000a01 Mdl: 813cae08
Not impersonating
Owning Process 81fc68a0
Wait Start TickCount 61333 Elapsed Ticks: 18713
Context Switch Count 3181
UserTime 0:00:00.0000
KernelTime 0:00:07.0630
Start Address nt!ExpWorkerThread (0x80419112)
Stack Init ec48c000 Current ec48b25c Base ec48c000 Limit ec489000 Call 0
Priority 14 BasePriority 12 PriorityDecrement 2 DecrementCount 16

ChildEBP RetAddr Args to Child
ec48b274 8042dc7d 00000001 00000000 00000001 nt!KiSwapThread+0xc5
ec48b2a8 804bdbf3 00000001 ec48bbdc 00000000
nt!KeWaitForMultipleObjects+0x266
ec48bcf4 804bde7a 00000001 00000000 ec48bd1c nt!CmpFileWrite+0x1a7
ec48bd40 804be061 e139d400 00000000 e139d4c8 nt!HvpDoWriteHive+0x1f4
ec48bd54 804bd98c e139d400 8046d9bc 80476680 nt!HvSyncHive+0x44
ec48bd70 804bd9e8 81fa4d40 804191d7 00000000 nt!CmpDoFlushAll+0x4c
ec48bd78 804191d7 00000000 00000000 00000000 nt!CmpLazyFlushWorker+0x16
ec48bda8 80455e49 00000000 00000000 00000000 nt!ExpWorkerThread+0xae
ec48bddc 8046a152 80419112 80000001 00000000 nt!PspSystemThreadStartup+0x69
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

kd> !irp f5f1bdb8
Irp is active with 13 stacks 12 is current (= 0xf5f1bfb4)
Mdl = 813cae08 Thread 81fa4d40: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 10 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[4, 0] 0 e1 81fa1018 00000000 f86d9a62-813b8548 Success Error Cancel
pending
\Driver\psman5 Ntfs!NtfsSingleAsyncCompletionRoutine
Args: 00000200 00000000 924f5000 00000001
[4, 0] 0 0 81f80720 81ef9208 00000000-00000000
\FileSystem\Ntfs
Args: 00000200 00000000 00000000 00000000

kd> !devstack 81fa1018
!DevObj !DrvObj !DevExt ObjectName

81fa1018 \Driver\psman5 81fa10d0
81fc7770 \Driver\Ftdisk 81fc7828 HarddiskVolume1
!DevNode 81fc8888 :
DeviceInst is
“STORAGE\Volume\1&30a96598&0&Signature6441277EOffset7E00Length1F4117A00”
ServiceName is “psman5”
kd> !object 81ef9208
Object: 81ef9208 Type: (81fbd4a0) File
ObjectHeader: 81ef91f0
HandleCount: 1 PointerCount: 2
Directory Object: 00000000 Name: \WINNT\system32\config\software
{HarddiskVolume1}
kd> .thread 81fa4d40
Implicit thread is now 81fa4d40
kd> kv
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr Args to Child
ec48b274 8042dc7d 00000001 00000000 00000001 nt!KiSwapThread+0xc5 (FPO: [EBP
0xec48b2a8] [0,0,4])
ec48b2a8 804bdbf3 00000001 ec48bbdc 00000000
nt!KeWaitForMultipleObjects+0x266 (FPO: [Non-Fpo])
ec48bcf4 804bde7a 00000001 00000000 ec48bd1c nt!CmpFileWrite+0x1a7 (FPO:
[Non-Fpo])
ec48bd40 804be061 e139d400 00000000 e139d4c8 nt!HvpDoWriteHive+0x1f4 (FPO:
[Non-Fpo])
ec48bd54 804bd98c e139d400 8046d9bc 80476680 nt!HvSyncHive+0x44 (FPO:
[Non-Fpo])
ec48bd70 804bd9e8 81fa4d40 804191d7 00000000 nt!CmpDoFlushAll+0x4c (FPO:
[EBP 0x8046d9bc] [0,1,4])
ec48bd78 804191d7 00000000 00000000 00000000 nt!CmpLazyFlushWorker+0x16
(FPO: [1,0,1])
ec48bda8 80455e49 00000000 00000000 00000000 nt!ExpWorkerThread+0xae (FPO:
[Non-Fpo])
ec48bddc 8046a152 80419112 80000001 00000000 nt!PspSystemThreadStartup+0x69
(FPO: [Non-Fpo])
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

Thanks,
Rob

OSR_Community_User · August 30, 2004, 11:25pm

Rob,

Here’s a theory to explore: You drop (or queue and forget) the IRP during
the startup that you refer to, and the issuing thread is blocked waiting for
IRP completion, while it holds the Registry lock. Try to either verify or
disprove the following points.

– The thread you show is not waiting on the Registry lock, it already owns
it. The lock was acquired before the registry flush’s Write IRP was issued.

– Your driver received the IRP, pended it, and returned, but then never
processed the IRP.

– The Write was async, the call returned pending, and the thread is
explicitly waiting on the IRP to complete.

Perhaps there is a transient state during the initialization triggered by
your IOCTL, which breaks your concurrent handling of some Writes. This
would be a path that intends to queue/dequeue, since you pended the IRP (if
the above points are confirmed). You indicate that you have created no
threads yet, so it didn’t get as far as the dequeue.

Geoff

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com]On Behalf Of Rob Green
Sent: Monday, August 30, 2004 1:22 PM
To: Windows System Software Devs Interest List
Subject: [ntdev] Hang in storage filter and NFS