Hang observed due to NTFS!NtfsAcquireFileForCcFlush

Pooja

Hi All,

We have minifilter file system driver and I am looking into hang and would appreciate if anyone can suggest.

As per !locks command
3: kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks...........

Resource @ 0xffff9b0507ba3a08 Shared 3 owning threads
Contention Count = 658
NumberOfSharedWaiters = 110
NumberOfExclusiveWaiters = 1
Threads: ffff9b051a911800-01<> ffff9b050e123080-01<> ffff9b051ae81800-01<> ffff9b050aa9a800-01
ffff9b050b3d8080-01 ffff9b0509963580-01 ffff9b0509a6a080-01 ffff9b05099a3080-01
ffff9b050c418080-01 ffff9b050975e080-01 ffff9b05146b8080-01 ffff9b0514313800-01
not complete here
ffff9b05090b0080-01<>

 Threads Waiting On Exclusive Access:
          ffff9b050b399080       

KD: Scanning for held locks...

Resource @ 0xffff9b0507ba23d8 Shared 1 owning threads
Threads: ffff9b050a5a8800-01<*>

Resource @ 0xffff9b0513743260 Exclusively owned
Contention Count = 9
Threads: ffff9b05088cf080-02<*>
KD: Scanning for held locks.

Resource @ 0xffff9b0513697ce0 Shared 1 owning threads
Threads: ffff9b05088cf080-01<*>
KD: Scanning for held

Resource @ 0xffff9b0517a5d9c0 Exclusively owned
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: ffff9b05088cf080-01<*>

 Threads Waiting On Exclusive Access:
          ffff9b051a911800       

Resource @ 0xffff9b0517a5da70 Shared 1 owning threads
Contention Count = 4
NumberOfExclusiveWaiters = 3
Threads:
Threads Waiting On Exclusive Access:
ffff9b05088cf080 ffff9b051ae81800 ffff9b050e123080

213644 total locks, 6 locks currently held
**
From this !locks command, my understanding is that Resource 0xffff9b0517a5da70 is already acquired by Thread ffff9b05088cf080 as shared and same Thread ffff9b05088cf080 is now going to acquire it exclusively and hang happens.**

it seems that NTFS!NtfsAcquireFileForCcFlush has already acquired Paging IO Resource as shared and now, it is going to acquire same paging resource exclusively and system hangs.

3: kd> dt eresource 0xffff9b0517a5da70
vmlfs!ERESOURCE
+0x000 SystemResourcesList : _LIST_ENTRY [ 0xffff9b0517999aa0 - 0xffff9b0517a5d9c0 ]
+0x010 OwnerTable : (null)
+0x018 ActiveCount : 0n1
+0x01a Flag : 0xf06
+0x01a ReservedLowFlags : 0x6 ''
+0x01b WaiterPriority : 0xf ''
+0x020 SharedWaiters : (null)
+0x028 ExclusiveWaiters : 0xffff9b05`17b28b10 Void
+0x030 OwnerEntry : _OWNER_ENTRY
+0x040 ActiveEntries : 1
+0x044 ContentionCount : 4
+0x048 NumberOfSharedWaiters : 0
+0x04c NumberOfExclusiveWaiters : 3
+0x050 Reserved2 : (null)
+0x058 Address : (null)
+0x058 CreatorBackTraceIndex : 0
+0x060 SpinLock : 0
3: kd> dx -r1 ((vmlfs!_OWNER_ENTRY *)0xffff9b0517a5daa0)
((vmlfs!_OWNER_ENTRY *)0xffff9b0517a5daa0) : 0xffff9b0517a5daa0 [Type: _OWNER_ENTRY *]
[+0x000] OwnerThread : 0xffff9b05088cf080 [Type: unsigned __int64]
[+0x008 ( 0: 0)] IoPriorityBoosted : 0x0 [Type: unsigned long]
[+0x008 ( 1: 1)] OwnerReferenced : 0x0 [Type: unsigned long]
[+0x008 ( 2: 2)] IoQoSPriorityBoosted : 0x1 [Type: unsigned long]
[+0x008 (31: 3)] OwnerCount : 0x1 [Type: unsigned long]
[+0x008] TableSize : 0xc [Type: unsigned long]

3: kd> !thread ffff9b05088cf080
THREAD ffff9b05088cf080 Cid 0324.08b4 Teb: 0000007f91741000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
ffff9b0517b28b10 SynchronizationEvent
Impersonation token: ffffc1015b39f270 (Level Impersonation)
DeviceMap ffffc10152c2a0b0
Owning Process ffff9b0508d9b080 Image: services.exe
Attached Process N/A Image: N/A
Wait Start TickCount 535774 Ticks: 128 (0:00:00:02.000)
Context Switch Count 162965 IdealProcessor: 0
UserTime 00:00:03.687
KernelTime 00:00:25.203
Win32 Start Address 0x00007ffe5b9ce3f0
Stack Init ffff84002e508c90 Current ffff84002e507140
Base ffff84002e509000 Limit ffff84002e503000 Call 0000000000000000
Priority 15 BasePriority 9 PriorityDecrement 96 IoPriority 2 PagePriority 5
Child-SP RetAddr : Args to Child : Call Site
ffff84002e507180 fffff803654de1fd : ffff9b0500000000 0000000000000000 fffff803657c4980 fffff80300000000 : nt!KiSwapContext+0x76
ffff84002e5072c0 fffff803654ddc9f : ffff9b05088cf080 ffff9b05088cf180 ffff9b0508d6e080 ffff840000000000 : nt!KiSwapThread+0x17d
ffff84002e507370 fffff803654dff58 : 0000000000000000 ffff9b0517a5da70 000000000000000b ffff9b05088cf080 : nt!KiCommitThreadWait+0x14f
ffff84002e507410 fffff8036550ee47 : ffff9b0517a5da70 ffff9b0517b28b10 0000000000000300 ffff84002e5075c0 : nt!ExpWaitForResource+0x2a8
ffff84002e5074e0 fffff80a65944ae2 : ffffc1015d4129c0 ffff84002e507690 fffff80a659a89a0 ffff9b0506ac1880 : nt!ExAcquireResourceExclusiveLite+0x217
ffff84002e507560 fffff80365866605 : 0000000000000000 0000000000000000 ffff84002e507690 0000000000000000 : NTFS!NtfsAcquireFileForCcFlush+0xe2
ffff84002e507590 fffff803654a8c32 : ffff84002e5078b0 ffff84002e507920 0000000000000000 ffff9b050d5ee670 : nt!FsRtlAcquireFileForCcFlushEx+0x15d
ffff84002e507840 fffff8036547be41 : 0000000000000000 ffff9b05088cf080 0000000000000000 0000000000000000 : nt!MmFlushSection+0x9e
ffff84002e5078f0 fffff803658c837e : 0000000000000c00 0000000000000c02 0000000000000000 0000000000000000 : nt!MiFlushDataSection+0x81
ffff84002e507940 fffff803658c9908 : ffff9b050d5ee670 0000000000000000 ffff84002e507be9 0000000000000000 : nt!MiCreateImageFileMap+0x14e
ffff84002e507af0 fffff803658d1d92 : 0000000000000c02 ffff84002e507d30 ffffffffffffffff ffff9b050d5ee670 : nt!MiCreateNewSection+0x1ec
ffff84002e507c20 fffff803658c36e1 : ffff84002e507e68 ffff84002e507fb8 0000000000000001 ffff84002e507e60 : nt!MiCreateSection+0x562
ffff84002e507e00 fffff803658c06a9 : 0000000000000000 ffff84002e508b80 0000000000000000 ffff840000000000 : nt!MmCreateSpecialImageSection+0xb9
ffff84002e507eb0 fffff80365573d03 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!NtCreateUserProcess+0x4dd
ffff84002e508a90 00007ffe5ba57424 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffff84002e508b00) 0000007f9267d848 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : 0x00007ffe5ba57424

**Now, I am trying to understand why NtfsAcquireFileForCcFlush is again going to acquire same lock exclusively without releasing it before??? is It NTFS issue??

I tried to understand assembly of NtfsAcquireFileForCcFlush and looks like **

rbx has FSCONTEXT**(0xffffc101`5d4129c0) **value from !fileobj

