Jump-start your project by learning from devs who
write Windows drivers and file systems every day.
Take an OSR seminar!

OSR is Hiring! Click here to find out more.

Upcoming OSR Seminars:
Kernel Debugging & Crash Analysis Lab, Dulles/Sterling, VA 24-28 March, 2014
Writing WDF Drivers for Windows Lab, Palo Alto, CA 28 April-2 May, 2014
Advanced WDF Driver Lab, Palo Alto, CA 5-8 May, 2014
Developing File Systems for Windows, Boston/Waltham, MA 13-16 May, 2014
Windows Internals & Software Drivers Lab, Dulles/Sterling, VA, CA 23-27 June, 2014


Go Back   OSR Online Lists > ntfsd
Welcome, Guest
You must login to post to this list
  Message 1 of 4  
01 Feb 13 09:17
Amritanshu Johri
xxxxxx@gmail.com
Join Date: 05 Jul 2012
Posts To This List: 47
thread stuck on NTFS write: Windows 7 64 bit

Hello ntfsd, We have a legacy filter driver that keeps track of changes happening on files for a volume. It writes things back to a log file especially when a file handle is closed. We are observing an occasional hang in the system, it happens when a new file has been created, here is how it looks. # Child-SP RetAddr Call Site 01 fffff880`0919ed50 fffff800`036e5d8f nt!KiCommitThreadWait+0x1d2 02 fffff880`0919ede0 fffff880`0165850a nt!KeWaitForSingleObject+0x19f <-- (stuck for a wait here) 03 fffff880`0919ee80 fffff880`01002bcf Ntfs!NtfsFsdWrite+0x26a 04 fffff880`0919ef40 fffff880`010016df fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x24f 05 fffff880`0919efd0 fffff880`01247b0b fltmgr!FltpDispatch+0xcf 06 fffff880`0919f030 fffff880`01248852 mfl!call_driver_with_sync+0xdb <-- (We create our own Write IRP and send it down.) ... internal bookkeeping done in these frames ... 12 fffff880`0919f600 fffff880`012686c2 mfl!event_handle+0x96 13 fffff880`0919f670 fffff880`0127309c mfl!hook_cleanup_cmpl+0x122 14 fffff880`0919f6d0 fffff880`012314b9 mfl!fs_hook_cleanup_cmpl+0x3c ... More internal book keeping ... 1a fffff880`0919f8b0 fffff800`039e25ef mfl!fs_flt_cleanup+0x89 <-- (we see a cleanup IRP) 1b fffff880`0919f8f0 fffff800`039d1d14 nt!IopCloseFile+0x11f 1c fffff880`0919f980 fffff800`039d1ad1 nt!ObpDecrementHandleCount+0xb4 1d fffff880`0919fa00 fffff800`039d2094 nt!ObpCloseHandleTableEntry+0xb1 1e fffff880`0919fa90 fffff800`036de253 nt!ObpCloseHandle+0x94 1f fffff880`0919fae0 00000000`77b4140a nt!KiSystemServiceCopyEnd+0x13 20 00000000`0008e318 00000000`00000000 0x77b4140a IRP that is stuck: 0: kd> !irp 0xfffffa80`074f5bd0 Irp is active with 11 stacks 10 is current (= 0xfffffa80074f5f28) Mdl=fffffa800d996bf0: No System Buffer: Thread fffffa800bdf2b50: Irp stack trace. cmd flg cl Device File Completion-Context [ 0, 0] 0 0 00000000 00000000 00000000-00000000 ... skipped empty stack locations for brevity Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 >[ 4, 0] 0 e0 fffffa80098dc030 fffffa800c731a10 fffff88001005e40-fffffa800e0e6cb0 Success Error Cancel \FileSystem\Ntfs fltmgr!FltpPassThroughCompletion Args: 00000004 00000000 0000027e 00000000 [ 4, 0] 0 e1 fffffa8009654de0 fffffa800c731a10 fffff88001247b60-fffffa800c8cead0 Success Error Cancel pending \FileSystem\FltMgr mfl!completion_routine Args: 00000004 00000000 ffffffffffffffff 00000000 The associated file object 0: kd> !fileobj fffffa800c731a10 \sc\sclog Device Object: 0xfffffa800961cb10 \Driver\volmgr Vpb: 0xfffffa800961ca50 Event signalled Access: Write SharedRead SharedWrite SharedDelete Flags: 0x40042 Synchronous IO Cache Supported Handle Created FsContext: 0xfffff8a01c114c70 FsContext2: 0xfffff8a017bc1b40 CurrentByteOffset: 0 Cache Data: Section Object Pointers: fffffa800b9050c8 Shared Cache Map: 00000000 I tried to make a guess about what is going on by disassembling bits but couldn't find much, here is a pieced up block of what code was executed Ntfs!NtfsFsdWrite+0x164: fffff880`01658404 81a330010000fffbffff and dword ptr [rbx+130h],0FFFFFBFFh fffff880`0165840e 8b8330010000 mov eax,dword ptr [rbx+130h] fffff880`01658414 098334010000 or dword ptr [rbx+134h],eax fffff880`0165841a 488b4620 mov rax,qword ptr [rsi+20h] fffff880`0165841e 48894340 mov qword ptr [rbx+40h],rax Ntfs!NtfsFsdWrite+0x182: fffff880`01658422 4584ff test r15b,r15b fffff880`01658425 7546 jne Ntfs!NtfsFsdWrite+0x1cd (fffff880`0165846d) Ntfs!NtfsFsdWrite+0x187: fffff880`01658427 81ff880100c0 cmp edi,0C0000188h <-- this is false fffff880`0165842d 0f8499000000 je Ntfs!NtfsFsdWrite+0x22c (fffff880`016584cc) Ntfs!NtfsFsdWrite+0x193: fffff880`01658433 81ff67030000 cmp edi,367h fffff880`01658439 0f849a000000 je Ntfs!NtfsFsdWrite+0x239 (fffff880`016584d9) Ntfs!NtfsFsdWrite+0x239: fffff880`016584d9 498b8c24b8000000 mov rcx,qword ptr [r12+0B8h] fffff880`016584e1 0fb64103 movzx eax,byte ptr [rcx+3] fffff880`016584e5 83e0fe and eax,0FFFFFFFEh fffff880`016584e8 884103 mov byte ptr [rcx+3],al fffff880`016584eb 488b4b78 mov rcx,qword ptr [rbx+78h] fffff880`016584ef 4883c108 add rcx,8 fffff880`016584f3 48c744242000000000 mov qword ptr [rsp+20h],0 fffff880`016584fc 4533c9 xor r9d,r9d fffff880`016584ff 4533c0 xor r8d,r8d fffff880`01658502 33d2 xor edx,edx fffff880`01658504 ff153ee70200 call qword ptr [Ntfs!_imp_KeWaitForSingleObject (fffff880`01686c48)] <-- we are waiting here ________________________________________________________________________ fffff880`0165850a 894504 mov dword ptr [rbp+4],eax fffff880`0165850d 48837b7800 cmp qword ptr [rbx+78h],0 fffff880`01658512 7422 je Ntfs!NtfsFsdWrite+0x296 (fffff880`01658536) Do let me know if anyone knows anything about it. or how to go about root causing this. TIA, Johri
  Message 2 of 4  
