Hi all,
In the process of trying to debug a filter driver, I have run into some
behavior that I truely do not understand. It is probably something stupid,
but I am hoping someone can shed some light on this. I am finding that when
I create a file and then write to it (using buffered I/O), sometimes, but
not always, the buffered writes generated by the CacheManager go to a
DIFFERENT FILEOBJECT than the original Create and Write. I can’t find that
the FileObject in question has ever been Created. Below is an example:
I am confused as to where this extra FileObject is coming from. The presence
of this additional FileObject, is greatly confusing my filter driver. The
initial (buffered) write goes to the FileObject as expected, but the paging
writes to support it go to an entirely different FileObject. What is
happening here??
Thanks for any help,
Don
I am running the FileSpy app as shipped with the IFS Kit.
First I create a file, FileHandle = 864BD778
I 00000D68 13:12:28:447 13:12:28:447 c04.668 IRP_MJ_CREATE
85DEFD60 864BD778 00000000:00000002 40000884 --S- e:\test\test.file
Then I write to it (buffered):
I 00000D6F 13:12:32:244 13:12:32:479 c04.668 IRP_MJ_WRITE
IRP_MN_NORMAL 85DEFD60 864BD778 00000000:00400000 40000a00 ----
e:\test\test.file
This of course generates lots of paging writes, some of which are as
follows. but the paging I/O is to fileObject 860ABDE8, not 864BD778. There
are 64 paging writes, which is the correct number to account for the initial
4 MByte buffered I/O.
O 00000D70 13:12:32:244 13:12:32:244 c04.668 ACQUIRE_FOR_CC_FLUSH
85DEFD60 860ABDE8 00000000 e:[-=Nested Operation=-]
I 00000D71 13:12:32:244 13:12:32:244 c04.668 IRP_MJ_WRITE
IRP_MN_NORMAL 85DEFD60 860ABDE8 00000000:00010000 40000043 NP-Y
e:[-=Not In Cache=-]
I 00000D72 13:12:32:244 13:12:32:244 c04.668 IRP_MJ_WRITE
IRP_MN_NORMAL 85DEFD60 860ABDE8 00000000:00010000 40000043 NP-Y
e:[-=Not In Cache=-]
I 00000D73 13:12:32:244 13:12:32:244 c04.668 IRP_MJ_WRITE
IRP_MN_NORMAL 85DEFD60 860ABDE8 00000000:00010000 40000043 NP-Y
e:[-=Not In Cache=-]
I 00000D74 13:12:32:244 13:12:32:244 c04.668 IRP_MJ_WRITE
IRP_MN_NORMAL 85DEFD60 860ABDE8 00000000:00010000 40000043 NP-Y
e:[-=Not In Cache=-]
O 00000D75 13:12:32:244 13:12:32:244 c04.668 RELEASE_FOR_CC_FLUSH
85DEFD60 860ABDE8 00000000 e:[-=Not In Cache=-]
After a lot more paging writes, the file is cleaned up and closed.
I 00000DD7 13:12:36:244 13:12:36:260 c04.668 IRP_MJ_CLEANUP
85DEFD60 864BD778 00000000:00000000 40000404 --S- e:\test\test.file
I 00000DF4 13:12:36:260 13:12:36:260 c04.668 IRP_MJ_CLOSE
85DEFD60 864BD778 00000000:00000000 40000404 --S- e:\test\test.file
When I look at the same operation using FileMon from SysInternals, I see the
following:
Here, the file is opened
100 1:33:49 PM AfapTester.exe:3076 IRP_MJ_CREATE E:\test\test3.file SUCCESS
Options: OpenIf Access: All
Here is the initial write
105 1:33:54 PM AfapTester.exe:3076 IRP_MJ_WRITE E:\test\test3.file SUCCESS
Offset: 0 Length: 4194304
Here are some of the Paging writes, again to a different file
($ConvertToNonresident)
106 1:33:54 PM AfapTester.exe:3076 IRP_MJ_WRITE* E:$ConvertToNonresident
SUCCESS Offset: 0 Length: 65536
107 1:33:54 PM AfapTester.exe:3076 IRP_MJ_WRITE* E:$ConvertToNonresident
SUCCESS Offset: 65536 Length: 65536
108 1:33:54 PM AfapTester.exe:3076 IRP_MJ_WRITE* E:$ConvertToNonresident
SUCCESS Offset: 131072 Length: 65536
109 1:33:54 PM AfapTester.exe:3076 IRP_MJ_WRITE* E:$ConvertToNonresident
SUCCESS Offset: 196608 Length: 65536
Finally the file is cleaned up and closed:
177 1:34:00 PM AfapTester.exe:3076 IRP_MJ_CLEANUP E:\test\test3.file SUCCESS
206 1:34:00 PM AfapTester.exe:3076 IRP_MJ_CLOSE E:\test\test3.file SUCCESS