3: kd> dt file_object 0xffff9b05148e2090** vmlfs!FILE_OBJECT +0x000 Type : 0n5 +0x002 Size : 0n216 +0x008 DeviceObject : 0xffff9b0506c0b8a0 _DEVICE_OBJECT
+0x010 Vpb : 0xffff9b0506c0d850 _VPB ** +0x018 FsContext : 0xffffc1015d4129c0 Void
+0x020 FsContext2 : 0xffffc1015d412c08 Void +0x028 SectionObjectPointer : 0xffff9b0517a5da38 _SECTION_OBJECT_POINTERS
+0x030 PrivateCacheMap : (null)
+0x038 FinalStatus : 0n0
+0x040 RelatedFileObject : (null)
+0x048 LockOperation : 0 ''
+0x049 DeletePending : 0 ''
+0x04a ReadAccess : 0x1 ''
+0x04b WriteAccess : 0 ''
+0x04c DeleteAccess : 0 ''
+0x04d SharedRead : 0x1 ''
+0x04e SharedWrite : 0x1 ''
+0x04f SharedDelete : 0x1 ''
+0x050 Flags : 0x4000a
+0x058 FileName : _UNICODE_STRING "\ZIM\InputAccel\Client\binnt\QuickModuleHost.exe"
+0x068 CurrentByteOffset : _LARGE_INTEGER 0x0
+0x070 Waiters : 0
+0x074 Busy : 0
+0x078 LastLock : (null)
+0x080 Lock : _KEVENT
+0x098 Event : _KEVENT
+0x0b0 CompletionContext : (null)
+0x0b8 IrpListLock : 0
+0x0c0 IrpList : _LIST_ENTRY [ 0xffff9b05148e2150 - 0xffff9b05148e2150 ]
+0x0d0 FileObjectExtension : 0xffff9b05`0d21fa70 Void

2. mov rcx,qword ptr [rbx+0A8h] => This value store value at address [0xffffc101`5d4129c0+0A8h= FFFF C101 5D41 2A68] in rcx.
   rcx= ffffc1015d412880

3. mov eax,dword ptr [rcx+4]
   and eax,20020100h
   cmp eax,20000000h

ffffc101`5d412880 02 07 38 01 48 0a 00 20

eax will be 20000A48h **
**After and and cmp will be 20000000h
and this makes je NTFS!NtfsAcquireFileForCcFlush+0xd7 (fffff80a`65944ad7) => This makes control goes to NtfsAcquirePagingResourceExclusive

Now, what is this value 20000A48h which is forcing NTFS to take this code route to acquire tis paging resource exclusively.

Thanks for your help in advance.

rod_widdowson

What (if anything) are you doing in process create? Or the pseudo-IRP_MJ calls (create section, acquire for flush in particular.)

Also are you doing anything strange with the advanced fcb header?

Pooja

We have complete minifilter driver architecture, so we create FCB,CCB,SCB for FO above us.
I am looking for actual flag meaning in NTFS code which is causing this hang.