01 Feb 13 10:27
Scott Noone
xxxxxx@osr.com
Join Date: 10 Jul 2002
Posts To This List: 666
List Moderator
Re: thread stuck on NTFS write: Windows 7 64 bit

"Amritanshu" wrote in message news:95657@ntfsd... >Ntfs!NtfsFsdWrite+0x187: >cmp edi,0C0000188h <-- this is false >je Ntfs!NtfsFsdWrite+0x22c >Ntfs!NtfsFsdWrite+0x193: >cmp edi,367h >je Ntfs!NtfsFsdWrite+0x239 Assuming that EDI contains an NTSTATUS value: E:\>winerror -s C0000188 1502 ERROR_LOG_FILE_FULL <--> c0000188 STATUS_LOG_FILE_FULL E:\>winerror -s 367 765 ERROR_WAIT_FOR_OPLOCK <--> 00000367 STATUS_WAIT_FOR_OPLOCK So, seems like NTFS waiting for an oplock break. Any other threads out there stuck in your driver or NTFS? ("!stacks 2 mfl!", "!stacks 2 ntfs!"). It's also possible that the cleanup you're currently blocking is the one that needs to trigger the oplock break. -scott OSR Hello ntfsd, We have a legacy filter driver that keeps track of changes happening on files for a volume. It writes things back to a log file especially when a file handle is closed. We are observing an occasional hang in the system, it happens when a new file has been created, here is how it looks. # Child-SP RetAddr Call Site 01 fffff880`0919ed50 fffff800`036e5d8f nt!KiCommitThreadWait+0x1d2 02 fffff880`0919ede0 fffff880`0165850a nt!KeWaitForSingleObject+0x19f <-- (stuck for a wait here) 03 fffff880`0919ee80 fffff880`01002bcf Ntfs!NtfsFsdWrite+0x26a 04 fffff880`0919ef40 fffff880`010016df fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x24f 05 fffff880`0919efd0 fffff880`01247b0b fltmgr!FltpDispatch+0xcf 06 fffff880`0919f030 fffff880`01248852 mfl!call_driver_with_sync+0xdb <-- (We create our own Write IRP and send it down.) ... internal bookkeeping done in these frames ... 12 fffff880`0919f600 fffff880`012686c2 mfl!event_handle+0x96 13 fffff880`0919f670 fffff880`0127309c mfl!hook_cleanup_cmpl+0x122 14 fffff880`0919f6d0 fffff880`012314b9 mfl!fs_hook_cleanup_cmpl+0x3c ... More internal book keeping ... 1a fffff880`0919f8b0 fffff800`039e25ef mfl!fs_flt_cleanup+0x89 <-- (we see a cleanup IRP) 1b fffff880`0919f8f0 fffff800`039d1d14 nt!IopCloseFile+0x11f 1c fffff880`0919f980 fffff800`039d1ad1 nt!ObpDecrementHandleCount+0xb4 1d fffff880`0919fa00 fffff800`039d2094 nt!ObpCloseHandleTableEntry+0xb1 1e fffff880`0919fa90 fffff800`036de253 nt!ObpCloseHandle+0x94 1f fffff880`0919fae0 00000000`77b4140a nt!KiSystemServiceCopyEnd+0x13 20 00000000`0008e318 00000000`00000000 0x77b4140a IRP that is stuck: 0: kd> !irp 0xfffffa80`074f5bd0 Irp is active with 11 stacks 10 is current (= 0xfffffa80074f5f28) Mdl=fffffa800d996bf0: No System Buffer: Thread fffffa800bdf2b50: Irp stack trace. cmd flg cl Device File Completion-Context [ 0, 0] 0 0 00000000 00000000 00000000-00000000 ... skipped empty stack locations for brevity Args: 00000000 00000000 00000000 00000000 [ 0, 0] 0 0 00000000 00000000 00000000-00000000 Args: 00000000 00000000 00000000 00000000 >[ 4, 0] 0 e0 fffffa80098dc030 fffffa800c731a10 >fffff88001005e40-fffffa800e0e6cb0 Success Error Cancel \FileSystem\Ntfs fltmgr!FltpPassThroughCompletion Args: 00000004 00000000 0000027e 00000000 [ 4, 0] 0 e1 fffffa8009654de0 fffffa800c731a10 fffff88001247b60-fffffa800c8cead0 Success Error Cancel pending \FileSystem\FltMgr mfl!completion_routine Args: 00000004 00000000 ffffffffffffffff 00000000 The associated file object 0: kd> !fileobj fffffa800c731a10 \sc\sclog Device Object: 0xfffffa800961cb10 \Driver\volmgr Vpb: 0xfffffa800961ca50 Event signalled Access: Write SharedRead SharedWrite SharedDelete Flags: 0x40042 Synchronous IO Cache Supported Handle Created FsContext: 0xfffff8a01c114c70 FsContext2: 0xfffff8a017bc1b40 CurrentByteOffset: 0 Cache Data: Section Object Pointers: fffffa800b9050c8 Shared Cache Map: 00000000 I tried to make a guess about what is going on by disassembling bits but couldn't find much, here is a pieced up block of what code was executed Ntfs!NtfsFsdWrite+0x164: fffff880`01658404 81a330010000fffbffff and dword ptr [rbx+130h],0FFFFFBFFh fffff880`0165840e 8b8330010000 mov eax,dword ptr [rbx+130h] fffff880`01658414 098334010000 or dword ptr [rbx+134h],eax fffff880`0165841a 488b4620 mov rax,qword ptr [rsi+20h] fffff880`0165841e 48894340 mov qword ptr [rbx+40h],rax Ntfs!NtfsFsdWrite+0x182: fffff880`01658422 4584ff test r15b,r15b fffff880`01658425 7546 jne Ntfs!NtfsFsdWrite+0x1cd (fffff880`0165846d) Ntfs!NtfsFsdWrite+0x187: fffff880`01658427 81ff880100c0 cmp edi,0C0000188h <-- this is false fffff880`0165842d 0f8499000000 je Ntfs!NtfsFsdWrite+0x22c (fffff880`016584cc) Ntfs!NtfsFsdWrite+0x193: fffff880`01658433 81ff67030000 cmp edi,367h fffff880`01658439 0f849a000000 je Ntfs!NtfsFsdWrite+0x239 (fffff880`016584d9) Ntfs!NtfsFsdWrite+0x239: fffff880`016584d9 498b8c24b8000000 mov rcx,qword ptr [r12+0B8h] fffff880`016584e1 0fb64103 movzx eax,byte ptr [rcx+3] fffff880`016584e5 83e0fe and eax,0FFFFFFFEh fffff880`016584e8 884103 mov byte ptr [rcx+3],al fffff880`016584eb 488b4b78 mov rcx,qword ptr [rbx+78h] fffff880`016584ef 4883c108 add rcx,8 fffff880`016584f3 48c744242000000000 mov qword ptr [rsp+20h],0 fffff880`016584fc 4533c9 xor r9d,r9d fffff880`016584ff 4533c0 xor r8d,r8d fffff880`01658502 33d2 xor edx,edx fffff880`01658504 ff153ee70200 call qword ptr [Ntfs!_imp_KeWaitForSingleObject (fffff880`01686c48)] <-- we are waiting here ________________________________________________________________________ fffff880`0165850a 894504 mov dword ptr [rbp+4],eax fffff880`0165850d 48837b7800 cmp qword ptr [rbx+78h],0 fffff880`01658512 7422 je Ntfs!NtfsFsdWrite+0x296 (fffff880`01658536) Do let me know if anyone knows anything about it. or how to go about root causing this. TIA, Johri
  Message 3 of 4  
