I developped a minifilter,I find there is a strange problem,I have do a test:
In PostCreate,I will call FltCreateFile(…,FILE_READ_ATTRIBUTES|FILE_READ_DATA|SYNCHRONIZE,FILE_SHARE_READ|FILE_SHARE_WRITE|FILE_SHARE_DELETE,FILE_OPEN,…),and call FltClose;
When the original IRP_MJ_CREATE is for a RDR,and the os is vista,my fltclose will very slow.
I do a DbgPrint before FltCreateFile,after FltCreateFile,Before FltClose,and after FltClose.
the 1st,2nd and 3rd DbgPrint output is very fast appeared ,but the last DbgPrint output(after FltClose) appeared after 5 seconds.
That’s to say: the FltClose spend 5 senconds!!!
(I trace these DbgPrint output in DbgView).
I do a trace in SRV.it looks like the 5 seconds is spent for a FSCTL_REQUEST_OPLOCK_LEVEL2.
(after the FSCTL_REQUEST_OPLOCK_LEVEL2,is IRP_MJ_CLEANUP and IRP_MJ_CLOSE).
If I modified my fltcreatefile ,the desired access is modified to FILE_READ_ATTRIBUTES|SYNCHRONIZE,the problem disappeared.
(because it will not cause oplock behavior).
If the os is not vista,that’s OK.
But in my design,I must do a fltcreatefile with FILE_READ_DATA when the Instances is RDR.
everyone can clear it?and give me a suggestion?
That's very strange!
the RDR is WinXP,and the SRV is WinXP.everything is OK.
But RDR is vista,and the SRV is winXP,the fltclose is very slow.
I have traced the above two situation in SRV(WinXP).
The first situation(RDR is winXP) is the same with the second situation(RDR is vista).,except that FSCTL_REQUEST_OPLOCK_LEVEL_2 in 2nd situation is very slow.
the trace log by FileSpy in 1st situation(RDR is winXP,SRV is winXP):
Time sent Dur. Process IRP Request FileObject FO Flags Path Status More info
1 12:03:17.421 0 System 88EF7DE0 IRP_MJ_CREATE 89287398 00000000 F:\test\1.txt STATUS_SUCCESS FILE_OPEN CreOpts: 00200000 Access: 00000080 Share: 00000007 Attrib: 0 Result: FILE_OPENED
2 12:03:17.421 0 System 88EF7DE0 IRP_MJ_QUERY_INFORMATION 89287398 01040040 F:\test\1.txt STATUS_SUCCESS FileBasicInformation Attrib: 00000020
3 12:03:17.421 0 System 88EF7DE0 IRP_MJ_CLEANUP 89287398 01040040 F:\test\1.txt STATUS_SUCCESS
4 12:03:17.421 0 System 88EF7DE0 IRP_MJ_CLOSE 89287398 01044040 F:\test\1.txt STATUS_SUCCESS
5 12:03:17.421 0 System 88DE4DE0 IRP_MJ_CREATE 88F336D0 00000000 F:\test\1.txt STATUS_SUCCESS FILE_OPEN CreOpts: 00000140 Access: 00020089 Share: 00000001 Attrib: 00000080 Result: FILE_OPENED
6 12:03:17.421 0 System FASTIO_QUERY_NETWORK_OPEN_INFO 88F336D0 01040040 F:\test\1.txt STATUS_SUCCESS
7 12:03:17.421 0 System 88DE4DE0 IRP_MJ_QUERY_INFORMATION 88F336D0 01040040 F:\test\1.txt STATUS_SUCCESS FileEaInformation
8 12:03:17.421 0 System 88DE4DE0 IRP_MJ_QUERY_INFORMATION 88F336D0 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileStreamInformation
9 12:03:17.421 0 System 88DE4DE0 IRP_MJ_QUERY_INFORMATION 88F336D0 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileAttributeTagInformation
10 12:03:17.421 0 System 88DE4DE0 IRP_MJ_QUERY_SECURITY 88F336D0 01040040 F:\test\1.txt STATUS_INVALID_DEVICE_REQUEST
11 12:03:17.421 15 System 88FD1390 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 88F336D0 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_REQUEST_BATCH_OPLOCK
12 12:03:17.437 0 System 88EF7DE0 IRP_MJ_CREATE 89287398 00000000 F:\test\1.txt STATUS_OPLOCK_BREAK_IN_PROGRESS FILE_OPEN CreOpts: 00000140 Access: 00000081 Share: 00000007 Attrib: 00000080
13 12:03:17.437 0 System 88264978 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 89287398 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_OPLOCK_BREAK_NOTIFY
14 12:03:17.437 0 System 88DD4BA0 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 89287398 01040040 F:\test\1.txt STATUS_OPLOCK_NOT_GRANTED FSCTL_REQUEST_BATCH_OPLOCK
15 12:03:17.437 0 System FASTIO_QUERY_NETWORK_OPEN_INFO 89287398 01040040 F:\test\1.txt STATUS_SUCCESS
16 12:03:17.437 0 System 88DE4DE0 IRP_MJ_QUERY_INFORMATION 89287398 01040040 F:\test\1.txt STATUS_SUCCESS FileEaInformation
17 12:03:17.437 0 System 88DE4DE0 IRP_MJ_QUERY_INFORMATION 89287398 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileStreamInformation
18 12:03:17.437 0 System 88DE4DE0 IRP_MJ_QUERY_INFORMATION 89287398 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileAttributeTagInformation
19 12:03:17.437 0 System 88DE4DE0 IRP_MJ_QUERY_SECURITY 89287398 01040040 F:\test\1.txt STATUS_INVALID_DEVICE_REQUEST
20 12:03:17.437 0 System 88DD4BA0 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 89287398 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_REQUEST_OPLOCK_LEVEL_2
21 12:03:17.437 0 System 88EF7DE0 IRP_MJ_CLEANUP 89287398 01040040 F:\test\1.txt STATUS_SUCCESS
22 12:03:17.437 0 System 88EF7DE0 IRP_MJ_CLOSE 89287398 01044040 F:\test\1.txt STATUS_SUCCESS
the trace log by FileSpy in 2nd situation(RDR is vista,SRV is winXP):
Time sent Dur. Process IRP Request FileObject FO Flags Path Status More info
26 12:15:46.234 0 System 88CEA408 IRP_MJ_CREATE 88FDC2F0 00000000 F:\test\1.txt STATUS_SUCCESS FILE_OPEN CreOpts: 00200000 Access: 00000080 Share: 00000007 Attrib: 0 Result: FILE_OPENED
27 12:15:46.234 0 System 88CEA408 IRP_MJ_QUERY_INFORMATION 88FDC2F0 01040040 F:\test\1.txt STATUS_SUCCESS FileBasicInformation Attrib: 00000020
28 12:15:46.234 0 System 88CEA408 IRP_MJ_CLEANUP 88FDC2F0 01040040 F:\test\1.txt STATUS_SUCCESS
29 12:15:46.234 0 System 88CEA408 IRP_MJ_CLOSE 88FDC2F0 01044040 F:\test\1.txt STATUS_SUCCESS
30 12:15:46.234 0 System 88CEA408 IRP_MJ_CREATE 88FDC2F0 00000000 F:\test\1.txt STATUS_SUCCESS FILE_OPEN CreOpts: 00200000 Access: 00000080 Share: 00000007 Attrib: 0 Result: FILE_OPENED
31 12:15:46.234 0 System 88CEA408 IRP_MJ_QUERY_INFORMATION 88FDC2F0 01040040 F:\test\1.txt STATUS_SUCCESS FileStandardInformation AllocationSize: 00000000-00002000 EndOfFile: 00000000-00000012 NumberOfLinks: 1 DeletePending: 0
32 12:15:46.234 0 System 88CEA408 IRP_MJ_CLEANUP 88FDC2F0 01040040 F:\test\1.txt STATUS_SUCCESS
33 12:15:46.234 0 System 88CEA408 IRP_MJ_CLOSE 88FDC2F0 01044040 F:\test\1.txt STATUS_SUCCESS
34 12:15:46.250 0 System 88CEA408 IRP_MJ_CREATE 88D9ACD0 00000000 F:\test\1.txt STATUS_SUCCESS FILE_OPEN CreOpts: 00000140 Access: 00020089 Share: 00000001 Attrib: 00000080 Result: FILE_OPENED
35 12:15:46.250 0 System FASTIO_QUERY_NETWORK_OPEN_INFO 88D9ACD0 01040040 F:\test\1.txt STATUS_SUCCESS
36 12:15:46.250 0 System 88CEA408 IRP_MJ_QUERY_INFORMATION 88D9ACD0 01040040 F:\test\1.txt STATUS_SUCCESS FileEaInformation
37 12:15:46.250 0 System 88CEA408 IRP_MJ_QUERY_INFORMATION 88D9ACD0 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileStreamInformation
38 12:15:46.250 0 System 88CEA408 IRP_MJ_QUERY_INFORMATION 88D9ACD0 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileAttributeTagInformation
39 12:15:46.250 0 System 88CEA408 IRP_MJ_QUERY_SECURITY 88D9ACD0 01040040 F:\test\1.txt STATUS_INVALID_DEVICE_REQUEST
40 12:15:46.250 0 System 88FD5C40 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 88D9ACD0 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_REQUEST_BATCH_OPLOCK
41 12:15:46.250 0 System 88CEA408 IRP_MJ_CREATE 88C41EF8 00000000 F:\test\1.txt STATUS_OPLOCK_BREAK_IN_PROGRESS FILE_OPEN CreOpts: 00000140 Access: 00000081 Share: 00000007 Attrib: 00000080
42 12:15:46.250 15 System 89253978 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 88C41EF8 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_OPLOCK_BREAK_NOTIFY
43 12:15:46.265 0 System 88DCBA30 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 88C41EF8 01040040 F:\test\1.txt STATUS_OPLOCK_NOT_GRANTED FSCTL_REQUEST_BATCH_OPLOCK
44 12:15:46.265 0 System FASTIO_QUERY_NETWORK_OPEN_INFO 88C41EF8 01040040 F:\test\1.txt STATUS_SUCCESS
45 12:15:46.265 0 System 88E3D8C8 IRP_MJ_QUERY_INFORMATION 88C41EF8 01040040 F:\test\1.txt STATUS_SUCCESS FileEaInformation
46 12:15:46.265 0 System 88E3D8C8 IRP_MJ_QUERY_INFORMATION 88C41EF8 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileStreamInformation
47 12:15:46.265 0 System 88E3D8C8 IRP_MJ_QUERY_INFORMATION 88C41EF8 01040040 F:\test\1.txt STATUS_INVALID_PARAMETER FileAttributeTagInformation
48 12:15:46.265 0 System 88E3D8C8 IRP_MJ_QUERY_SECURITY 88C41EF8 01040040 F:\test\1.txt STATUS_INVALID_DEVICE_REQUEST
49 12:15:46.265 4921 System 88DCBA30 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUEST 88C41EF8 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_REQUEST_OPLOCK_LEVEL_2
50 12:15:51.187 0 System 88DB94B0 IRP_MJ_CLEANUP 88C41EF8 01040040 F:\test\1.txt STATUS_SUCCESS
51 12:15:51.187 0 System 88DB94B0 IRP_MJ_CLOSE 88C41EF8 01044040 F:\test\1.txt STATUS_SUCCESS
the item 20:(situation 1,RDR is winXP)
20 12:03:17.437 0 System 88DD4BA0 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_REQUE
ST 89287398 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_REQUEST_OPLOCK_LEVEL_2
the dur. is 0;
but in situation 2(RDR is vista),item 49:
49 12:15:46.265 4921 System 88DCBA30 IRP_MJ_FILE_SYSTEM_CONTROL/IRP_MN_USER_FS_RE
QUEST 88C41EF8 01040040 F:\test\1.txt STATUS_SUCCESS FSCTL_REQUEST_OPLOCK_LEVEL_2
the dur. is 4921(about 5 seconds).
others is all same!
I can't understand it.
anybody can clear it?Thanks!