Deadlock during FlushFileBuffers, 2nd

Hi all,

currently I’m trying so solve a problem in our filterdriver. I already
posted this problem but I didn’t get any further. The sympthoms are as
follows:

When a large file is written through the “shadow device”, which is provided
by our filter driver, occationally the flush after the file is completely
written by BackupWrite() gets blocked. This suituation happens very rarely
with large files on W2k but on Win2003 it is easily reproudcible.

My interpretation is that the flush-thread currently waits exclusively on
resource 0x81edf258 and does not get it, since “mapped page writer” still
own it shared. It seems as the lazy writer and the explcit flush are
blocking erach other.

When looking at the PFN database, the file that is written shows the
following state:

Control Valid Standby Dirty Shared Locked PageTables name
8215f440 308 0 7040 0 1280 0 mapped_file( ~test.mpg.itr )

The control area looks as follows:
kd> !ca 8215f440

ControlArea @8215f440
Segment: e1874930 Flink 0 Blink 0
Section Ref 1 Pfn Ref 741 Mapped Views 2
User Ref 0 WaitForDel 0 Flush Count 0
File Object 81bd7e80 ModWriteCount 14 System Views 2
Flags (8080) File WasPurged

File: \large~test.mpg.itr

Segment @ e1874930:
Type MAPPED_FILE_SEGMENT not found.

I would suspect this this mapping is a result of the file system cache. I’ve
read the memory management section of Marc Russinovich’s “Inside Win 2000”
but I couldn’t find an explanation of pages that are in state “locked”. Are
these pages that are “currently” written to the file ?

As I stated ealier the filter attaches to NTFS drives only and does not use
AcquireForModWrite and ReleaseForModWrite handlers.

Thanks in advance for any help, comments or hints get a little further in
this problem.

Lars

kd> !locks -v 0x81edf258

Resource @ 0x81edf258 Shared 1 owning threads
Contention Count = 2
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 1
Threads: 822c3a58-93a1<*>

THREAD 822c3a58 Cid 0004.0078 Teb: 00000000 Win32Thread: 00000000
WAIT: (DelayExecution) KernelMode Non-Alertable
822c3ad0 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116984 Elapsed Ticks: 1
Context Switch Count 111131
UserTime 00:00:00.0000
KernelTime 00:00:01.0171
Start Address nt!MiMappedPageWriter (0x805071e3)
Stack Init f892f000 Current f892ecd4 Base f892f000 Limit f892c000 Call
0
Priority 17 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
f892ecec 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP 0xf892ed04] [0,0,4])
f892ed04 804e4692 nt!KiSwapThread+0x85
f892ed38 8051f78f nt!KeDelayExecutionThread+0x183
f892ed78 805072fa nt!MiWriteComplete+0x3c3
f892edac 805f1828 nt!MiMappedPageWriter+0x150
f892eddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

822ad020-01

THREAD 822ad020 Cid 0004.0024 Teb: 00000000 Win32Thread: 00000000
WAIT: (WrResource) KernelMode Non-Alertable
82115408 Semaphore Limit 0x7fffffff
822ad098 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116838 Elapsed Ticks: 147
Context Switch Count 1238
UserTime 00:00:00.0000
KernelTime 00:00:00.0000
Start Address nt!ExpWorkerThread (0x804ec50d)
Stack Init f88d7000 Current f88d6c30 Base f88d7000 Limit f88d4000 Call
0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
f88d6c48 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP 0xf88d6c60] [0,0,4])
f88d6c60 804e42c2 nt!KiSwapThread+0x85
f88d6c90 805212c8 nt!KeWaitForSingleObject+0x209
f88d6ccc 8050388a nt!ExpWaitForResource+0xd1
f88d6ce0 f829acec nt!ExAcquireResourceSharedLite+0xaf
f88d6cec f82bf46b Ntfs!NtfsAcquirePagingResourceShared+0x1d (FPO:
[3,0,0])
f88d6d08 804f1014 Ntfs!NtfsAcquireScbForLazyWrite+0x78
f88d6d40 804ed5e2 nt!CcWriteBehind+0x22
f88d6d80 804ec5c8 nt!CcWorkerThread+0x123
f88d6dac 805f1828 nt!ExpWorkerThread+0xe9
f88d6ddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

Threads Waiting On Exclusive Access:
81f65da0