11 Feb 13 05:46
Amritanshu Johri
xxxxxx@gmail.com
Join Date: 05 Jul 2012
Posts To This List: 47
Re: thread stuck on NTFS write: Windows 7 64 bit

Hi Scott, Thank you for helping out on this one. You were right, there was another operation happening on the file that was resulting in a create 'collision'. Based on our logging in one instance that create was waiting for the OPLOCK break, in most instances the create had just completed so no ntfs stack was around, But in all cases the original thread was stuck on IO in the same path. On further analysis it was found that in certain condition a return status of STATUS_OPLOCK_BREAK_IN_PROGRESS during create was not resulting FSCTL_NOTIFY_BREAK being issued and the driver was going ahead. Perhaps this was locking up things. Do let me know if it doesn't makes sense. Thanks a ton. Regards, Johri
  Message 4 of 4  
11 Feb 13 11:36
Scott Noone
xxxxxx@osr.com
Join Date: 10 Jul 2002
Posts To This List: 666
List Moderator
Re: thread stuck on NTFS write: Windows 7 64 bit

"Amritanshu" wrote in message news:95698@ntfsd... >On further analysis it was found that in certain condition a return >status of STATUS_OPLOCK_BREAK_IN_PROGRESS during create was not >resulting FSCTL_NOTIFY_BREAK being issued and the driver was going >ahead. Perhaps this was locking up things. Do you mean that you were not specifically handling a return of STATUS_OPLOCK_BREAK_IN_PROGRESS from an open with FILE_COMPLETE_IF_OPLOCKED set? That could certainly be problematic. -scott OSR "Amritanshu" wrote in message news:95698@ntfsd... Hi Scott, Thank you for helping out on this one. You were right, there was another operation happening on the file that was resulting in a create 'collision'. Based on our logging in one instance that create was waiting for the OPLOCK break, in most instances the create had just completed so no ntfs stack was around, But in all cases the original thread was stuck on IO in the same path. On further analysis it was found that in certain condition a return status of STATUS_OPLOCK_BREAK_IN_PROGRESS during create was not resulting FSCTL_NOTIFY_BREAK being issued and the driver was going ahead. Perhaps this was locking up things. Do let me know if it doesn't makes sense. Thanks a ton. Regards, Johri
Posting Rules  
You may not post new threads
You may not post replies
You may not post attachments
You must login to OSR Online AND be a member of the ntfsd list to be able to post.

All times are GMT -5. The time now is 08:53.


Copyright ©2014, OSR Open Systems Resources, Inc.
Based on vBulletin Copyright ©2000 - 2005, Jelsoft Enterprises Ltd.
Modified under license