Recently, my vista system frozen when accessing certain virtual volume.
After analyzing full memory dump, it seems that the problem may related to NTFS driver, specificallyTransactional NTFS (TxF).
0: kd> !locks 85205ec8
Resource @ 0x85205ec8 Exclusively owned
Contention Count = 7
NumberOfExclusiveWaiters = 7
Threads: 88b9fcb0-01<*>
Threads Waiting On Exclusive Access:
850bbd78 89b2b3f0 89754030 84753d78 <<< remember ME
84e92b78 853cf760 89b44578
0: kd> !THREAD 84753d78
THREAD 84753d78 Cid 0004.0028 Teb: 00000000 Win32Thread: 00000000 WAIT:
(WrResource) KernelMode Non-Alertable
88bee2e8 SynchronizationEvent
84753e00 NotificationTimer
IRP List:
8897fb38: (0006,0220) Flags: 00000884 Mdl: 00000000
b4657418: (0006,0220) Flags: 00000404 Mdl: 00000000
Not impersonating
DeviceMap 8ae08800
Owning Process 84726c10 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 198074 Ticks: 100 (0:00:00:01.560)
Context Switch Count 178261
UserTime 00:00:00.000
KernelTime 00:00:31.309
Win32 Start Address nt!ExpWorkerThread (0x820f4d25)
Stack Init 8b150000 Current 8b14f260 Base 8b150000 Limit 8b14d000 Call 0
Priority 14 BasePriority 13 PriorityDecrement 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr Args to Child
8b14f278 820fb352 84753d78 84753e00 82147e90 nt!KiSwapContext+0x26 (FPO: [Uses
EBP] [0,0,4])
8b14f2bc 82096f28 84753d78 85205ec8 84753d78 nt!KiSwapThread+0x44f
8b14f314 820ff9b9 88bee2e8 0000001b 00000000 nt!KeWaitForSingleObject+0x492
8b14f34c 820fcebf 88bee2e8 00000000 820fff69 nt!ExpWaitForResource+0xbd
8b14f374 82706427 85205ec8 00000001 097bcbf9 nt!
ExAcquireResourceExclusiveLite+0x96
8b14f3c0 826fb5a7 85205b78 895372d8 89537220 fltmgr!
FltpDoFilterNotificationForNewVolume+0x3d (FPO: [Non-Fpo])
8b14f404 820939c6 866a3ac8 85205b78 8897fb38 fltmgr!FltpCreate+0x205 (FPO: [Non-
Fpo])
8b14f41c b4f87063 b4657428 89537220 8897fb38 nt!IofCallDriver+0x63
WARNING: Stack unwind information not available. Following frames may be wrong.
8b14f4c8 b4f871c9 89537220 8897fb38 8b14f4f0 SeedSpy+0x1063
8b14f4d8 820939c6 89537220 8897fb38 b461afdc SeedSpy+0x11c9
8b14f4f0 8228e195 7000f906 84dc2dc4 86331d18 nt!IofCallDriver+0x63
8b14f5c0 8227c5e1 86331d30 00000000 84dc2d20 nt!IopParseDevice+0xf61
8b14f650 82289b62 00000000 8b14f6a8 00000040 nt!ObpLookupObjectName+0x5a8
8b14f6b4 8228f29c 8b14f858 00000000 00000000 nt!ObOpenObjectByName+0x13c
8b14f728 82290e4d 8b14f880 00100000 8b14f858 nt!IopCreateFile+0x63b
8b14f774 82099c7a 8b14f880 00100000 8b14f858 nt!NtCreateFile+0x34
8b14f774 82097765 8b14f880 00100000 8b14f858 nt!KiFastCallEntry+0x12a (FPO:
[0,3] TrapFrame @ 8b14f7a8)
8b14f818 b4f87e1b 8b14f880 00100000 8b14f858 nt!ZwCreateFile+0x11 (FPO:
[11,0,0])
8b14f88c b4f86f5c 895372d8 00000000 b4657428 MySpy+0x1e1b
8b14f940 b4f98a46 89537220 b4657418 8b14f968 MySpy+0xf5c
8b14f950 820939c6 89537220 b4657418 ba4fa388 MySpy+0x12a46
8b14f968 8228d116 00000000 00000000 ba4fa370 nt!IofCallDriver+0x63
8b14f9ac 8227cf44 ba4fa388 8202326c ba4fa370 nt!IopDeleteFile+0x178
8b14f9c8 82093e1c ba4fa388 00000000 ba4fa388 nt!ObpRemoveObjectRoutine+0x13d
8b14f9f0 8a6a3fe0 8b14fa90 b419d000 00000000 nt!ObfDereferenceObject+0xa1
8b14fa08 8a6582f2 84dbf4b8 c3349d08 00000000 Ntfs!
NtfsDeleteInternalAttributeStream+0xde (FPO: [Non-Fpo])
8b14fabc 8a65f41e 84dbf4b8 b419d000 850a5001 Ntfs!TxfInitializeTxfDir+0x337
(FPO: [Non-Fpo])
8b14fc14 8a65b01f 84dbf4b8 c335b008 c4582d78 Ntfs!TxfStartRm+0x75c (FPO: [Non-
Fpo])
8b14fca8 8a6a4898 850a50d8 86693de0 84dbf4b8 Ntfs!TxfInitializeVolume+0x688
(FPO: [Non-Fpo]) <<<< Event 850a5f88 will be set here after Ntfs!TxfStartRm
returns
8b14fcc4 8a60c8ce 84dbf4b8 00000000 0170d693 Ntfs!
NtfsCommonFileSystemControl+0x99 (FPO: [Non-Fpo])
8b14fd44 820f4e22 00000000 00000000 84753d78 Ntfs!NtfsFspDispatch+0x264 (FPO:
[Non-Fpo])
8b14fd7c 82224c42 84dbf4b8 7000f106 00000000 nt!ExpWorkerThread+0xfd
8b14fdc0 8208df4e 820f4d25 00000000 00000000 nt!PspSystemThreadStartup+0x9d
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
0: kd> !thread 88b9fcb0
THREAD 88b9fcb0 Cid 1548.16e4 Teb: 7ffac000 Win32Thread: fe288838 WAIT:
(Executive) KernelMode Non-Alertable
850a5f88 NotificationEvent
IRP List:
85102de0: (0006,0220) Flags: 00000884 Mdl: 00000000
86693de0: (0006,0220) Flags: 00000884 Mdl: 00000000
Not impersonating
DeviceMap 80fe7a68
Owning Process b469a3c8 Image: PSDrt.exe
Attached Process N/A Image: N/A
Wait Start TickCount 171370 Ticks: 26804 (0:00:06:58.145)
Context Switch Count 78
UserTime 00:00:00.015
KernelTime 00:00:00.031
Win32 Start Address 0x745529e1
Stack Init 8b488000 Current 8b4870e0 Base 8b488000 Limit 8b485000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 4 IoPriority 2 PagePriority 5
ChildEBP RetAddr Args to Child
8b4870f8 820fb352 88b9fcb0 88b9fd38 00000000 nt!KiSwapContext+0x26 (FPO: [Uses
EBP] [0,0,4])
8b48713c 82096f28 88b9fcb0 00004005 86331be8 nt!KiSwapThread+0x44f
8b487190 8a615901 850a5f88 00000000 00000000 nt!KeWaitForSingleObject+0x492
8b487210 8a696a29 86331be8 c00000d8 012c58df Ntfs!
NtfsPreRequestProcessingExtend+0x6b0 (FPO: [Non-Fpo])
8b487308 820939c6 850a5020 85102de0 85102de0 Ntfs!NtfsFsdCreate+0x18a (FPO:
[Non-Fpo])
8b487320 826e8ba7 85102de0 00000000 85102e98 nt!IofCallDriver+0x63
8b487344 826fb643 8b487364 866a3ac8 00000000 fltmgr!
FltpLegacyProcessingAfterPreCallbacksCompleted+0x251 (FPO: [Non-Fpo])
8b487390 820939c6 866a3ac8 85205b78 88909f64 fltmgr!FltpCreate+0x2a1 (FPO: [Non-
Fpo])
8b4873a8 8228e195 705c78be 930a9b9c 86331d18 nt!IofCallDriver+0x63
8b487478 8227c5e1 86331d30 00000000 930a9af8 nt!IopParseDevice+0xf61
8b487508 82289b62 00000000 8b487560 00000240 nt!ObpLookupObjectName+0x5a8
8b48756c 8228f29c 8b487708 00000000 00000000 nt!ObOpenObjectByName+0x13c
8b4875e0 822940ba 8b487748 00100180 8b487708 nt!IopCreateFile+0x63b
8b48763c 826fd7dc 8b487748 00100180 8b487708 nt!IoCreateFileEx+0x9d
8b4876c0 82706058 88919310 865deb48 8b487748 fltmgr!FltCreateFileEx2+0xae (FPO:
[Non-Fpo])
8b487728 8270667e 865deb48 8b487748 00000000 fltmgr!FltOpenVolume+0x66 (FPO:
[Non-Fpo])
8b487740 8f89f6c6 865deb48 8b487794 c3523008 fltmgr!
FltQueryVolumeInformation+0x14 (FPO: [Non-Fpo])
8b4877a8 8f8a54ac 00000000 8afac4a0 00000002 SRTSP+0x3423
8b4877ec 826fc8a0 8b487808 00000005 00000008 SRTSP+0x1763
8b487820 826fd09f 865deb48 00000005 09274055 fltmgr!
FltpDoInstanceSetupNotification+0x66 (FPO: [Non-Fpo])
8b48786c 826fd457 88919310 85205b78 00000005 fltmgr!FltpInitInstance+0x245
(FPO: [Non-Fpo])
8b4878dc 826fd55d 88919310 85205b78 00000005 fltmgr!
FltpCreateInstanceFromName+0x285 (FPO: [Non-Fpo])
8b487948 827064ca 88919310 85205b78 00000005 fltmgr!
FltpEnumerateRegistryInstances+0xf9 (FPO: [Non-Fpo])
8b487998 826fb5a7 85205b78 895372d8 86693eb4 fltmgr!
FltpDoFilterNotificationForNewVolume+0xe0 (FPO: [Non-Fpo])
8b4879dc 820939c6 866a3ac8 85205b78 86693de0 fltmgr!FltpCreate+0x205 (FPO: [Non-
Fpo])
8b4879f4 b4f87063 88b9fedc 89537220 86693de0 nt!IofCallDriver+0x63
WARNING: Stack unwind information not available. Following frames may be wrong.
8b487aa0 b4f871c9 89537220 86693de0 8b487ac8 MySpy+0x1063
8b487ab0 820939c6 89537220 86693de0 851e4b64 MySpy+0x11c9
8b487ac8 8228e195 705c775e 86666dc4 86331d18 nt!IofCallDriver+0x63
8b487b98 8227c5e1 86331d30 00000000 86666d20 nt!IopParseDevice+0xf61
8b487c28 82289b62 00000000 8b487c80 00000040 nt!ObpLookupObjectName+0x5a8
8b487c88 8228f29c 041cf1bc 00000000 820e9201 nt!ObOpenObjectByName+0x13c
8b487cfc 82255077 041cf1f8 00100000 041cf1bc nt!IopCreateFile+0x63b
8b487d44 82099c7a 041cf1f8 00100000 041cf1bc nt!NtOpenFile+0x2a
8b487d44 779b5e74 041cf1f8 00100000 041cf1bc nt!KiFastCallEntry+0x12a (FPO:
[0,3] TrapFrame @ 8b487d64)
041cf1f0 00000000 00000000 00000000 00000000 0x779b5e74
Summary: there is deadlock between THREAD 88b9fcb0 and THREAD
84753d78.
Thread 84753d78 requests exclusive access to ERESOUCE 85205ec8 which is owned
by thread 88b9fcb0. However thread 88b9fcb0 is waiting for kernel event
850a5f88 which will be signaled by thread 84753d78 after it gains exclusive
access to ERESOUCE 85205ec8. Hence the deadlock.
Event 850a5f88 has tag Txfp, it is owned by NTFS, it will be set in Ntfs!TxfInitializeVolume.
0: kd> !pool 850a5f88
Pool page 850a5f88 region is Nonpaged pool
850a5000 size: c40 previous size: 0 (Allocated) Devi (Protected)
850a5c40 size: 30 previous size: c40 (Allocated) Ntfn
850a5c70 size: 48 previous size: 30 (Allocated) Vadl
*850a5cb8 size: 348 previous size: 48 (Allocated) *Txfp
Owning component : Unknown (update pooltag.txt)
After some thought, it seems that thread 84753d78 is the system thread who is responsible of handling volume mount operations (Ntfs!NtfsCommonFileSystemControl), in 2 steps:
1)Ntfs!NtfsMountVolume and
2)Ntfs!TxfInitializeVolume .
In step 1, VPB is set up appropriately. The volume can be accessable since VPB is not null. The hang is this case occurs because some thread access the volume after step1 and before step2.
So can I say this is a problem of NTFS?
0: kd> uf Ntfs!NtfsCommonFileSystemControl
Ntfs!NtfsCommonFileSystemControl+0x73:
8a6a4872 8d45fc lea eax,[ebp-4]
8a6a4875 50 push eax
8a6a4876 53 push ebx
8a6a4877 ff7508 push dword ptr [ebp+8]
8a6a487a e80d90faff call Ntfs!NtfsMountVolume (8a64d88c) <<<<<< step 1
8a6a487f 3bc7 cmp eax,edi
8a6a4881 89450c mov dword ptr [ebp+0Ch],eax
8a6a4884 755d jne Ntfs!NtfsCommonFileSystemControl+0xe4 (8a6a48e3)
…
Ntfs!NtfsCommonFileSystemControl+0x93:
8a6a4892 56 push esi
8a6a4893 e8ff60fbff call Ntfs!TxfInitializeVolume (8a65a997) <<<<<< step 2