kd> !thread 81f65da0
THREAD 81f65da0 Cid 0170.00c8 Teb: 7ffde000 Win32Thread: e184a008 WAIT:
(WrResource) KernelMode Non-Alertable
8218a6a8 SynchronizationEvent
81f65e18 NotificationTimer
Not impersonating
DeviceMap e164e0d0
Owning Process 81f53c00
Wait Start TickCount 116784 Elapsed Ticks: 201
Context Switch Count 558932 LargeStack
UserTime 00:00:03.0250
KernelTime 00:00:24.0046
Start Address 0x77e2f35f
Win32 Start Address 0x00405f10
Stack Init f5f05000 Current f5f04950 Base f5f05000 Limit f5f01000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2
*** ERROR: Module load completed but symbols could not be loaded for
IvdIFS_G.sys
ChildEBP RetAddr Args to Child
f5f04968 804e4252 81f65da0 8218a6a8 00000000 nt!KiSwapContext+0x25 (FPO:
[EBP 0xf5f04980] [0,0,4])
f5f04980 804e42c2 81f65da0 81edf258 00000000 nt!KiSwapThread+0x85
f5f049b0 805212c8 8218a6a8 0000001b 00000000 nt!KeWaitForSingleObject+0x209
f5f049ec 804ef26b e1947678 82121a38 f5f04a74 nt!ExpWaitForResource+0xd1
f5f049fc f829acb8 81edf258 00000001 f82ca671
nt!ExAcquireResourceExclusiveLite+0x6c
f5f04a08 f82ca671 82121a38 e1947678 00000001
Ntfs!NtfsAcquirePagingResourceExclusive+0x1d (FPO: [3,0,0])
f5f04a74 f82ca8ff 82121a38 82153970 82153970
Ntfs!NtfsCommonFlushBuffers+0x10d
f5f04ad8 804e0e0d 82102598 82153970 81e732c0 Ntfs!NtfsFsdFlushBuffers+0x92
f5f04ae8 f610b8df 82153970 81e732c0 804efd6b nt!IofCallDriver+0x3f (FPO:
[0,0,0])
WARNING: Stack unwind information not available. Following frames may be
wrong.
f5f04ca8 f6106885 82167588 82153970 00000000 IvdIFS_G+0x68df
f5f04cbc 804e0e0d 82167588 82153970 82153970 IvdIFS_G+0x1885
f5f04ccc 805759ea 81bd7e80 82153970 00000000 nt!IofCallDriver+0x3f (FPO:
[0,0,0])
f5f04ce0 805921b0 82167588 82153970 81bd7e80
nt!IopSynchronousServiceTail+0x6c
f5f04d54 804e7a8c 0000071c 0011cda4 00000000 nt!NtFlushBuffersFile+0x1b5
f5f04d54 7ffe0304 0000071c 0011cda4 00000000 nt!KiSystemService+0xcb (FPO:
[0,0] TrapFrame @ f5f04d64)
0011cdac 00000000 00000000 00000000 00000000
SharedUserData!SystemCallStub+0x4 (FPO: [0,0,0])

This is a long shot, but can you answer a couple questions for me –

  1. Is this file compressed?
  2. What are the file size and valid data length from the
    FSRTL_COMMON_FCB_HEADER for this file? (This header is at the beginning
    of the FsContext structure.)

Thanks,
Molly Brown
Microsoft Corporation

This posting is provided “AS IS” with no warranties and confers no
rights.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Lars Diehl
Sent: Tuesday, February 17, 2004 3:05 AM
To: Windows File Systems Devs Interest List
Subject: [ntfsd] Deadlock during FlushFileBuffers, 2nd

Hi all,

currently I’m trying so solve a problem in our filterdriver. I already
posted this problem but I didn’t get any further. The sympthoms are as
follows:

When a large file is written through the “shadow device”, which is
provided by our filter driver, occationally the flush after the file is
completely written by BackupWrite() gets blocked. This suituation
happens very rarely with large files on W2k but on Win2003 it is easily
reproudcible.

My interpretation is that the flush-thread currently waits exclusively
on resource 0x81edf258 and does not get it, since “mapped page writer”
still own it shared. It seems as the lazy writer and the explcit flush
are blocking erach other.

When looking at the PFN database, the file that is written shows the
following state:

Control Valid Standby Dirty Shared Locked PageTables name
8215f440 308 0 7040 0 1280 0 mapped_file(
~test.mpg.itr )

The control area looks as follows:
kd> !ca 8215f440

ControlArea @8215f440
Segment: e1874930 Flink 0 Blink 0
Section Ref 1 Pfn Ref 741 Mapped Views 2
User Ref 0 WaitForDel 0 Flush Count
0
File Object 81bd7e80 ModWriteCount 14 System Views 2
Flags (8080) File WasPurged

File: \large~test.mpg.itr

Segment @ e1874930:
Type MAPPED_FILE_SEGMENT not found.

I would suspect this this mapping is a result of the file system cache.
I’ve read the memory management section of Marc Russinovich’s “Inside
Win 2000”
but I couldn’t find an explanation of pages that are in state “locked”.
Are these pages that are “currently” written to the file ?

As I stated ealier the filter attaches to NTFS drives only and does not
use AcquireForModWrite and ReleaseForModWrite handlers.

Thanks in advance for any help, comments or hints get a little further
in this problem.

Lars

kd> !locks -v 0x81edf258

Resource @ 0x81edf258 Shared 1 owning threads
Contention Count = 2
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 1
Threads: 822c3a58-93a1<*>

