Jonathon,
Here’s my theory:
NTFS is called by the user mode thread to read from a region of the file
that was not previously written (beyond valid data length). In the
process it sets the FSRTL_FLAG_EOF_ADVANCE_ACTIVE flag in the common
header block (Flags) - this gives you something else to confirm.
It performs a read from the cache (hence the call to CcCopyRead from
NtfsCommonRead). Since the data is not in the cache, this triggers a
page fault. The page fault irp is intercepted by your filter; you then
post a work item to the worker thread. The worker thread issues a
ZwReadFile on the same file and ALSO beyond the ValidDataLength of the
file, so this second thread blocks and waits for the EOF to be extended
by the first thread. Of course, the first thread won’t ever finish
because it is waiting for the second thread (the worker) to finish.
So now you’ll say “so, how do I prevent this from happening?” First,
before making some wild suggestions, I’ll note that I have no idea what
you are doing, or why you did it this way. What I CAN note is that this
form of EOF serialization doesn’t happen for paging I/O, which is why
you’d never see it in the “normal course of events”. I also suspect it
requires a file where the ValidDataLength < EOF and not on a page
boundary, requiring that the VM system pull in the data (hence the
paging I/O) rather than just return a zero-filled block of data. That
might explain why you only see it sometimes.
My first suggestion would be: don’t use ZwReadFile. That’s just asking
for trouble here. If you must do this in a worker thread (and again, I
don’t know why you are doing this) you should do this with an IRP. Of
course, if my theory above is correct, even a garden variety IRP_MJ_READ
is going to hang as well on the growth of ValidDataLength. Only a
paging I/O IRP is not going to do that - and building paging I/O IRPs
can be done but the I/O Manager handles them quite a bit differently
(completion processing is very different for paging I/O operations.)
So, perhaps better understanding what you are trying to achieve, I or
someone else can suggest an alternative approach.
Regards,
Tony
Tony Mason
Consulting Partner
OSR Open Systems Resources, Inc.
http://www.osr.com
Hope to see you at the next OSR file systems class in Boston, MA, March
29, 2004!
-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Jonathon
Sent: Thursday, April 08, 2004 2:26 PM
To: ntfsd redirect
Subject: Re:[ntfsd] Deadlock with PagingIoResource
Thanks again Tony. This has been really helpful.
I tried looking up that WaitForIoAtEof but couldn’t figure out what it
was
doing. The user-mode-application-read that I block isn’t under my
control
but I assume that it is somehow special since I have no problem blocking
other file reads. Is there a way that I can get around this? In other
words
is there a way to read from a blocked file that is in the process of
“extending the EOF”? Would it be possible for me to stop that app from
“extending the EOF” temporarily?
I’ve included output for everything with symbols and with more detail
for
the IRPs.
Pended user-mode read:
kd> !thread 81e36020
THREAD 81e36020 Cid 0514.02cc Teb: 7ffde000 Win32Thread: e1125008
WAIT:
(Executive) KernelMode Non-Alertable
baf632a0 NotificationEvent
IRP List:
825f8e28: (0006,01d8) Flags: 40000900 Mdl: 00000000
Not impersonating
DeviceMap e1f5bd20
Owning Process 81db4020
Wait Start TickCount 8425 Elapsed Ticks: 391
Context Switch Count 120 LargeStack
UserTime 00:00:00.0000
KernelTime 00:00:00.0718
Start Address 0x77e8149f
Win32 Start Address 0x004b64d9
Stack Init f4ea5000 Current f4ea42ec Base f4ea5000 Limit f4ea0000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2 DecrementCount 16
ChildEBP RetAddr Args to Child
f4ea4304 804fafe4 81e36090 81e36020 804f50ec nt!KiSwapContext+0x2e (FPO:
[EBP 0xf4ea4338] [0,0,4])
f4ea4310 804f50ec 00000000 baf632a0 8213d001 nt!KiSwapThread+0x44 (FPO:
[0,0,2])
f4ea4338 8062d3ac 00000000 00000000 00000000
nt!KeWaitForSingleObject+0x1c0
(FPO: [Non-Fpo])
f4ea4360 baf5bb80 baf632a0 00000000 00000000
nt!VerifierKeWaitForSingleObject+0x54 (FPO: [Non-Fpo])
f4ea45f4 804ea221 822b4e80 82754e28 806ad1a8 Sfilter!SfRead+0x4a0 (CONV:
stdcall) [c:\code\warbird\driver\sfilter.c @ 1941]
f4ea4604 8062c190 81e2abe0 1fe33000 8213d0c8 nt!IopfCallDriver+0x31
(FPO:
[0,0,1])
f4ea4628 804eab1a 00000000 8213d0b8 00000000 nt!IovCallDriver+0x9e (FPO:
[Non-Fpo])
f4ea463c 804eab3b 822b4e80 8213d00a 8213d0d0 nt!IopPageReadInternal+0xf2
(FPO: [Non-Fpo])
f4ea465c 8050a326 81e2abe0 8213d0f0 8213d0d0 nt!IoPageRead+0x19 (FPO:
[Non-Fpo])
f4ea46cc 80511a33 8213d0b8 d403329d c03500cc nt!MiDispatchFault+0x270
(FPO:
[Non-Fpo])
f4ea471c 8050d988 00000000 d403329d 00000000 nt!MmAccessFault+0x5bb
(FPO:
[Non-Fpo])
f4ea4754 80547e5a d403329d 00000000 825f8e40
nt!MmCheckCachedPageState+0x308
(FPO: [Non-Fpo])
f4ea47e0 baebffc7 81e2abe0 f4ea486c 00000404 nt!CcCopyRead+0x3da (FPO:
[Non-Fpo])
f4ea48bc baec016f 81e65788 825f8e28 00000001 Ntfs!NtfsCommonRead+0xd29
f4ea495c 804ea221 82258020 825f8e28 806ad1a8 Ntfs!NtfsFsdRead+0x22d
f4ea496c 8062c190 822d4dd0 8226b2d0 825f8e00 nt!IopfCallDriver+0x31
(FPO:
[0,0,1])
f4ea4990 baf6d42d 804ea221 822d4dd0 825f8e28 nt!IovCallDriver+0x9e (FPO:
[Non-Fpo])
f4ea4994 804ea221 822d4dd0 825f8e28 806ad1a8 sr!SrPassThrough+0x2f (FPO:
[2,0,0])
f4ea49a4 8062c190 822b4e80 82269040 825f8e00 nt!IopfCallDriver+0x31
(FPO:
[0,0,1])
f4ea49c8 baf5bbac baf5b5ae 00000001 00000001 nt!IovCallDriver+0x9e (FPO:
[Non-Fpo])
f4ea4c48 804ea221 822b4e80 825f8e28 806ad1a8 Sfilter!SfRead+0x4cc (CONV:
stdcall) [c:\code\warbird\driver\sfilter.c @ 1943]
f4ea4c58 8062c190 81e36230 806ad190 825f8e28 nt!IopfCallDriver+0x31
(FPO:
[0,0,1])
f4ea4c7c 8055d0fe 825f8fdc 825f8e28 81e2abe0 nt!IovCallDriver+0x9e (FPO:
[Non-Fpo])
f4ea4c90 8055a3bf 822b4e80 825f8e28 81e2abe0
nt!IopSynchronousServiceTail+0x5e (FPO: [Non-Fpo])
f4ea4d38 8052d571 0000006c 00000000 00000000 nt!NtReadFile+0x559
f4ea4d38 7ffe0304 0000006c 00000000 00000000 nt!KiSystemService+0xc4
(FPO:
[0,0] TrapFrame @ f4ea4d64)
01e1eb48 00000000 00000000 00000000 00000000
SharedUserData!SystemCallStub+0x4 (FPO: [0,0,0])
kd> !irp 825f8e28 1
Irp is active with 10 stacks 8 is current (= 0x825f8f94)
No Mdl Thread 81e36020: Irp stack trace.
Flags = 40000900
ThreadListEntry.Flink = 81e36230
ThreadListEntry.Blink = 81e36230
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000001
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = 01e1eb18
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 003ee370
&Tail.Overlay.DeviceQueueEntry = 825f8e68
Tail.Overlay.Thread = 81e36020
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = 825f8f94
Tail.Overlay.OriginalFileObject = 81e2abe0
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
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 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 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
[3, 0] 0 e0 82258020 81e2abe0 8063879c-825f8fb8 Success Error
Cancel
\FileSystem\Ntfs nt!IovpInternalCompletionTrap
Args: 00001000 00000000 1fe3329d 00000000
[3, 0] 0 e0 822d4dd0 81e2abe0 8063879c-825f8fdc Success Error
Cancel
\FileSystem\sr nt!IovpInternalCompletionTrap
Args: 00001000 00000000 1fe3329d 00000000
[3, 0] 0 0 822b4e80 81e2abe0 00000000-00000000
\FileSystem\Sfilter
Args: 00001000 00000000 1fe3329d 00000000
Worker thread ZwReadFile which doesn’t return:
kd> !thread 82299DA8
THREAD 82299da8 Cid 0004.006c Teb: 00000000 Win32Thread: 00000000
WAIT:
(Executive) KernelMode Non-Alertable
f8926608 NotificationEvent
IRP List:
82576e28: (0006,01d8) Flags: 40000900 Mdl: 00000000
Not impersonating
DeviceMap e1004498
Owning Process 822ce838
Wait Start TickCount 8618 Elapsed Ticks: 198
Context Switch Count 201
UserTime 00:00:00.0000
KernelTime 00:00:04.0906
Start Address Sfilter!SFilterWorkerThreadMaster (0xbaf5f6a0)
Stack Init f8927000 Current f892658c Base f8927000 Limit f8924000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr Args to Child
f89265a4 804fafe4 82299e18 82299da8 804f50ec nt!KiSwapContext+0x2e (FPO:
[EBP 0xf89265d8] [0,0,4])
f89265b0 804f50ec 00000000 e262c590 81db96a0 nt!KiSwapThread+0x44 (FPO:
[0,0,2])
f89265d8 baefb2d9 00000000 00000000 00000000
nt!KeWaitForSingleObject+0x1c0
(FPO: [Non-Fpo])
f8926618 baec59a1 e262c590 baedb358 00000000
Ntfs!NtfsWaitForIoAtEof+0x48
(FPO: [Non-Fpo])
f89266e8 baec016f 81db96a0 82576e28 00000001 Ntfs!NtfsCommonRead+0xca6
f8926788 804ea221 82258020 82576e28 806ad1a8 Ntfs!NtfsFsdRead+0x22d
f8926798 8062c190 822d4dd0 8226b2d0 82576e00 nt!IopfCallDriver+0x31
(FPO:
[0,0,1])
f89267bc baf6d42d 804ea221 822d4dd0 82576e28 nt!IovCallDriver+0x9e (FPO:
[Non-Fpo])
f89267c0 804ea221 822d4dd0 82576e28 806ad1a8 sr!SrPassThrough+0x2f (FPO:
[2,0,0])
f89267d0 8062c190 822b4e80 82269040 82576e00 nt!IopfCallDriver+0x31
(FPO:
[0,0,1])
f89267f4 baf5ba59 baf5b5ae 00000001 00000001 nt!IovCallDriver+0x9e (FPO:
[Non-Fpo])
f8926a74 804ea221 822b4e80 82576e28 806ad1a8 Sfilter!SfRead+0x379 (CONV:
stdcall) [c:\code\warbird\driver\sfilter.c @ 1867]
f8926a84 8062c190 82299fb8 806ad190 82576e28 nt!IopfCallDriver+0x31
(FPO:
[0,0,1])
f8926aa8 8055d0fe 82576fdc 82576e28 81e5c0e8 nt!IovCallDriver+0x9e (FPO:
[Non-Fpo])
f8926abc 8055a3bf 822b4e80 82576e28 81e5c0e8
nt!IopSynchronousServiceTail+0x5e (FPO: [Non-Fpo])
f8926b64 8052d571 800004bc 00000000 00000000 nt!NtReadFile+0x559
f8926b64 804f926d 800004bc 00000000 00000000 nt!KiSystemService+0xc4
(FPO:
[0,0] TrapFrame @ f8926b90)
f8926c00 baf607d4 800004bc 00000000 00000000 nt!ZwReadFile+0x11 (FPO:
[9,0,0])
f8926d00 baf5f891 bac32000 81e4c550 000004b8
Sfilter!PreloadDataFiles+0x534
(CONV: stdcall) [c:\code\warbird\driver\sfilterwthread.c @ 874]
f8926dac 805aa2b6 baf630a4 00000000 00000000
Sfilter!SFilterWorkerThreadMaster+0x1f1 (CONV: stdcall)
[c:\code\warbird\driver\sfilterwthread.c @ 264]
f8926ddc 805319c6 baf5f6a0 baf630a4 00000000
nt!PspSystemThreadStartup+0x34
(FPO: [Non-Fpo])
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
kd> !irp 82576e28 1
Irp is active with 10 stacks 8 is current (= 0x82576f94)
No Mdl Thread 82299da8: Irp stack trace.
Flags = 40000900
ThreadListEntry.Flink = 82299fb8
ThreadListEntry.Blink = 82299fb8
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = f8926c58
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = bac32000
&Tail.Overlay.DeviceQueueEntry = 82576e68
Tail.Overlay.Thread = 82299da8
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = 82576f94
Tail.Overlay.OriginalFileObject = 81e5c0e8
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
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 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 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
[3, 0] 0 e0 82258020 81e5c0e8 8063879c-82576fb8 Success Error
Cancel
\FileSystem\Ntfs nt!IovpInternalCompletionTrap
Args: 00000100 00000000 00000000 00000000
[3, 0] 0 e0 822d4dd0 81e5c0e8 8063879c-82576fdc Success Error
Cancel
\FileSystem\sr nt!IovpInternalCompletionTrap
Args: 00000100 00000000 00000000 00000000
[3, 0] 0 0 822b4e80 81e5c0e8 00000000-00000000
\FileSystem\Sfilter
Args: 00000100 00000000 00000000 00000000
“Tony Mason” wrote in message news:xxxxx@ntfsd…
Jonathon,
The missing piece here is that the driver without symbols in the first
case
ALSO included NTFS - and now I think I suspect the problem is you are
hitting some serialization between NTFS and yourself. Notice that
“WaitForIoAtEof” in NTFS? You don’t give us the other thread trace with
the
NTFS symbols, but my guess is that you’re extending the EOF in that
initial
thread and NTFS is serializing against itself - waiting for the first
thread
to signal to the second thread that it can proceed.
Nothing like running the debugger over e-mail!
Regards,
Tony
Tony Mason
Consulting Partner
OSR Open Systems Resources, Inc.
http://www.osr.com
Hope to see you at the next OSR file systems class in Boston, MA, March
29,
2004!
—
Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17
You are currently subscribed to ntfsd as: xxxxx@osr.com
To unsubscribe send a blank email to xxxxx@lists.osr.com