I?m getting a very strange callstack from a memory dump. The system was bluescreened by the DPC Watchdog after one of the thread got deadlocked on itself by acquiring spinlock and trying to acquire it again on the same callstack using KeAcquireInStackQueuedSpinLock. The second attempt to lock popped out from the IRP completion handler. Any idea could it happened? Why did I get IRP completion while I?m under the spinlock?
Callstack:
nt!KxWaitForLockOwnerShip+0x34
nt!KeAcquireInStackQueuedSpinLock+0x8d
nt!VerifierKeAcquireInStackQueuedSpinLock+0xba
Filter!enter_lock+0x26 [list_platform.h @ 87]
Filter!list_lock+0x58 [list.c @ 436]
Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
Filter!list_remove_item+0xe5 [list.c @ 603]
Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
Filter!DataSourceReadCompletion+0xbd [filereadcbk.cpp @ 293]
Filter!IrpCompletion+0x22d [datasource.cpp @ 382]
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
CLASSPNP!TransferPktComplete+0x1ce
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
storport!RaidUnitCompleteRequest+0x1fb
storport!RaidpAdapterRedirectDpcRoutine+0x4e
nt!KiRetireDpcList+0x1bc
nt!KxRetireDpcList+0x5 (TrapFrame @ fffff88001e1be70) nt!KiDispatchInterruptContinue nt!KiDpcInterrupt+0xcc (TrapFrame @ fffff880065dce80)
nt!MiFreeWsleList+0x2e8
nt!MiEmptyWorkingSet+0x27d
nt!MiTrimAllSystemPagableMemory+0x218
nt!MmVerifierTrimMemory+0xf1
nt!ViKeRaiseIrqlSanityChecks+0xcf
nt!VerifierKeAcquireInStackQueuedSpinLock+0xac
Filter!enter_lock+0x26 [list_platform.h @ 87]
Filter!list_lock+0x58 [list.c @ 436]
Filter!list_int_release_pending_ops+0x4f [list.c @ 283]
Filter!list_int_remove_item_helper+0x128 [list.c @ 353]
Filter!list_remove_item+0xe5 [list.c @ 603]
Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
Filter!CompleteReadOp+0x5aa [filereadcbk.cpp @ 405]
If your top-level stack is running on PASSIVE_LEVEL, there is a possibility a DPC may be called at any time. You see that storport DPC was called and caused another request completion which then called your completion routine. If you don’t want that to happen, run on DISPATCH_LEVEL. But if such recursion screws you up, then a concurrency on a different processor will screw you up, too. You need to use some appropriate locks to prevent that.
That stack is pretty cool (if you can call a stack cool), you’re trying to
acquire a spinlock and during the IRQL raise the DPC queue gets drained,
which completes a request, which causes you to try to grab a spinlock which
results in the deadlock.
It looks to me like this isn’t a recursive acquire of the same spinlock.
Acquiring a spinlock involves two steps:
-
Raise the IRQL to the implied IRQL of the spinlock
-
Acquire the lock
Here, you’re second lock is being acquired between steps 1 and 2 of
acquiring the first lock. A locking hierarchy violation maybe?
-scott
–
Scott Noone
Consulting Associate and Chief System Problem Analyst
OSR Open Systems Resources, Inc.
http://www.osronline.com
wrote in message news:xxxxx@ntdev…
I?m getting a very strange callstack from a memory dump. The system was
bluescreened by the DPC Watchdog after one of the thread got deadlocked on
itself by acquiring spinlock and trying to acquire it again on the same
callstack using KeAcquireInStackQueuedSpinLock. The second attempt to lock
popped out from the IRP completion handler. Any idea could it happened? Why
did I get IRP completion while I?m under the spinlock?
Callstack:
nt!KxWaitForLockOwnerShip+0x34
nt!KeAcquireInStackQueuedSpinLock+0x8d
nt!VerifierKeAcquireInStackQueuedSpinLock+0xba
Filter!enter_lock+0x26 [list_platform.h @ 87]
Filter!list_lock+0x58 [list.c @ 436]
Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
Filter!list_remove_item+0xe5 [list.c @ 603]
Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
Filter!DataSourceReadCompletion+0xbd [filereadcbk.cpp @ 293]
Filter!IrpCompletion+0x22d [datasource.cpp @ 382]
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
CLASSPNP!TransferPktComplete+0x1ce
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
storport!RaidUnitCompleteRequest+0x1fb
storport!RaidpAdapterRedirectDpcRoutine+0x4e
nt!KiRetireDpcList+0x1bc
nt!KxRetireDpcList+0x5 (TrapFrame @ fffff88001e1be70) nt!KiDispatchInterruptContinue nt!KiDpcInterrupt+0xcc (TrapFrame @ fffff880065dce80)
nt!MiFreeWsleList+0x2e8
nt!MiEmptyWorkingSet+0x27d
nt!MiTrimAllSystemPagableMemory+0x218
nt!MmVerifierTrimMemory+0xf1
nt!ViKeRaiseIrqlSanityChecks+0xcf
nt!VerifierKeAcquireInStackQueuedSpinLock+0xac
Filter!enter_lock+0x26 [list_platform.h @ 87]
Filter!list_lock+0x58 [list.c @ 436]
Filter!list_int_release_pending_ops+0x4f [list.c @ 283]
Filter!list_int_remove_item_helper+0x128 [list.c @ 353]
Filter!list_remove_item+0xe5 [list.c @ 603]
Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
Filter!CompleteReadOp+0x5aa [filereadcbk.cpp @ 405]
The lock could not actually have been acquired in the first instance
at the point in time when the dpc started running - instead verifier
code was running before the actual lock acquisition. So the question
is why is the second acquisition blocked? Has verifier mangled lock
acquisition? Is there another thread holding this same lock?
First acquisition:
nt!KiDpcInterrupt+0xcc (TrapFrame @ fffff880`065dce80)
nt!MiFreeWsleList+0x2e8
nt!MiEmptyWorkingSet+0x27d
nt!MiTrimAllSystemPagableMemory+0x218
nt!MmVerifierTrimMemory+0xf1
nt!ViKeRaiseIrqlSanityChecks+0xcf
nt!VerifierKeAcquireInStackQueuedSpinLock+0xac <<< this is not really
KeAcquireInStackSpinLock
Filter!enter_lock+0x26 [list_platform.h @ 87]
Second acquisition:
nt!KxWaitForLockOwnerShip+0x34
nt!KeAcquireInStackQueuedSpinLock+0x8d <<< this is the real
KeAcquireInStackSpinLock.
nt!VerifierKeAcquireInStackQueuedSpinLock+0xba
Filter!enter_lock+0x26 [list_platform.h @ 87]
Mark Roddy
On Wed, Mar 2, 2011 at 3:44 PM, wrote:
> If your top-level stack is running on PASSIVE_LEVEL, there is a possibility a DPC may be called at any time. You see that storport DPC was called and caused another request completion which then called your completion routine. If you don’t want that to happen, run on DISPATCH_LEVEL. But if such recursion screws you up, then a concurrency on a different processor will screw you up, too. You need to use some appropriate locks to prevent that.
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
>
@Scott:
The DPC interrupt seems to happen during the Verifier pre-IRQL-raise operations. It can’t by definition happen post-IRQL raise. Looks like the top of the stack is at PASSIVE, which was the OPs design mistake.
How is that a design mistake? A worker thread runs and tries to grab a
spinlock, a dpc runs inside the grab, during the IRQL raise but
before the lock acquire, and grabs the same spinlock. There is no bug
there. The second acquire works unless SOME OTHER THREAD OWNS THE
LOCK. That has to work. It is fundamental to the design of spinlocks
in NT. There is no requirement to not run at passive level when
calling keacquirespinlock.
Mark Roddy
On Wed, Mar 2, 2011 at 4:37 PM, wrote:
> @Scott:
> The DPC interrupt seems to happen during the Verifier pre-IRQL-raise operations. It can’t by definition happen post-IRQL raise. Looks like the top of the stack is at PASSIVE, which was the OPs design mistake.
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
>
>The DPC interrupt seems to happen during the Verifier pre-IRQL-raise
operations. It can’t by definition happen post-IRQL raise.
Yes, excellent point. My example was a bit sloppy there.
Looks like the top of the stack is at PASSIVE, which was the OPs design
mistake.
How so? It’s legal to acquire a spinlock at IRQL PASSIVE_LEVEL, otherwise
you wouldn’t be able to serialize your dispatch entry point with your DPC
(for example).
-scott
–
Scott Noone
Consulting Associate and Chief System Problem Analyst
OSR Open Systems Resources, Inc.
http://www.osronline.com
Are you sure that there isn’t another thread holding this lock?
We see this thread trying to acquire the same lock twice, but the first attempt doesn’t actually seem to have gotten to the point where it acquired the lock. That would seem to indicate that something else is holding the lock preventing the second acquisition of the lock from inside this thread from occurring.
I’ve checked I?m acquiring the same lock in both cases (fffff980`0edd87b8) that sits in the non-pageable memory. There are basically 2 threads related to the lock ~2 and ~3. ~2 is in the deadlock while ~3 is waiting?
2: kd> !thread
THREAD fffffa8008b46660 Cid 0bb4.0e88 Teb: 000007fffff9a000 Win32Thread: 0000000000000000 RUNNING on processor 2
IRP List:
fffff9800ec48ee0: (0006,0118) Flags: 40060000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007bf0
Owning Process fffffa80080af9c0 Image: driver.exe
Attached Process N/A Image: N/A
Wait Start TickCount 583981 Ticks: 0
Context Switch Count 43234
UserTime 00:00:02.106
KernelTime 00:00:08.736
Win32 Start Address 0x000000013f671de0
Stack Init fffff8800c7dfdb0 Current fffff8800c7ded00
Base fffff8800c7e0000 Limit fffff8800c7da000 Call 0
Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Args to Child : Call Site
fffff88001e8c550 ffffffff0000000c 0000000000000000 0000000000000004 : nt!RtlpInterlockedPushEntrySList+0x31
fffffa80069af950 fffffa8008f59f30 0000000000000000 0000000000000005 : nt!ExFreeToNPagedLookasideList+0x27
000000000008e92d fffffa8008a20b80 fffffa80083f1b90 fffffa8009531990 : nt!ViDeadlockFree+0x3a
fffff9800edd87b8 fffff88001e8ca02 0000000000000000 fffff80000000000 : nt!VfDeadlockAcquireResource+0x641
fffff9800e37afb0 fffff9800e350f68 fffff9800e37afb0 fffff88001e8cad0 : nt!VerifierKeAcquireSpinLockRaiseToDpc+0x11f
fffff9800edd87b8 fffff88001e8c6d0 fffffa8008e4b090 fffff88006131946 : Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
fffff9800edd8788 fffff88001e8c6d0 fffff8800613c690 fffff88006141c0d : Filter!list_lock+0x58 [list.c @ 436]
fffff9800edd8788 fffff88006142461 fffff8800614c688 fffff88001e8c728 : Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
fffff9800eefcf70 fffff80003517202 fffff88006a00000 fffff88006a57074 : Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
fffff9800edd8788 fffff9800eefcf90 fffff8800614c688 fffff88001e8c828 : Filter!list_remove_item+0xe5 [list.c @ 603]
fffff9800eefcf90 fffffa80000003f1 fffff88001e8c828 0000000000000000 : Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
fffff9800eefcf90 fffff80000000000 fffffa800000da00 0000000000000000 : Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
fffff9800e350cd0 fffff9800eefcf90 0000000000000000 0000000000000000 : Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
fffffa8008ec6ac0 fffff9800e350ca0 fffff9800e37afb0 fffff9800e350ca0 : Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370]
fffff9800e350f6b fffff80000000000 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800e350ca0 00000000ffffff01 fffffa8008521001 0000000000000000 : nt!IopfCompleteRequest+0x3a6
000000000000000c fffff9800cd02e02 0000000000000008 fffffa8008521010 : nt!IovCompleteRequest+0x19f
fffffa80090cdb10 fffffa80090cdb10 fffff88001e8cd60 fffff9800cd02ea0 : CLASSPNP!TransferPktComplete+0x1ce
fffff9800cd02fbb fffff80000000001 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800cd02ea0 fffffa8008506101 fffffa80090cdc01 0000000000000000 : nt!IopfCompleteRequest+0x3a6
fffffa8008becc60 0000000000000000 fffffa8008becc60 fffffa80090cdc30 : nt!IovCompleteRequest+0x19f
0000000000000000 fffff800000000e1 fffff88001e5d180 fffffa8007eb7140 : storport!RaidUnitCompleteRequest+0x1fb
fffff88001e5d180 fffffa8007eb7100 0000000000000000 0000000000000064 : storport!RaidpAdapterRedirectDpcRoutine+0x4e
0000000000000000 fffffa8008b46660 0000000000000000 fffff88000c4e280 : nt!KiRetireDpcList+0x1bc
fffff88006131190 fffffa8009bf4dc1 0000000000000000 fffff8000360fb50 : nt!KxRetireDpcList+0x5 (TrapFrame @ fffff88001e8ce70) 0000000000000000 fffff8800c7df240 000000000000000b fffff8800000000c : nt!KiDispatchInterruptContinue fffff9800edd87b8 fffff88006131208 fffffa8008306000 0000000000000002 : nt!KiDpcInterrupt+0xcc (TrapFrame @ fffff8800c7df120)
0000000000000008 0000000000000008 fffffa8008bc3d20 fffffa8008306090 : nt!VerifierKeReleaseSpinLock+0xd8
fffff9800edd87b8 fffff8800c7df390 fffff8800614c600 fffff9800e28cf70 : Filter!vs_leave_lock+0x58 [list_platform.h @ 97]
fffff9800edd8788 fffff8800c7df390 fffff9805630706c fffff8800c7df3e0 : Filter!list_unlock+0x58 [list.c @ 444]
fffff9800edd8788 fffff8800c7df3e0 fffff9800edd87b0 fffff88006141c0d : Filter!list_int_remove_deleted_items+0x157 [list.c @ 175]
fffff9800edd8788 fffff88006142461 fffff8800614c688 fffff8800c7df438 : Filter!list_int_decrement_pending_ops+0xea [list.c @ 249]
fffff9800e28cf70 fffff80003517200 fffff88006a00000 fffff88006a5701c : Filter!list_int_remove_item_helper+0x176 [list.c @ 360]
fffff9800edd8788 fffff9800e28cf90 fffff8800614c688 fffff8800c7df538 : Filter!list_remove_item+0xe5 [list.c @ 603]
fffff9800e28cf90 fffffa80000003f1 fffff8800c7df538 0000000000000000 : Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
fffff9800e28cf90 fffff98000000000 fffff88000000000 fffff88000004400 : Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
fffffa80095610c0 fffff880000000e6 0000000000000005 0000000000f7e17c : Filter!StartSingleWrite+0x3db [filewritecbk.cpp @ 350]
fffffa80095610c0 0000000002df1be8 0000000000000000 0000000000000000 : Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
0000000000000000 0000000000f7e150 fffff98000000074 000000000c26f7e8 : Filter!OnCommPortMessage+0x4c9 [servicemsg.cpp @ 150]
fffff8800c7df920 000000000c26f701 fffff9800ec48ee0 0000000000000074 : fltmgr!FltpFilterMessage+0xc7
3: kd> !thread
THREAD fffffa8008b44660 Cid 0bb4.041c Teb: 000007fffffa0000 Win32Thread: 0000000000000000 RUNNING on processor 3
IRP List:
fffff9800e104ee0: (0006,0118) Flags: 40060000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007bf0
Owning Process fffffa80080af9c0 Image: driver.exe
Attached Process N/A Image: N/A
Wait Start TickCount 583981 Ticks: 0
Context Switch Count 43226
UserTime 00:00:01.716
KernelTime 00:01:06.440
Win32 Start Address 0x000000013f671de0
Stack Init fffff8800c6b2db0 Current fffff8800c6b22b0
Base fffff8800c6b3000 Limit fffff8800c6ad000 Call 0
Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Args to Child : Call Site
fffff9800edd87b8 fffff8800c6b1a70 0000000000000000 fffff8000351758b : nt!KxWaitForSpinLockAndAcquire+0x23
fffff9800ed56fb0 fffff9800e11ef68 fffff9800ed56fb0 fffff8800c6b1a70 : nt!VerifierKeAcquireSpinLockRaiseToDpc+0xb0
fffff9800edd87b8 fffff8800c6b1670 fffff88001ece180 fffff88006131909 : Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
fffff9800edd8788 fffff8800c6b1670 fffff8800613c690 fffff88006141c0d : Filter!list_lock+0x58 [list.c @ 436]
fffff9800edd8788 fffff88006142461 fffff8800614c688 fffff8800c6b16c8 : Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
fffff9800e0e2f70 fffff80003517202 fffff88006a00000 fffff88006a57048 : Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
fffff9800edd8788 fffff9800e0e2f90 fffff8800614c688 fffff8800c6b17c8 : Filter!list_remove_item+0xe5 [list.c @ 603]
fffff9800e0e2f90 fffffa80000003f1 fffff8800c6b17c8 0000000000000000 : Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
fffff9800e0e2f90 fffff80000000000 fffffa8000009c00 0000000000000000 : Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
fffff9800e11ecd0 fffff9800e0e2f90 0000000000000000 0000000000000000 : Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
fffffa8008ec6ac0 fffff9800e11eca0 fffff9800ed56fb0 fffff9800e11eca0 : Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370]
fffff9800e11ef6b fffff80000000000 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800e11eca0 00000000ffffff01 fffffa8008521001 0000000000000000 : nt!IopfCompleteRequest+0x3a6
fffff88001ece102 fffff9800cc9ee02 000000000000000a fffffa8008521010 : nt!IovCompleteRequest+0x19f
fffffa80090d6e60 fffffa80090d6e60 fffff8800c6b1d00 fffff9800cc9eea0 : CLASSPNP!TransferPktComplete+0x1ce
fffff9800cc9efbb fffff80000000001 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800cc9eea0 fffffa8008506101 fffffa80090d6f01 0000000000000000 : nt!IopfCompleteRequest+0x3a6
fffffa80094d7260 fffffa80090d3b80 fffffa80094d7260 fffffa80090d6f80 : nt!IovCompleteRequest+0x19f
fffffa8000000000 00000000000000c8 fffffa8007d89470 0000000000000001 : storport!RaidUnitCompleteRequest+0x1fb
fffffa80085061b0 fffff9800cdaaf18 000000000000e400 fffffa80085061b0 : storport!RaidCheckPerProcessorCompletions+0x93
fffff8800c6b2001 fffff88000c64110 0000000000030000 0000000000000000 : storport! ?? ::FNODOBFM::string'+0x1f03 fffff9800cdaaea0 0000000000000002 fffffa8008506060 0000000000000000 : storport!RaDriverScsiIrp+0x5d 0000000000000000 0000000000000001 fffffa80090d3a60 fffffa8009abe010 : nt!IovCallDriver+0x566 fffffa8008521010 fffffa8008506060 fffff88000040000 fffff80000000000 : CLASSPNP!ServiceTransferRequest+0x355 fffff9800e1ceca0 0000000000000002 fffffa8008515790 0000000000000002 : CLASSPNP!ClassReadWrite+0xd5 fffff9800e1ceca0 0000000000000002 fffff9800e1cee90 fffffa80095cc0b0 : nt!IovCallDriver+0x566 fffff9800e1ceca0 fffffa8008516040 fffff9800e1cef20 0000000000000000 : partmgr!PmGlobalDispatch+0x9f fffffa8008520c10 0000000000000002 fffff9800e1ceca0 fffffa8008b6d240 : nt!IovCallDriver+0x566 0000000000000002 fffffa80098739a0 fffff9800e1ceca0 0000000000000001 : volmgr!VmReadWrite+0x11c fffff9800e1ceca0 0000000000000002 fffff9800e1cef20 fffffa80098739a0 : nt!IovCallDriver+0x566 0000000000000002 fffffa8008535040 0000000000000000 fffffa80094e99c0 : volsnap!VolsnapWriteFilter+0xf8 fffff9800e1cef68 fffff9800e1ceca0 fffffa8008a9de50 fffffa8008f73500 : nt!IovCallDriver+0x566 0000000000000000 0000000000000002 fffff9800e1ceca0 fffff880012c76af : nt!RawReadWriteDeviceControl+0xa8 fffff9800e1ceca0 fffffa8008a9dd00 fffffa80093859a0 0000000000000000 : nt!RawDispatch+0x7d fffffa8008ec6ac0 0000000000000002 fffffa8008ec6ac0 fffffa80093859a0 : nt!IovCallDriver+0x566 fffff9800e1ceca0 0000000000000002 fffff9800e1ceca0 fffff80003524b80 : fltmgr!FltpDispatch+0x9f 0000000000000008 fffffa8008bc3d20 fffffa8008306090 fffffa80094e99c0 : nt!IovCallDriver+0x566 fffffa8009078bd0 fffff980074aaf00 fffff8800c6b25f8 fffff8800000e400 : Filter!WriteToDestinationSingle+0x3ba [datasource.cpp @ 749] fffffa8007bcea70 fffff880000000e6 0000000000000005 0000000000f7e47c : Filter!StartSingleWrite+0x3b0 [filewritecbk.cpp @ 340] fffffa8007bcea70 0000000002deefe8 0000000000000000 fffff800`00000000 : Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
Same callstacks without the arguments.
2: kd> !thread
THREAD fffffa8008b46660 Cid 0bb4.0e88 Teb: 000007fffff9a000 Win32Thread: 0000000000000000 RUNNING on processor 2
IRP List:
fffff9800ec48ee0: (0006,0118) Flags: 40060000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007bf0
Owning Process fffffa80080af9c0 Image: driver.exe
Attached Process N/A Image: N/A
Wait Start TickCount 583981 Ticks: 0
Context Switch Count 43234
UserTime 00:00:02.106
KernelTime 00:00:08.736
Win32 Start Address 0x000000013f671de0
Stack Init fffff8800c7dfdb0 Current fffff8800c7ded00
Base fffff8800c7e0000 Limit fffff8800c7da000 Call 0
Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Call Site
nt!RtlpInterlockedPushEntrySList+0x31
nt!ExFreeToNPagedLookasideList+0x27
nt!ViDeadlockFree+0x3a
nt!VfDeadlockAcquireResource+0x641
nt!VerifierKeAcquireSpinLockRaiseToDpc+0x11f
Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
Filter!list_lock+0x58 [list.c @ 436]
Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
Filter!list_remove_item+0xe5 [list.c @ 603]
Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370]
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
CLASSPNP!TransferPktComplete+0x1ce
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
storport!RaidUnitCompleteRequest+0x1fb
storport!RaidpAdapterRedirectDpcRoutine+0x4e
nt!KiRetireDpcList+0x1bc
nt!KxRetireDpcList+0x5 (TrapFrame @ fffff88001e8ce70) nt!KiDispatchInterruptContinue nt!KiDpcInterrupt+0xcc (TrapFrame @ fffff8800c7df120)
nt!VerifierKeReleaseSpinLock+0xd8
Filter!vs_leave_lock+0x58 [list_platform.h @ 97]
Filter!list_unlock+0x58 [list.c @ 444]
Filter!list_int_remove_deleted_items+0x157 [list.c @ 175]
Filter!list_int_decrement_pending_ops+0xea [list.c @ 249]
Filter!list_int_remove_item_helper+0x176 [list.c @ 360]
Filter!list_remove_item+0xe5 [list.c @ 603]
Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
Filter!StartSingleWrite+0x3db [filewritecbk.cpp @ 350]
Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
Filter!OnCommPortMessage+0x4c9 [servicemsg.cpp @ 150]
fltmgr!FltpFilterMessage+0xc7
3: kd> !thread
THREAD fffffa8008b44660 Cid 0bb4.041c Teb: 000007fffffa0000 Win32Thread: 0000000000000000 RUNNING on processor 3
IRP List:
fffff9800e104ee0: (0006,0118) Flags: 40060000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007bf0
Owning Process fffffa80080af9c0 Image: driver.exe
Attached Process N/A Image: N/A
Wait Start TickCount 583981 Ticks: 0
Context Switch Count 43226
UserTime 00:00:01.716
KernelTime 00:01:06.440
Win32 Start Address 0x000000013f671de0
Stack Init fffff8800c6b2db0 Current fffff8800c6b22b0
Base fffff8800c6b3000 Limit fffff8800c6ad000 Call 0
Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Call Site
nt!KxWaitForSpinLockAndAcquire+0x23
nt!VerifierKeAcquireSpinLockRaiseToDpc+0xb0
Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
Filter!list_lock+0x58 [list.c @ 436]
Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
Filter!list_remove_item+0xe5 [list.c @ 603]
Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370]
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
CLASSPNP!TransferPktComplete+0x1ce
nt!IovpLocalCompletionRoutine+0x166
nt!IopfCompleteRequest+0x3a6
nt!IovCompleteRequest+0x19f
storport!RaidUnitCompleteRequest+0x1fb
storport!RaidCheckPerProcessorCompletions+0x93
storport! ?? ::FNODOBFM::`string’+0x1f03
storport!RaDriverScsiIrp+0x5d
nt!IovCallDriver+0x566
CLASSPNP!ServiceTransferRequest+0x355
CLASSPNP!ClassReadWrite+0xd5
nt!IovCallDriver+0x566
partmgr!PmGlobalDispatch+0x9f
nt!IovCallDriver+0x566
volmgr!VmReadWrite+0x11c
nt!IovCallDriver+0x566
volsnap!VolsnapWriteFilter+0xf8
nt!IovCallDriver+0x566
nt!RawReadWriteDeviceControl+0xa8
nt!RawDispatch+0x7d
nt!IovCallDriver+0x566
fltmgr!FltpDispatch+0x9f
nt!IovCallDriver+0x566
Filter!WriteToDestinationSingle+0x3ba [datasource.cpp @ 749]
Filter!StartSingleWrite+0x3b0 [filewritecbk.cpp @ 340]
Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
You aren’t by any chance mixing KeAcquireInStackQueuedSpinLock and
KeAcquireSpinLock are you? Your new stacks are not using
KeAcquireInStackQueuedSpinLock. Did you change the code?
Anyway, I’m going to guess that verifier is having a false positive on
deadlock detection here. If this is as reproducible as it seems to be,
it should be equally reproducible with verifier out of the picture. Is
it?
Mark Roddy
On Wed, Mar 2, 2011 at 5:56 PM, wrote:
> Same callstacks without the arguments.
>
> 2: kd> !thread
> THREAD fffffa8008b46660 ?Cid 0bb4.0e88 ?Teb: 000007fffff9a000 Win32Thread: 0000000000000000 RUNNING on processor 2
> IRP List:
> ? ?fffff9800ec48ee0: (0006,0118) Flags: 40060000 ?Mdl: 00000000
> Not impersonating
> DeviceMap ? ? ? ? ? ? ? ? fffff8a000007bf0
> Owning Process ? ? ? ? ? ?fffffa80080af9c0 ? ? ? Image: ? ? ? ? driver.exe
> Attached Process ? ? ? ? ?N/A ? ? ? ? ? ?Image: ? ? ? ? N/A
> Wait Start TickCount ? ? ?583981 ? ? ? ? Ticks: 0
> Context Switch Count ? ? ?43234
> UserTime ? ? ? ? ? ? ? ? ?00:00:02.106
> KernelTime ? ? ? ? ? ? ? ?00:00:08.736
> Win32 Start Address 0x000000013f671de0
> Stack Init fffff8800c7dfdb0 Current fffff8800c7ded00
> Base fffff8800c7e0000 Limit fffff8800c7da000 Call 0
> Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
> Call Site
> nt!RtlpInterlockedPushEntrySList+0x31
> nt!ExFreeToNPagedLookasideList+0x27
> nt!ViDeadlockFree+0x3a
> nt!VfDeadlockAcquireResource+0x641
> nt!VerifierKeAcquireSpinLockRaiseToDpc+0x11f
> Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
> Filter!list_lock+0x58 [list.c @ 436]
> Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
> Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
> Filter!list_remove_item+0xe5 [list.c @ 603]
> Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
> Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
> Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
> Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370]
> nt!IovpLocalCompletionRoutine+0x166
> nt!IopfCompleteRequest+0x3a6
> nt!IovCompleteRequest+0x19f
> CLASSPNP!TransferPktComplete+0x1ce
> nt!IovpLocalCompletionRoutine+0x166
> nt!IopfCompleteRequest+0x3a6
> nt!IovCompleteRequest+0x19f
> storport!RaidUnitCompleteRequest+0x1fb
> storport!RaidpAdapterRedirectDpcRoutine+0x4e
> nt!KiRetireDpcList+0x1bc
> nt!KxRetireDpcList+0x5 (TrapFrame @ fffff88001e8ce70)<br>> nt!KiDispatchInterruptContinue<br>> nt!KiDpcInterrupt+0xcc (TrapFrame @ fffff8800c7df120)
> nt!VerifierKeReleaseSpinLock+0xd8
> Filter!vs_leave_lock+0x58 [list_platform.h @ 97]
> Filter!list_unlock+0x58 [list.c @ 444]
> Filter!list_int_remove_deleted_items+0x157 [list.c @ 175]
> Filter!list_int_decrement_pending_ops+0xea [list.c @ 249]
> Filter!list_int_remove_item_helper+0x176 [list.c @ 360]
> Filter!list_remove_item+0xe5 [list.c @ 603]
> Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
> Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
> Filter!StartSingleWrite+0x3db [filewritecbk.cpp @ 350]
> Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
> Filter!OnCommPortMessage+0x4c9 [servicemsg.cpp @ 150]
> fltmgr!FltpFilterMessage+0xc7
>
> 3: kd> !thread
> THREAD fffffa8008b44660 ?Cid 0bb4.041c ?Teb: 000007fffffa0000 Win32Thread: 0000000000000000 RUNNING on processor 3
> IRP List:
> ? ?fffff9800e104ee0: (0006,0118) Flags: 40060000 ?Mdl: 00000000
> Not impersonating
> DeviceMap ? ? ? ? ? ? ? ? fffff8a000007bf0
> Owning Process ? ? ? ? ? ?fffffa80080af9c0 ? ? ? Image: ? ? ? ? driver.exe
> Attached Process ? ? ? ? ?N/A ? ? ? ? ? ?Image: ? ? ? ? N/A
> Wait Start TickCount ? ? ?583981 ? ? ? ? Ticks: 0
> Context Switch Count ? ? ?43226
> UserTime ? ? ? ? ? ? ? ? ?00:00:01.716
> KernelTime ? ? ? ? ? ? ? ?00:01:06.440
> Win32 Start Address 0x000000013f671de0
> Stack Init fffff8800c6b2db0 Current fffff8800c6b22b0
> Base fffff8800c6b3000 Limit fffff8800c6ad000 Call 0
> Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
> Call Site
> nt!KxWaitForSpinLockAndAcquire+0x23
> nt!VerifierKeAcquireSpinLockRaiseToDpc+0xb0
> Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
> Filter!list_lock+0x58 [list.c @ 436]
> Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
> Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
> Filter!list_remove_item+0xe5 [list.c @ 603]
> Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
> Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
> Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
> Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370]
> nt!IovpLocalCompletionRoutine+0x166
> nt!IopfCompleteRequest+0x3a6
> nt!IovCompleteRequest+0x19f
> CLASSPNP!TransferPktComplete+0x1ce
> nt!IovpLocalCompletionRoutine+0x166
> nt!IopfCompleteRequest+0x3a6
> nt!IovCompleteRequest+0x19f
> storport!RaidUnitCompleteRequest+0x1fb
> storport!RaidCheckPerProcessorCompletions+0x93
> storport! ?? ::FNODOBFM::`string’+0x1f03
> storport!RaDriverScsiIrp+0x5d
> nt!IovCallDriver+0x566
> CLASSPNP!ServiceTransferRequest+0x355
> CLASSPNP!ClassReadWrite+0xd5
> nt!IovCallDriver+0x566
> partmgr!PmGlobalDispatch+0x9f
> nt!IovCallDriver+0x566
> volmgr!VmReadWrite+0x11c
> nt!IovCallDriver+0x566
> volsnap!VolsnapWriteFilter+0xf8
> nt!IovCallDriver+0x566
> nt!RawReadWriteDeviceControl+0xa8
> nt!RawDispatch+0x7d
> nt!IovCallDriver+0x566
> fltmgr!FltpDispatch+0x9f
> nt!IovCallDriver+0x566
> Filter!WriteToDestinationSingle+0x3ba [datasource.cpp @ 749]
> Filter!StartSingleWrite+0x3b0 [filewritecbk.cpp @ 340]
> Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
>
>
> —
> NTDEV is sponsored by OSR
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
>
>You aren’t by any chance mixing KeAcquireInStackQueuedSpinLock and
KeAcquireSpinLock are you? Your new stacks are not using
KeAcquireInStackQueuedSpinLock. Did you change the code?
I began to suspect something is wrong with KeAcquireInStackQueuedSpinLock so I changed the code to KeAcquireSpinLock/KeReleaseSpinLock. And I 100% sure I’m not mixing them (.
Anyway, I’m going to guess that verifier is having a false positive on
deadlock detection here. If this is as reproducible as it seems to be,
it should be equally reproducible with verifier out of the picture. Is
it?
I started to run under verifier after I got a couple of reports that server hangs with my filter driver installed. At this moment I’m trying to setup debugger to test it on the live system. Will keep you posted.
“How is that a design mistake? A worker thread runs and tries to grab a
spinlock, a dpc runs inside the grab, during the IRQL raise but
before the lock acquire, and grabs the same spinlock.”
I may have worded it wrong. Actually, I did. The OP’s mistake is most likely the lock type mixup. Could be that the project was not rebuilt completely after the changes. The stacks show different lock function for lock (stacked) and unlock (old style).
>I may have worded it wrong. Actually, I did. The OP’s mistake is most likely the
lock type mixup. Could be that the project was not rebuilt completely after the
changes. The stacks show different lock function for lock (stacked) and unlock
(old style).
Could you, please, point me out to the different lock functions? I’ve changed the code between the message #1 and message #9-10.
This is the code for the second run. The code is in one .c, so I cannot imagine how the compiler could mess-up.
// Locks
typedef KSPIN_LOCK vs_lock_t;
typedef KIRQL vs_lock_context_t;
VS_INLINE
void
vs_init_lock(INOUT vs_lock_t* pLock)
{
KeInitializeSpinLock(pLock);
}
VS_INLINE
void
vs_free_lock(INOUT vs_lock_t* pLock)
{
}
VS_INLINE
void
vs_enter_lock(INOUT vs_lock_t* pLock, IN vs_lock_context_t* pCtx)
{
ASSERT(pLock != NULL);
KeAcquireSpinLock(pLock, pCtx);
}
VS_INLINE
void
vs_leave_lock(INOUT vs_lock_t* pLock, IN vs_lock_context_t* pCtx)
{
ASSERT(pLock != NULL);
KeReleaseSpinLock(pLock, *pCtx);
}
> Could you, please, point me out to the different lock functions?
Would you please rephrase this?
Maybe you meant more than the two different types of lock functions you’ve already tried. There are the ERESOURCE (e.g. ExAcquireResourceExclusiveLite) ones, but you have to be below DISPATCH_LEVEL to use them.
>The stacks show different lock function for lock (stacked) and unlock
(old style).
Sorry, I meant that I do not see different lock and unlock functions in the call stack.
The ~2 thread is not deadlocked. It has successfully acquired the spinlock, and is now performing verifier checks that are supposed to detect problems such out of order acquires which can lead to deadlocks (hence the “VfDeadlock” name).
If you can reproduce this under debugger, try continuing execution to see if the threads eventually make progress.
-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Wednesday, March 02, 2011 2:55 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] Strange re-entrance and deadlock under the spinlock
I’ve checked I?m acquiring the same lock in both cases (fffff980`0edd87b8) that sits in the non-pageable memory. There are basically 2 threads related to the lock ~2 and ~3. ~2 is in the deadlock while ~3 is waiting?
2: kd> !thread
THREAD fffffa8008b46660 Cid 0bb4.0e88 Teb: 000007fffff9a000 Win32Thread: 0000000000000000 RUNNING on processor 2 IRP List:
fffff9800ec48ee0: (0006,0118) Flags: 40060000 Mdl: 00000000 Not impersonating
DeviceMap fffff8a000007bf0
Owning Process fffffa80080af9c0 Image: driver.exe
Attached Process N/A Image: N/A
Wait Start TickCount 583981 Ticks: 0
Context Switch Count 43234
UserTime 00:00:02.106
KernelTime 00:00:08.736
Win32 Start Address 0x000000013f671de0
Stack Init fffff8800c7dfdb0 Current fffff8800c7ded00 Base fffff8800c7e0000 Limit fffff8800c7da000 Call 0 Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Args to Child : Call Site
fffff88001e8c550 ffffffff0000000c 0000000000000000 0000000000000004 : nt!RtlpInterlockedPushEntrySList+0x31
fffffa80069af950 fffffa8008f59f30 0000000000000000 0000000000000005 : nt!ExFreeToNPagedLookasideList+0x27
000000000008e92d fffffa8008a20b80 fffffa80083f1b90 fffffa8009531990 : nt!ViDeadlockFree+0x3a
fffff9800edd87b8 fffff88001e8ca02 0000000000000000 fffff80000000000 : nt!VfDeadlockAcquireResource+0x641
fffff9800e37afb0 fffff9800e350f68 fffff9800e37afb0 fffff88001e8cad0 : nt!VerifierKeAcquireSpinLockRaiseToDpc+0x11f
fffff9800edd87b8 fffff88001e8c6d0 fffffa8008e4b090 fffff88006131946 : Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
fffff9800edd8788 fffff88001e8c6d0 fffff8800613c690 fffff88006141c0d : Filter!list_lock+0x58 [list.c @ 436]
fffff9800edd8788 fffff88006142461 fffff8800614c688 fffff88001e8c728 : Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
fffff9800eefcf70 fffff80003517202 fffff88006a00000 fffff88006a57074 : Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
fffff9800edd8788 fffff9800eefcf90 fffff8800614c688 fffff88001e8c828 : Filter!list_remove_item+0xe5 [list.c @ 603]
fffff9800eefcf90 fffffa80000003f1 fffff88001e8c828 0000000000000000 : Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
fffff9800eefcf90 fffff80000000000 fffffa800000da00 0000000000000000 : Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
fffff9800e350cd0 fffff9800eefcf90 0000000000000000 0000000000000000 : Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
fffffa8008ec6ac0 fffff9800e350ca0 fffff9800e37afb0 fffff9800e350ca0 : Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370] fffff9800e350f6b fffff80000000000 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800e350ca0 00000000ffffff01 fffffa8008521001 0000000000000000 : nt!IopfCompleteRequest+0x3a6 000000000000000c fffff9800cd02e02 0000000000000008 fffffa8008521010 : nt!IovCompleteRequest+0x19f
fffffa80090cdb10 fffffa80090cdb10 fffff88001e8cd60 fffff9800cd02ea0 : CLASSPNP!TransferPktComplete+0x1ce
fffff9800cd02fbb fffff80000000001 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800cd02ea0 fffffa8008506101 fffffa80090cdc01 0000000000000000 : nt!IopfCompleteRequest+0x3a6
fffffa8008becc60 0000000000000000 fffffa8008becc60 fffffa80090cdc30 : nt!IovCompleteRequest+0x19f
0000000000000000 fffff800000000e1 fffff88001e5d180 fffffa8007eb7140 : storport!RaidUnitCompleteRequest+0x1fb
fffff88001e5d180 fffffa8007eb7100 0000000000000000 0000000000000064 : storport!RaidpAdapterRedirectDpcRoutine+0x4e
0000000000000000 fffffa8008b46660 0000000000000000 fffff88000c4e280 : nt!KiRetireDpcList+0x1bc
fffff88006131190 fffffa8009bf4dc1 0000000000000000 fffff8000360fb50 : nt!KxRetireDpcList+0x5 (TrapFrame @ fffff88001e8ce70) 0000000000000000 fffff8800c7df240 000000000000000b fffff8800000000c : nt!KiDispatchInterruptContinue fffff9800edd87b8 fffff88006131208 fffffa8008306000 0000000000000002 : nt!KiDpcInterrupt+0xcc (TrapFrame @ fffff8800c7df120)
0000000000000008 0000000000000008 fffffa8008bc3d20 fffffa8008306090 : nt!VerifierKeReleaseSpinLock+0xd8
fffff9800edd87b8 fffff8800c7df390 fffff8800614c600 fffff9800e28cf70 : Filter!vs_leave_lock+0x58 [list_platform.h @ 97]
fffff9800edd8788 fffff8800c7df390 fffff9805630706c fffff8800c7df3e0 : Filter!list_unlock+0x58 [list.c @ 444]
fffff9800edd8788 fffff8800c7df3e0 fffff9800edd87b0 fffff88006141c0d : Filter!list_int_remove_deleted_items+0x157 [list.c @ 175]
fffff9800edd8788 fffff88006142461 fffff8800614c688 fffff8800c7df438 : Filter!list_int_decrement_pending_ops+0xea [list.c @ 249]
fffff9800e28cf70 fffff80003517200 fffff88006a00000 fffff88006a5701c : Filter!list_int_remove_item_helper+0x176 [list.c @ 360]
fffff9800edd8788 fffff9800e28cf90 fffff8800614c688 fffff8800c7df538 : Filter!list_remove_item+0xe5 [list.c @ 603]
fffff9800e28cf90 fffffa80000003f1 fffff8800c7df538 0000000000000000 : Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
fffff9800e28cf90 fffff98000000000 fffff88000000000 fffff88000004400 : Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
fffffa80095610c0 fffff880000000e6 0000000000000005 0000000000f7e17c : Filter!StartSingleWrite+0x3db [filewritecbk.cpp @ 350]
fffffa80095610c0 0000000002df1be8 0000000000000000 0000000000000000 : Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
0000000000000000 0000000000f7e150 fffff98000000074 000000000c26f7e8 : Filter!OnCommPortMessage+0x4c9 [servicemsg.cpp @ 150]
fffff8800c7df920 000000000c26f701 fffff9800ec48ee0 0000000000000074 : fltmgr!FltpFilterMessage+0xc7
3: kd> !thread
THREAD fffffa8008b44660 Cid 0bb4.041c Teb: 000007fffffa0000 Win32Thread: 0000000000000000 RUNNING on processor 3 IRP List:
fffff9800e104ee0: (0006,0118) Flags: 40060000 Mdl: 00000000 Not impersonating
DeviceMap fffff8a000007bf0
Owning Process fffffa80080af9c0 Image: driver.exe
Attached Process N/A Image: N/A
Wait Start TickCount 583981 Ticks: 0
Context Switch Count 43226
UserTime 00:00:01.716
KernelTime 00:01:06.440
Win32 Start Address 0x000000013f671de0
Stack Init fffff8800c6b2db0 Current fffff8800c6b22b0 Base fffff8800c6b3000 Limit fffff8800c6ad000 Call 0 Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Args to Child : Call Site
fffff9800edd87b8 fffff8800c6b1a70 0000000000000000 fffff8000351758b : nt!KxWaitForSpinLockAndAcquire+0x23
fffff9800ed56fb0 fffff9800e11ef68 fffff9800ed56fb0 fffff8800c6b1a70 : nt!VerifierKeAcquireSpinLockRaiseToDpc+0xb0
fffff9800edd87b8 fffff8800c6b1670 fffff88001ece180 fffff88006131909 : Filter!vs_enter_lock+0x50 [list_platform.h @ 86]
fffff9800edd8788 fffff8800c6b1670 fffff8800613c690 fffff88006141c0d : Filter!list_lock+0x58 [list.c @ 436]
fffff9800edd8788 fffff88006142461 fffff8800614c688 fffff8800c6b16c8 : Filter!list_int_increment_pending_ops+0x5e [list.c @ 214]
fffff9800e0e2f70 fffff80003517202 fffff88006a00000 fffff88006a57048 : Filter!list_int_remove_item_helper+0x13b [list.c @ 356]
fffff9800edd8788 fffff9800e0e2f90 fffff8800614c688 fffff8800c6b17c8 : Filter!list_remove_item+0xe5 [list.c @ 603]
fffff9800e0e2f90 fffffa80000003f1 fffff8800c6b17c8 0000000000000000 : Filter!RemovePendingOp+0x92 [pendinglist.cpp @ 171]
fffff9800e0e2f90 fffff80000000000 fffffa8000009c00 0000000000000000 : Filter!DecrementSubOpNumber+0x551 [pendinglist.cpp @ 332]
fffff9800e11ecd0 fffff9800e0e2f90 0000000000000000 0000000000000000 : Filter!DataSourceWriteCompletion+0x12d [filewritecbk.cpp @ 249]
fffffa8008ec6ac0 fffff9800e11eca0 fffff9800ed56fb0 fffff9800e11eca0 : Filter!IrpCompletion+0x1e4 [datasource.cpp @ 370] fffff9800e11ef6b fffff80000000000 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800e11eca0 00000000ffffff01 fffffa8008521001 0000000000000000 : nt!IopfCompleteRequest+0x3a6
fffff88001ece102 fffff9800cc9ee02 000000000000000a fffffa8008521010 : nt!IovCompleteRequest+0x19f
fffffa80090d6e60 fffffa80090d6e60 fffff8800c6b1d00 fffff9800cc9eea0 : CLASSPNP!TransferPktComplete+0x1ce
fffff9800cc9efbb fffff80000000001 0000000000000000 fffff88000000005 : nt!IovpLocalCompletionRoutine+0x166
fffff9800cc9eea0 fffffa8008506101 fffffa80090d6f01 0000000000000000 : nt!IopfCompleteRequest+0x3a6
fffffa80094d7260 fffffa80090d3b80 fffffa80094d7260 fffffa80090d6f80 : nt!IovCompleteRequest+0x19f
fffffa8000000000 00000000000000c8 fffffa8007d89470 0000000000000001 : storport!RaidUnitCompleteRequest+0x1fb
fffffa80085061b0 fffff9800cdaaf18 000000000000e400 fffffa80085061b0 : storport!RaidCheckPerProcessorCompletions+0x93
fffff8800c6b2001 fffff88000c64110 0000000000030000 0000000000000000 : storport! ?? ::FNODOBFM::string'+0x1f03 fffff9800cdaaea0 0000000000000002 fffffa8008506060 0000000000000000 : storport!RaDriverScsiIrp+0x5d 0000000000000000 0000000000000001 fffffa80090d3a60 fffffa8009abe010 : nt!IovCallDriver+0x566 fffffa8008521010 fffffa8008506060 fffff88000040000 fffff80000000000 : CLASSPNP!ServiceTransferRequest+0x355 fffff9800e1ceca0 0000000000000002 fffffa8008515790 0000000000000002 : CLASSPNP!ClassReadWrite+0xd5 fffff9800e1ceca0 0000000000000002 fffff9800e1cee90 fffffa80095cc0b0 : nt!IovCallDriver+0x566 fffff9800e1ceca0 fffffa8008516040 fffff9800e1cef20 0000000000000000 : partmgr!PmGlobalDispatch+0x9f fffffa8008520c10 0000000000000002 fffff9800e1ceca0 fffffa8008b6d240 : nt!IovCallDriver+0x566 0000000000000002 fffffa80098739a0 fffff9800e1ceca0 0000000000000001 : volmgr!VmReadWrite+0x11c fffff9800e1ceca0 0000000000000002 fffff9800e1cef20 fffffa80098739a0 : nt!IovCallDriver+0x566 0000000000000002 fffffa8008535040 0000000000000000 fffffa80094e99c0 : volsnap!VolsnapWriteFilter+0xf8 fffff9800e1cef68 fffff9800e1ceca0 fffffa8008a9de50 fffffa8008f73500 : nt!IovCallDriver+0x566 0000000000000000 0000000000000002 fffff9800e1ceca0 fffff880012c76af : nt!RawReadWriteDeviceControl+0xa8 fffff9800e1ceca0 fffffa8008a9dd00 fffffa80093859a0 0000000000000000 : nt!RawDispatch+0x7d fffffa8008ec6ac0 0000000000000002 fffffa8008ec6ac0 fffffa80093859a0 : nt!IovCallDriver+0x566 fffff9800e1ceca0 0000000000000002 fffff9800e1ceca0 fffff80003524b80 : fltmgr!FltpDispatch+0x9f 0000000000000008 fffffa8008bc3d20 fffffa8008306090 fffffa80094e99c0 : nt!IovCallDriver+0x566 fffffa8009078bd0 fffff980074aaf00 fffff8800c6b25f8 fffff8800000e400 : Filter!WriteToDestinationSingle+0x3ba [datasource.cpp @ 749] fffffa8007bcea70 fffff880000000e6 0000000000000005 0000000000f7e47c : Filter!StartSingleWrite+0x3b0 [filewritecbk.cpp @ 340] fffffa8007bcea70 0000000002deefe8 0000000000000000 fffff800`00000000 : Filter!CompleteWriteOp+0x306 [filewritecbk.cpp @ 529]
NTDEV is sponsored by OSR
For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars
To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer
Sorry, I was mistaken about spinlock mixing.
How many spinlocks you’re using?
Are you ever holding multiple locks? If yes, do you make sure to follow the same acquisition order (lock hierarchy)?
Are you ever calling IoCompleteRequest or IoCallDriver while holding a spinlock?
Thank you all, and especially Pavel.
It was a stupid mistake on my side (as expected). I was stalling execution for about 20ms on dispatch level.