THREAD 822c3a58 Cid 0004.0078 Teb: 00000000 Win32Thread: 00000000
WAIT: (DelayExecution) KernelMode Non-Alertable
822c3ad0 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116984 Elapsed Ticks: 1
Context Switch Count 111131
UserTime 00:00:00.0000
KernelTime 00:00:01.0171
Start Address nt!MiMappedPageWriter (0x805071e3)
Stack Init f892f000 Current f892ecd4 Base f892f000 Limit f892c000
Call 0
Priority 17 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
f892ecec 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP 0xf892ed04]
[0,0,4])
f892ed04 804e4692 nt!KiSwapThread+0x85
f892ed38 8051f78f nt!KeDelayExecutionThread+0x183
f892ed78 805072fa nt!MiWriteComplete+0x3c3
f892edac 805f1828 nt!MiMappedPageWriter+0x150
f892eddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

822ad020-01

THREAD 822ad020 Cid 0004.0024 Teb: 00000000 Win32Thread: 00000000
WAIT: (WrResource) KernelMode Non-Alertable
82115408 Semaphore Limit 0x7fffffff
822ad098 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116838 Elapsed Ticks: 147
Context Switch Count 1238
UserTime 00:00:00.0000
KernelTime 00:00:00.0000
Start Address nt!ExpWorkerThread (0x804ec50d)
Stack Init f88d7000 Current f88d6c30 Base f88d7000 Limit f88d4000
Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
f88d6c48 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP 0xf88d6c60]
[0,0,4])
f88d6c60 804e42c2 nt!KiSwapThread+0x85
f88d6c90 805212c8 nt!KeWaitForSingleObject+0x209
f88d6ccc 8050388a nt!ExpWaitForResource+0xd1
f88d6ce0 f829acec nt!ExAcquireResourceSharedLite+0xaf
f88d6cec f82bf46b Ntfs!NtfsAcquirePagingResourceShared+0x1d (FPO:
[3,0,0])
f88d6d08 804f1014 Ntfs!NtfsAcquireScbForLazyWrite+0x78
f88d6d40 804ed5e2 nt!CcWriteBehind+0x22
f88d6d80 804ec5c8 nt!CcWorkerThread+0x123
f88d6dac 805f1828 nt!ExpWorkerThread+0xe9
f88d6ddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

Threads Waiting On Exclusive Access:
81f65da0

kd> !thread 81f65da0
THREAD 81f65da0 Cid 0170.00c8 Teb: 7ffde000 Win32Thread: e184a008
WAIT:
(WrResource) KernelMode Non-Alertable
8218a6a8 SynchronizationEvent
81f65e18 NotificationTimer
Not impersonating
DeviceMap e164e0d0
Owning Process 81f53c00
Wait Start TickCount 116784 Elapsed Ticks: 201
Context Switch Count 558932 LargeStack
UserTime 00:00:03.0250
KernelTime 00:00:24.0046
Start Address 0x77e2f35f
Win32 Start Address 0x00405f10
Stack Init f5f05000 Current f5f04950 Base f5f05000 Limit f5f01000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2
*** ERROR: Module load completed but symbols could not be loaded for
IvdIFS_G.sys ChildEBP RetAddr Args to Child
f5f04968 804e4252 81f65da0 8218a6a8 00000000 nt!KiSwapContext+0x25 (FPO:
[EBP 0xf5f04980] [0,0,4])
f5f04980 804e42c2 81f65da0 81edf258 00000000 nt!KiSwapThread+0x85
f5f049b0 805212c8 8218a6a8 0000001b 00000000
nt!KeWaitForSingleObject+0x209 f5f049ec 804ef26b e1947678 82121a38
f5f04a74 nt!ExpWaitForResource+0xd1 f5f049fc f829acb8 81edf258 00000001
f82ca671 nt!ExAcquireResourceExclusiveLite+0x6c
f5f04a08 f82ca671 82121a38 e1947678 00000001
Ntfs!NtfsAcquirePagingResourceExclusive+0x1d (FPO: [3,0,0])
f5f04a74 f82ca8ff 82121a38 82153970 82153970
Ntfs!NtfsCommonFlushBuffers+0x10d
f5f04ad8 804e0e0d 82102598 82153970 81e732c0
Ntfs!NtfsFsdFlushBuffers+0x92
f5f04ae8 f610b8df 82153970 81e732c0 804efd6b nt!IofCallDriver+0x3f (FPO:
[0,0,0])
WARNING: Stack unwind information not available. Following frames may be
wrong.
f5f04ca8 f6106885 82167588 82153970 00000000 IvdIFS_G+0x68df f5f04cbc
804e0e0d 82167588 82153970 82153970 IvdIFS_G+0x1885 f5f04ccc 805759ea
81bd7e80 82153970 00000000 nt!IofCallDriver+0x3f (FPO:
[0,0,0])
f5f04ce0 805921b0 82167588 82153970 81bd7e80
nt!IopSynchronousServiceTail+0x6c
f5f04d54 804e7a8c 0000071c 0011cda4 00000000 nt!NtFlushBuffersFile+0x1b5
f5f04d54 7ffe0304 0000071c 0011cda4 00000000 nt!KiSystemService+0xcb
(FPO:
[0,0] TrapFrame @ f5f04d64)
0011cdac 00000000 00000000 00000000 00000000
SharedUserData!SystemCallStub+0x4 (FPO: [0,0,0])


Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17

You are currently subscribed to ntfsd as: xxxxx@windows.microsoft.com
To unsubscribe send a blank email to xxxxx@lists.osr.com

Molly,

  1. No, it is not compressed
  2. The size values are:

Allocation size: 2484916224
File size: 2484916084
Valid data length: 2484916084

BTW, is there an easier way the get the contents of
FSRTL_COMMON_FCB_HEADER ?

Thanks,
Lars

dt _FILE_OBJECT 81bd7e80
+0x000 Type : 5
+0x002 Size : 112
+0x004 DeviceObject : 0x82167588
+0x008 Vpb : 0x82167690
+0x00c FsContext : 0xe1947740
+0x010 FsContext2 : 0xe1947888
+0x014 SectionObjectPointer : 0x81f98c1c
+0x018 PrivateCacheMap : 0x81f7f2e8
+0x01c FinalStatus : 0
+0x020 RelatedFileObject : (null)
+0x024 LockOperation : 0 ‘’
+0x025 DeletePending : 0 ‘’
+0x026 ReadAccess : 0 ‘’
+0x027 WriteAccess : 0x1 ‘’
+0x028 DeleteAccess : 0 ‘’
+0x029 SharedRead : 0 ‘’
+0x02a SharedWrite : 0 ‘’
+0x02b SharedDelete : 0 ‘’
+0x02c Flags : 0x43062
+0x030 FileName : _UNICODE_STRING “\large~test.mpg.itr”
+0x038 CurrentByteOffset : _LARGE_INTEGER 0x941ccf74
+0x040 Waiters : 0
+0x044 Busy : 1
+0x048 LastLock : (null)
+0x04c Lock : _KEVENT
+0x05c Event : _KEVENT
+0x06c CompletionContext : (null)

kd> dd 0xe1947740
e1947740 01480705 00020140 81e647c0 81edf258
e1947750 941cd000 00000000 941ccf74 00000000
e1947760 941ccf74 00000000 81f8f1b8 e194776c
e1947770 e194776c 00000000 e1947848 00000000
e1947780 e19476a8 e19476a8 e1947678 82102678
e1947790 00400a31 00000000 00000001 00000001
e19477a0 00000001 00000000 00000001 00000000
e19477b0 00000000 00000000 00000000 00000080

Molly Brown schrieb:

This is a long shot, but can you answer a couple
questions for me –

  1. Is this file compressed?
  2. What are the file size and valid data length from the
    FSRTL_COMMON_FCB_HEADER for this file? (This header is at
    the beginning
    of the FsContext structure.)

Thanks,
Molly Brown
Microsoft Corporation

This posting is provided “AS IS” with no warranties and
confers no
rights.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
Lars Diehl
Sent: Tuesday, February 17, 2004 3:05 AM
To: Windows File Systems Devs Interest List
Subject: [ntfsd] Deadlock during FlushFileBuffers, 2nd

Hi all,

currently I’m trying so solve a problem in our
filterdriver. I already
posted this problem but I didn’t get any further. The
sympthoms are as
follows:

When a large file is written through the “shadow device”,
which is
provided by our filter driver, occationally the flush
after the file is
completely written by BackupWrite() gets blocked. This
suituation
happens very rarely with large files on W2k but on
Win2003 it is easily
reproudcible.

My interpretation is that the flush-thread currently
waits exclusively
on resource 0x81edf258 and does not get it, since “mapped
page writer”
still own it shared. It seems as the lazy writer and the
explcit flush
are blocking erach other.

When looking at the PFN database, the file that is
written shows the
following state:

Control Valid Standby Dirty Shared Locked PageTables
name
8215f440 308 0 7040 0 1280 0
mapped_file(
~test.mpg.itr )

The control area looks as follows:
kd> !ca 8215f440

ControlArea @8215f440
Segment: e1874930 Flink 0 Blink
0
Section Ref 1 Pfn Ref 741 Mapped
Views 2
User Ref 0 WaitForDel 0 Flush
Count
0
File Object 81bd7e80 ModWriteCount 14 System
Views 2
Flags (8080) File WasPurged

File: \large~test.mpg.itr

Segment @ e1874930:
Type MAPPED_FILE_SEGMENT not found.

I would suspect this this mapping is a result of the file
system cache.
I’ve read the memory management section of Marc
Russinovich’s “Inside
Win 2000”
but I couldn’t find an explanation of pages that are in
state “locked”.
Are these pages that are “currently” written to the file
?

As I stated ealier the filter attaches to NTFS drives
only and does not
use AcquireForModWrite and ReleaseForModWrite handlers.

Thanks in advance for any help, comments or hints get a
little further
in this problem.

Lars

kd> !locks -v 0x81edf258

Resource @ 0x81edf258 Shared 1 owning threads
Contention Count = 2
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 1
Threads: 822c3a58-93a1<*>

THREAD 822c3a58 Cid 0004.0078 Teb: 00000000
Win32Thread: 00000000
WAIT: (DelayExecution) KernelMode Non-Alertable
822c3ad0 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116984 Elapsed
Ticks: 1
Context Switch Count 111131
UserTime 00:00:00.0000
KernelTime 00:00:01.0171
Start Address nt!MiMappedPageWriter (0x805071e3)
Stack Init f892f000 Current f892ecd4 Base f892f000
Limit f892c000
Call 0
Priority 17 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
f892ecec 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP
0xf892ed04]
[0,0,4])
f892ed04 804e4692 nt!KiSwapThread+0x85
f892ed38 8051f78f nt!KeDelayExecutionThread+0x183
f892ed78 805072fa nt!MiWriteComplete+0x3c3
f892edac 805f1828 nt!MiMappedPageWriter+0x150
f892eddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

822ad020-01

THREAD 822ad020 Cid 0004.0024 Teb: 00000000
Win32Thread: 00000000
WAIT: (WrResource) KernelMode Non-Alertable
82115408 Semaphore Limit 0x7fffffff
822ad098 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116838 Elapsed
Ticks: 147
Context Switch Count 1238
UserTime 00:00:00.0000
KernelTime 00:00:00.0000
Start Address nt!ExpWorkerThread (0x804ec50d)
Stack Init f88d7000 Current f88d6c30 Base f88d7000
Limit f88d4000
Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
f88d6c48 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP
0xf88d6c60]
[0,0,4])
f88d6c60 804e42c2 nt!KiSwapThread+0x85
f88d6c90 805212c8 nt!KeWaitForSingleObject+0x209
f88d6ccc 8050388a nt!ExpWaitForResource+0xd1
f88d6ce0 f829acec
nt!ExAcquireResourceSharedLite+0xaf
f88d6cec f82bf46b
Ntfs!NtfsAcquirePagingResourceShared+0x1d (FPO:
[3,0,0])
f88d6d08 804f1014
Ntfs!NtfsAcquireScbForLazyWrite+0x78
f88d6d40 804ed5e2 nt!CcWriteBehind+0x22
f88d6d80 804ec5c8 nt!CcWorkerThread+0x123
f88d6dac 805f1828 nt!ExpWorkerThread+0xe9
f88d6ddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

Threads Waiting On Exclusive Access:
81f65da0

kd> !thread 81f65da0
THREAD 81f65da0 Cid 0170.00c8 Teb: 7ffde000
Win32Thread: e184a008
WAIT:
(WrResource) KernelMode Non-Alertable
8218a6a8 SynchronizationEvent
81f65e18 NotificationTimer
Not impersonating
DeviceMap e164e0d0
Owning Process 81f53c00
Wait Start TickCount 116784 Elapsed Ticks:
201
Context Switch Count 558932
LargeStack
UserTime 00:00:03.0250
KernelTime 00:00:24.0046
Start Address 0x77e2f35f
Win32 Start Address 0x00405f10
Stack Init f5f05000 Current f5f04950 Base f5f05000 Limit
f5f01000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2
*** ERROR: Module load completed but symbols could not be
loaded for
IvdIFS_G.sys ChildEBP RetAddr Args to Child
f5f04968 804e4252 81f65da0 8218a6a8 00000000
nt!KiSwapContext+0x25 (FPO:
[EBP 0xf5f04980] [0,0,4])
f5f04980 804e42c2 81f65da0 81edf258 00000000
nt!KiSwapThread+0x85
f5f049b0 805212c8 8218a6a8 0000001b 00000000
nt!KeWaitForSingleObject+0x209 f5f049ec 804ef26b e1947678
82121a38
f5f04a74 nt!ExpWaitForResource+0xd1 f5f049fc f829acb8
81edf258 00000001
f82ca671 nt!ExAcquireResourceExclusiveLite+0x6c
f5f04a08 f82ca671 82121a38 e1947678 00000001
Ntfs!NtfsAcquirePagingResourceExclusive+0x1d (FPO:
[3,0,0])
f5f04a74 f82ca8ff 82121a38 82153970 82153970
Ntfs!NtfsCommonFlushBuffers+0x10d
f5f04ad8 804e0e0d 82102598 82153970 81e732c0
Ntfs!NtfsFsdFlushBuffers+0x92
f5f04ae8 f610b8df 82153970 81e732c0 804efd6b
nt!IofCallDriver+0x3f (FPO:
[0,0,0])
WARNING: Stack unwind information not available.
Following frames may be
wrong.
f5f04ca8 f6106885 82167588 82153970 00000000
IvdIFS_G+0x68df f5f04cbc
804e0e0d 82167588 82153970 82153970 IvdIFS_G+0x1885
f5f04ccc 805759ea
81bd7e80 82153970 00000000 nt!IofCallDriver+0x3f (FPO:
[0,0,0])
f5f04ce0 805921b0 82167588 82153970 81bd7e80
nt!IopSynchronousServiceTail+0x6c
f5f04d54 804e7a8c 0000071c 0011cda4 00000000
nt!NtFlushBuffersFile+0x1b5
f5f04d54 7ffe0304 0000071c 0011cda4 00000000
nt!KiSystemService+0xcb
(FPO:
[0,0] TrapFrame @ f5f04d64)
0011cdac 00000000 00000000 00000000 00000000
SharedUserData!SystemCallStub+0x4 (FPO: [0,0,0])


Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17

You are currently subscribed to ntfsd as:
xxxxx@windows.microsoft.com
To unsubscribe send a blank email to
xxxxx@lists.osr.com


Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17

You are currently subscribed to ntfsd as:
xxxxx@t-online.de
To unsubscribe send a blank email to
xxxxx@lists.osr.com

Sorry, this information doesn’t support my idea from yesterday.

The mapped page writer should have released this resource before calling
KeDelayExecutionThread. There are two reasons I can see that would
explain why Mm did not drop the lock:

  1. When Mm called FsRtlAcquireFileForModWriteEx, a NULL pointer was
    returned in the ResourceToRelease output parameter. If there is no
    resource to release, Mm will not call FsRtlReleaseFileForModWrite.
  2. Mm called FsRtlReleaseFileForModWrite, but the release of the
    ERESOURCE didn’t actually occur.

Here are some ideas on where to go next –

  1. See if you can reproduce the problem if there are no filter drivers
    installed on the system.

  2. Verify that there is a non-NULL resource pointer returned in the
    ResourceToRelease parameter when FsRtlAcquireForModWriteEx is called and
    a successful status is returned.

  3. You said earlier than you don’t register for FastIO
    AcquireForModWrite or ReleaseForModWrite (which is the correct thing to
    do), but on Server 2003, the FsFilterCallbacks are present and a filter
    driver can hook these locking operations through that path. Do you
    register for any FsFilterCallbacks? Particularly, the
    PreReleaseForModifiedPageWriter – do you ever return an error status
    here? If so, make sure you don’t return an error code other than
    STATUS_INVALID_DEVICE_REQUEST.

  4. Are there any other filter drivers on the system that could be
    hooking the FsFilterCallback PreReleaseForModifiedPageWriter?

As to dumping the FSRTL_COMMON_FCB_HEADER, the following doesn’t work?

dt nt!_FSRTL_COMMON_FCB_HEADER 0xe1947740

I thought that this type was in the public kernel symbols since it is
defined in NTIFS.H. If not, if you use this type in your driver, you
could use your driver’s prefix for the type instead (if your drivers is
named mydriver.sys, use mydriver!_FSRTL_COMMON_FCB_HEADER).

Thanks,
Molly Brown
Microsoft Corporation

This posting is provided “AS IS” with no warranties and confers no
rights.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Lars Diehl
Sent: Wednesday, February 18, 2004 5:39 AM
To: Windows File Systems Devs Interest List
Subject: Re: [ntfsd] Deadlock during FlushFileBuffers, 2nd

Molly,

  1. No, it is not compressed
  2. The size values are:

Allocation size: 2484916224
File size: 2484916084
Valid data length: 2484916084

BTW, is there an easier way the get the contents of
FSRTL_COMMON_FCB_HEADER ?

Thanks,
Lars

dt _FILE_OBJECT 81bd7e80
+0x000 Type : 5
+0x002 Size : 112
+0x004 DeviceObject : 0x82167588
+0x008 Vpb : 0x82167690
+0x00c FsContext : 0xe1947740
+0x010 FsContext2 : 0xe1947888
+0x014 SectionObjectPointer : 0x81f98c1c
+0x018 PrivateCacheMap : 0x81f7f2e8
+0x01c FinalStatus : 0
+0x020 RelatedFileObject : (null)
+0x024 LockOperation : 0 ‘’
+0x025 DeletePending : 0 ‘’
+0x026 ReadAccess : 0 ‘’
+0x027 WriteAccess : 0x1 ‘’
+0x028 DeleteAccess : 0 ‘’
+0x029 SharedRead : 0 ‘’
+0x02a SharedWrite : 0 ‘’
+0x02b SharedDelete : 0 ‘’
+0x02c Flags : 0x43062
+0x030 FileName : _UNICODE_STRING “\large~test.mpg.itr”
+0x038 CurrentByteOffset : _LARGE_INTEGER 0x941ccf74
+0x040 Waiters : 0
+0x044 Busy : 1
+0x048 LastLock : (null)
+0x04c Lock : _KEVENT
+0x05c Event : _KEVENT
+0x06c CompletionContext : (null)

kd> dd 0xe1947740
e1947740 01480705 00020140 81e647c0 81edf258 e1947750 941cd000
00000000 941ccf74 00000000 e1947760 941ccf74 00000000 81f8f1b8 e194776c
e1947770 e194776c 00000000 e1947848 00000000 e1947780 e19476a8
e19476a8 e1947678 82102678 e1947790 00400a31 00000000 00000001 00000001
e19477a0 00000001 00000000 00000001 00000000 e19477b0 00000000
00000000 00000000 00000080

Molly Brown schrieb:

This is a long shot, but can you answer a couple questions for me –

  1. Is this file compressed?
  2. What are the file size and valid data length from the
    FSRTL_COMMON_FCB_HEADER for this file? (This header is at the
    beginning of the FsContext structure.)

Thanks,
Molly Brown
Microsoft Corporation

This posting is provided “AS IS” with no warranties and confers no
rights.

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Lars Diehl
Sent: Tuesday, February 17, 2004 3:05 AM
To: Windows File Systems Devs Interest List
Subject: [ntfsd] Deadlock during FlushFileBuffers, 2nd

Hi all,

currently I’m trying so solve a problem in our filterdriver. I already

posted this problem but I didn’t get any further. The sympthoms are as
follows:

When a large file is written through the “shadow device”, which is
provided by our filter driver, occationally the flush after the file
is completely written by BackupWrite() gets blocked. This suituation
happens very rarely with large files on W2k but on
Win2003 it is easily
reproudcible.

My interpretation is that the flush-thread currently waits exclusively

on resource 0x81edf258 and does not get it, since “mapped page writer”
still own it shared. It seems as the lazy writer and the explcit flush

are blocking erach other.

When looking at the PFN database, the file that is written shows the
following state:

Control Valid Standby Dirty Shared Locked PageTables name
8215f440 308 0 7040 0 1280 0
mapped_file(
~test.mpg.itr )

The control area looks as follows:
kd> !ca 8215f440

ControlArea @8215f440
Segment: e1874930 Flink 0 Blink
0
Section Ref 1 Pfn Ref 741 Mapped
Views 2
User Ref 0 WaitForDel 0 Flush
Count
0
File Object 81bd7e80 ModWriteCount 14 System
Views 2
Flags (8080) File WasPurged

File: \large~test.mpg.itr

Segment @ e1874930:
Type MAPPED_FILE_SEGMENT not found.

I would suspect this this mapping is a result of the file system
cache.
I’ve read the memory management section of Marc Russinovich’s “Inside
Win 2000”
but I couldn’t find an explanation of pages that are in state
“locked”.
Are these pages that are “currently” written to the file ?

As I stated ealier the filter attaches to NTFS drives only and does
not use AcquireForModWrite and ReleaseForModWrite handlers.

Thanks in advance for any help, comments or hints get a little further

in this problem.

Lars

kd> !locks -v 0x81edf258

Resource @ 0x81edf258 Shared 1 owning threads
Contention Count = 2
NumberOfSharedWaiters = 1
NumberOfExclusiveWaiters = 1
Threads: 822c3a58-93a1<*>

THREAD 822c3a58 Cid 0004.0078 Teb: 00000000
Win32Thread: 00000000
WAIT: (DelayExecution) KernelMode Non-Alertable
822c3ad0 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116984 Elapsed
Ticks: 1
Context Switch Count 111131
UserTime 00:00:00.0000
KernelTime 00:00:01.0171
Start Address nt!MiMappedPageWriter (0x805071e3)
Stack Init f892f000 Current f892ecd4 Base f892f000 Limit f892c000

Call 0
Priority 17 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr
f892ecec 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP 0xf892ed04]
[0,0,4])
f892ed04 804e4692 nt!KiSwapThread+0x85
f892ed38 8051f78f nt!KeDelayExecutionThread+0x183
f892ed78 805072fa nt!MiWriteComplete+0x3c3
f892edac 805f1828 nt!MiMappedPageWriter+0x150
f892eddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

822ad020-01

THREAD 822ad020 Cid 0004.0024 Teb: 00000000
Win32Thread: 00000000
WAIT: (WrResource) KernelMode Non-Alertable
82115408 Semaphore Limit 0x7fffffff
822ad098 NotificationTimer
Not impersonating
DeviceMap e10013b0
Owning Process 822af818
Wait Start TickCount 116838 Elapsed
Ticks: 147
Context Switch Count 1238
UserTime 00:00:00.0000
KernelTime 00:00:00.0000
Start Address nt!ExpWorkerThread (0x804ec50d)
Stack Init f88d7000 Current f88d6c30 Base f88d7000 Limit f88d4000

Call 0
Priority 13 BasePriority 13 PriorityDecrement 0
ChildEBP RetAddr
f88d6c48 804e4252 nt!KiSwapContext+0x25 (FPO: [EBP 0xf88d6c60]
[0,0,4])
f88d6c60 804e42c2 nt!KiSwapThread+0x85
f88d6c90 805212c8 nt!KeWaitForSingleObject+0x209
f88d6ccc 8050388a nt!ExpWaitForResource+0xd1
f88d6ce0 f829acec
nt!ExAcquireResourceSharedLite+0xaf
f88d6cec f82bf46b
Ntfs!NtfsAcquirePagingResourceShared+0x1d (FPO:
[3,0,0])
f88d6d08 804f1014
Ntfs!NtfsAcquireScbForLazyWrite+0x78
f88d6d40 804ed5e2 nt!CcWriteBehind+0x22
f88d6d80 804ec5c8 nt!CcWorkerThread+0x123
f88d6dac 805f1828 nt!ExpWorkerThread+0xe9
f88d6ddc 8050058e nt!PspSystemThreadStartup+0x2e
00000000 00000000 nt!KiThreadStartup+0x16

Threads Waiting On Exclusive Access:
81f65da0

kd> !thread 81f65da0
THREAD 81f65da0 Cid 0170.00c8 Teb: 7ffde000
Win32Thread: e184a008
WAIT:
(WrResource) KernelMode Non-Alertable
8218a6a8 SynchronizationEvent
81f65e18 NotificationTimer
Not impersonating
DeviceMap e164e0d0
Owning Process 81f53c00
Wait Start TickCount 116784 Elapsed Ticks:
201
Context Switch Count 558932
LargeStack
UserTime 00:00:03.0250
KernelTime 00:00:24.0046
Start Address 0x77e2f35f
Win32 Start Address 0x00405f10
Stack Init f5f05000 Current f5f04950 Base f5f05000 Limit
f5f01000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2
*** ERROR: Module load completed but symbols could not be
loaded for
IvdIFS_G.sys ChildEBP RetAddr Args to Child
f5f04968 804e4252 81f65da0 8218a6a8 00000000
nt!KiSwapContext+0x25 (FPO:
[EBP 0xf5f04980] [0,0,4])
f5f04980 804e42c2 81f65da0 81edf258 00000000
nt!KiSwapThread+0x85
f5f049b0 805212c8 8218a6a8 0000001b 00000000
nt!KeWaitForSingleObject+0x209 f5f049ec 804ef26b e1947678
82121a38
f5f04a74 nt!ExpWaitForResource+0xd1 f5f049fc f829acb8
81edf258 00000001
f82ca671 nt!ExAcquireResourceExclusiveLite+0x6c
f5f04a08 f82ca671 82121a38 e1947678 00000001
Ntfs!NtfsAcquirePagingResourceExclusive+0x1d (FPO:
[3,0,0])
f5f04a74 f82ca8ff 82121a38 82153970 82153970
Ntfs!NtfsCommonFlushBuffers+0x10d
f5f04ad8 804e0e0d 82102598 82153970 81e732c0
Ntfs!NtfsFsdFlushBuffers+0x92
f5f04ae8 f610b8df 82153970 81e732c0 804efd6b
nt!IofCallDriver+0x3f (FPO:
[0,0,0])
WARNING: Stack unwind information not available.
Following frames may be
wrong.
f5f04ca8 f6106885 82167588 82153970 00000000
IvdIFS_G+0x68df f5f04cbc
804e0e0d 82167588 82153970 82153970 IvdIFS_G+0x1885
f5f04ccc 805759ea
81bd7e80 82153970 00000000 nt!IofCallDriver+0x3f (FPO:
[0,0,0])
f5f04ce0 805921b0 82167588 82153970 81bd7e80
nt!IopSynchronousServiceTail+0x6c
f5f04d54 804e7a8c 0000071c 0011cda4 00000000
nt!NtFlushBuffersFile+0x1b5
f5f04d54 7ffe0304 0000071c 0011cda4 00000000
nt!KiSystemService+0xcb
(FPO:
[0,0] TrapFrame @ f5f04d64)
0011cdac 00000000 00000000 00000000 00000000
SharedUserData!SystemCallStub+0x4 (FPO: [0,0,0])


Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17

You are currently subscribed to ntfsd as:
xxxxx@windows.microsoft.com
To unsubscribe send a blank email to
xxxxx@lists.osr.com


Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17

You are currently subscribed to ntfsd as:
xxxxx@t-online.de
To unsubscribe send a blank email to
xxxxx@lists.osr.com


Questions? First check the IFS FAQ at
https://www.osronline.com/article.cfm?id=17

You are currently subscribed to ntfsd as: xxxxx@windows.microsoft.com
To unsubscribe send a blank email to xxxxx@lists.osr.com