WdfObjectAcquireLock race-condition on Windows 7

OSR_Community_User · March 3, 2010, 1:09pm

I am currently encountering a race-condition with a KMDF (1.7) USB driver on Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are running code in my driver: Proc0 is running my DPC (EvtDataReadComplete) which is calling WdfObjectAcquireLock. Proc 1 is running my EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock itself or the lock has already been acquired elsewhere so both of these Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1
8078addc 81fa8317 Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62
…

Can I determine the current state of the device lock and, if it is already locked, anymore about where it was locked etc.?

Thanks

Will

Doron_Holan · March 3, 2010, 1:25pm

I wouldn’t call this a race condition, this is either a dropped release or someone is holding on to the lock for too long. Any reason you are using the object’s lock instead of a WDFSPINLOCK that you allocate? If you use your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a history of acquires and releases (visible via !wdfkd.wdfspinlock) that may help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are running code in my driver: Proc0 is running my DPC (EvtDataReadComplete) which is calling WdfObjectAcquireLock. Proc 1 is running my EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock itself or the lock has already been acquired elsewhere so both of these Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317 Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already locked, anymore about where it was locked etc.?

Thanks

Will

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

Gary_Little-3 · March 3, 2010, 3:08pm

Windows 7 is WDF 1.9, but you say you are testing a driver, I assume built
with 1.7. Can you rebuild the driver with 1.9 and re-test?

Gary G. Little
H (952) 223-1349
C (952) 454-4629
xxxxx@comcast.net

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 12:11 PM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on
Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my
WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are
running code in my driver: Proc0 is running my DPC (EvtDataReadComplete)
which is calling WdfObjectAcquireLock. Proc 1 is running my
EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for
the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock
itself or the lock has already been acquired elsewhere so both of these
Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1
8078addc 81fa8317
Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62
…

Can I determine the current state of the device lock and, if it is already
locked, anymore about where it was locked etc.?

Thanks

Will

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

__________ Information from ESET Smart Security, version of virus signature
database 4913 (20100303) __________

The message was checked by ESET Smart Security.

http://www.eset.com

__________ Information from ESET Smart Security, version of virus signature
database 4913 (20100303) __________

The message was checked by ESET Smart Security.

http://www.eset.com

OSR_Community_User · March 3, 2010, 3:52pm

> Any reason you are using the object’s lock instead of a WDFSPINLOCK that you allocate?

Seemed to be suitable at the time. I will try changing to my own WDFSPINLOCK

I assume built with 1.7.

Yep

Can you rebuild the driver with 1.9 and re-test?

That is certainly the plan - I just wanted to ensure that I got as much out of the current dump/test that I could lest the problem just “goes away” when I switch to 1.9

BTW - which tmf should be I be using if I run a driver built with *1.7* on Windows 7 (i.e. 1.9)? I’m not getting 100% consistent or successful log dumps at the moment (i.e. using wdflogdump) - wdf01009.tmf I assume? This results in more items being decoded but even with that it doesn’t always decode the driver’s entries - for example I often get:

Unknown( 14): GUID=31f474a8-23f3-c270-e156-7b455a6f635c (No Format Information found).
Unknown( 14): GUID=d816b6e3-c6ba-363d-54b4-3533d1de16bb (No Format Information found).
Unknown( 14): GUID=31f474a8-23f3-c270-e156-7b455a6f635c (No Format Information found).
Unknown( 14): GUID=31f474a8-23f3-c270-e156-7b455a6f635c (No Format Information found).
5: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 7AD87828 state, sending WDFREQUEST 89043580, state WdfIoTargetStarted
Unknown( 14): GUID=1c6af04a-8c20-a063-1976-7299d70a2744 (No Format Information found).
7: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x7AF93FF8 !devobj 0x8506DD30 entering power idle state FxIdleStarted from FxIdleStopped
Unknown( 15): GUID=9fad61e3-68ff-f42e-15fe-7a3fb252225e (No Format Information found).
Unknown( 15): GUID=9fad61e3-68ff-f42e-15fe-7a3fb252225e (No Format Information found).

Alex_Grig · March 3, 2010, 4:40pm

By any chance, does framework call those callbacks while holding the object
lock? Could that be that the OP is trying to acquire the lock in the
callback which is already held by the framework?

“Doron Holan” wrote in message
news:xxxxx@ntdev…
I wouldn’t call this a race condition, this is either a dropped release or
someone is holding on to the lock for too long. Any reason you are using
the object’s lock instead of a WDFSPINLOCK that you allocate? If you use
your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a
history of acquires and releases (visible via !wdfkd.wdfspinlock) that may
help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on
Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my
WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are
running code in my driver: Proc0 is running my DPC (EvtDataReadComplete)
which is calling WdfObjectAcquireLock. Proc 1 is running my
EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for
the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock
itself or the lock has already been acquired elsewhere so both of these
Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317
Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already
locked, anymore about where it was locked etc.?

Thanks

Will

—
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

Doron_Holan · March 3, 2010, 5:37pm

Caveat: this is one of the areas of KMDF I was never fully comfortable or knowedgable about. Depending on the sync scope you ask for, KMDF will hold a lock while making a call into the DPC. It will not acquire any lock on calling the preprocess callback. The lock acquired when calling the is the same lock as the one acquired by WdfObjectAcqireLock depending on the sync scope. But if he were acquiring the lock that was held before invoking the DPC, the DPC acquiring the lock would have never worked and would have deadlocked.

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 1:40 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] WdfObjectAcquireLock race-condition on Windows 7

By any chance, does framework call those callbacks while holding the object lock? Could that be that the OP is trying to acquire the lock in the callback which is already held by the framework?

“Doron Holan” wrote in message news:xxxxx@ntdev…
I wouldn’t call this a race condition, this is either a dropped release or someone is holding on to the lock for too long. Any reason you are using the object’s lock instead of a WDFSPINLOCK that you allocate? If you use your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a history of acquires and releases (visible via !wdfkd.wdfspinlock) that may help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are running code in my driver: Proc0 is running my DPC (EvtDataReadComplete) which is calling WdfObjectAcquireLock. Proc 1 is running my EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock itself or the lock has already been acquired elsewhere so both of these Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317 Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already locked, anymore about where it was locked etc.?

Thanks

Will

—
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

—
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

Doron_Holan · March 3, 2010, 6:18pm

On win7, you are using v1.9 even if you bound to v1.7. as such wdf01009.tmf is the right file. Are you using the TMF file from the RTM WDK?

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 12:53 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] WdfObjectAcquireLock race-condition on Windows 7

Any reason you are using the object’s lock instead of a WDFSPINLOCK that you allocate?

Seemed to be suitable at the time. I will try changing to my own WDFSPINLOCK

I assume built with 1.7.

Yep

Can you rebuild the driver with 1.9 and re-test?

That is certainly the plan - I just wanted to ensure that I got as much out of the current dump/test that I could lest the problem just “goes away” when I switch to 1.9

BTW - which tmf should be I be using if I run a driver built with *1.7* on Windows 7 (i.e. 1.9)? I’m not getting 100% consistent or successful log dumps at the moment (i.e. using wdflogdump) - wdf01009.tmf I assume? This results in more items being decoded but even with that it doesn’t always decode the driver’s entries - for example I often get:

Unknown( 14): GUID=31f474a8-23f3-c270-e156-7b455a6f635c (No Format Information found).
Unknown( 14): GUID=d816b6e3-c6ba-363d-54b4-3533d1de16bb (No Format Information found).
Unknown( 14): GUID=31f474a8-23f3-c270-e156-7b455a6f635c (No Format Information found).
Unknown( 14): GUID=31f474a8-23f3-c270-e156-7b455a6f635c (No Format Information found).
5: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 7AD87828 state, sending WDFREQUEST 89043580, state WdfIoTargetStarted Unknown( 14): GUID=1c6af04a-8c20-a063-1976-7299d70a2744 (No Format Information found).
7: FxPowerIdleMachine::ProcessEventLocked - WDFDEVICE 0x7AF93FF8 !devobj 0x8506DD30 entering power idle state FxIdleStarted from FxIdleStopped Unknown( 15): GUID=9fad61e3-68ff-f42e-15fe-7a3fb252225e (No Format Information found).
Unknown( 15): GUID=9fad61e3-68ff-f42e-15fe-7a3fb252225e (No Format Information found).

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

Alex_Grig · March 3, 2010, 6:33pm

So OP’s DPC callback EvtDataReadComplete may be called with the lock held,
and he’s trying to acquire the lock recursively?

Does driver verifier detect recursive spinlock acquisition? It should be
really easy to implement (rather than set the DPC to 1, set it to the
current processor number+1).

“Doron Holan” wrote in message
news:xxxxx@ntdev…
Caveat: this is one of the areas of KMDF I was never fully comfortable or
knowedgable about. Depending on the sync scope you ask for, KMDF will hold
a lock while making a call into the DPC. It will not acquire any lock on
calling the preprocess callback. The lock acquired when calling the is the
same lock as the one acquired by WdfObjectAcqireLock depending on the sync
scope. But if he were acquiring the lock that was held before invoking the
DPC, the DPC acquiring the lock would have never worked and would have
deadlocked.

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 1:40 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] WdfObjectAcquireLock race-condition on Windows 7

By any chance, does framework call those callbacks while holding the object
lock? Could that be that the OP is trying to acquire the lock in the
callback which is already held by the framework?

“Doron Holan” wrote in message
news:xxxxx@ntdev…
I wouldn’t call this a race condition, this is either a dropped release or
someone is holding on to the lock for too long. Any reason you are using
the object’s lock instead of a WDFSPINLOCK that you allocate? If you use
your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a
history of acquires and releases (visible via !wdfkd.wdfspinlock) that may
help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on
Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my
WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are
running code in my driver: Proc0 is running my DPC (EvtDataReadComplete)
which is calling WdfObjectAcquireLock. Proc 1 is running my
EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for
the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock
itself or the lock has already been acquired elsewhere so both of these
Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317
Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already
locked, anymore about where it was locked etc.?

Thanks

Will

—
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

—
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

Doron_Holan · March 3, 2010, 6:38pm

Yes, DV finds that. My point was if he was doing that, his driver would have not worked on any MP machine with or without DV. It might have worked on a UP machine since the spinlock semantics are a little different between the 2

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 3:33 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] Re:WdfObjectAcquireLock race-condition on Windows 7

So OP’s DPC callback EvtDataReadComplete may be called with the lock held, and he’s trying to acquire the lock recursively?

Does driver verifier detect recursive spinlock acquisition? It should be really easy to implement (rather than set the DPC to 1, set it to the current processor number+1).

“Doron Holan” wrote in message news:xxxxx@ntdev…
Caveat: this is one of the areas of KMDF I was never fully comfortable or knowedgable about. Depending on the sync scope you ask for, KMDF will hold a lock while making a call into the DPC. It will not acquire any lock on calling the preprocess callback. The lock acquired when calling the is the same lock as the one acquired by WdfObjectAcqireLock depending on the sync scope. But if he were acquiring the lock that was held before invoking the DPC, the DPC acquiring the lock would have never worked and would have deadlocked.

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 1:40 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] WdfObjectAcquireLock race-condition on Windows 7

By any chance, does framework call those callbacks while holding the object lock? Could that be that the OP is trying to acquire the lock in the callback which is already held by the framework?

“Doron Holan” wrote in message news:xxxxx@ntdev…
I wouldn’t call this a race condition, this is either a dropped release or someone is holding on to the lock for too long. Any reason you are using the object’s lock instead of a WDFSPINLOCK that you allocate? If you use your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a history of acquires and releases (visible via !wdfkd.wdfspinlock) that may help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are running code in my driver: Proc0 is running my DPC (EvtDataReadComplete) which is calling WdfObjectAcquireLock. Proc 1 is running my EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock itself or the lock has already been acquired elsewhere so both of these Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317 Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already locked, anymore about where it was locked etc.?

Thanks

Will

—
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

—
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

—
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

Alex_Grig · March 3, 2010, 11:25pm

I thought UP kernel is not shipped anymore (Since Win 6.1?)

“Doron Holan” wrote in message
news:xxxxx@ntdev…
Yes, DV finds that. My point was if he was doing that, his driver would
have not worked on any MP machine with or without DV. It might have worked
on a UP machine since the spinlock semantics are a little different between
the 2

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 3:33 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] Re:WdfObjectAcquireLock race-condition on Windows 7

So OP’s DPC callback EvtDataReadComplete may be called with the lock held,
and he’s trying to acquire the lock recursively?

Does driver verifier detect recursive spinlock acquisition? It should be
really easy to implement (rather than set the DPC to 1, set it to the
current processor number+1).

“Doron Holan” wrote in message
news:xxxxx@ntdev…
Caveat: this is one of the areas of KMDF I was never fully comfortable or
knowedgable about. Depending on the sync scope you ask for, KMDF will hold
a lock while making a call into the DPC. It will not acquire any lock on
calling the preprocess callback. The lock acquired when calling the is the
same lock as the one acquired by WdfObjectAcqireLock depending on the sync
scope. But if he were acquiring the lock that was held before invoking the
DPC, the DPC acquiring the lock would have never worked and would have
deadlocked.

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 1:40 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] WdfObjectAcquireLock race-condition on Windows 7

By any chance, does framework call those callbacks while holding the object
lock? Could that be that the OP is trying to acquire the lock in the
callback which is already held by the framework?

“Doron Holan” wrote in message
news:xxxxx@ntdev…
I wouldn’t call this a race condition, this is either a dropped release or
someone is holding on to the lock for too long. Any reason you are using
the object’s lock instead of a WDFSPINLOCK that you allocate? If you use
your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a
history of acquires and releases (visible via !wdfkd.wdfspinlock) that may
help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of
xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on
Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my
WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are
running code in my driver: Proc0 is running my DPC (EvtDataReadComplete)
which is calling WdfObjectAcquireLock. Proc 1 is running my
EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for
the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock
itself or the lock has already been acquired elsewhere so both of these
Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317
Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already
locked, anymore about where it was locked etc.?

Thanks

Will

—
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

—
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

—
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

Doron_Holan · March 4, 2010, 1:08am

Correct. The post was not about which OS supports UP or not, rather how on UP you can get away with recursively acquiring a spinlock (incorrectly) while on MP you can’t and that might be one of the differences in his it works here but not there scenarios

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 8:25 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] Re:Re:WdfObjectAcquireLock race-condition on Windows 7

I thought UP kernel is not shipped anymore (Since Win 6.1?)

“Doron Holan” wrote in message news:xxxxx@ntdev…
Yes, DV finds that. My point was if he was doing that, his driver would have not worked on any MP machine with or without DV. It might have worked on a UP machine since the spinlock semantics are a little different between the 2

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 3:33 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] Re:WdfObjectAcquireLock race-condition on Windows 7

So OP’s DPC callback EvtDataReadComplete may be called with the lock held, and he’s trying to acquire the lock recursively?

Does driver verifier detect recursive spinlock acquisition? It should be really easy to implement (rather than set the DPC to 1, set it to the current processor number+1).

“Doron Holan” wrote in message news:xxxxx@ntdev…
Caveat: this is one of the areas of KMDF I was never fully comfortable or knowedgable about. Depending on the sync scope you ask for, KMDF will hold a lock while making a call into the DPC. It will not acquire any lock on calling the preprocess callback. The lock acquired when calling the is the same lock as the one acquired by WdfObjectAcqireLock depending on the sync scope. But if he were acquiring the lock that was held before invoking the DPC, the DPC acquiring the lock would have never worked and would have deadlocked.

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 1:40 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] WdfObjectAcquireLock race-condition on Windows 7

By any chance, does framework call those callbacks while holding the object lock? Could that be that the OP is trying to acquire the lock in the callback which is already held by the framework?

“Doron Holan” wrote in message news:xxxxx@ntdev…
I wouldn’t call this a race condition, this is either a dropped release or someone is holding on to the lock for too long. Any reason you are using the object’s lock instead of a WDFSPINLOCK that you allocate? If you use your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a history of acquires and releases (visible via !wdfkd.wdfspinlock) that may help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are running code in my driver: Proc0 is running my DPC (EvtDataReadComplete) which is calling WdfObjectAcquireLock. Proc 1 is running my EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock itself or the lock has already been acquired elsewhere so both of these Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317 Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already locked, anymore about where it was locked etc.?

Thanks

Will

—
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

—
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

—
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

—
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

OSR_Community_User · March 4, 2010, 6:34am

Thanks for the feedback everyone

Depending on the sync scope you ask for

I’m using WdfSynchronizationScopeNone

Are you using the TMF file from the RTM WDK?

Ah - I thought I was - but it would appear not! - fixed- thanks

…his driver would have not worked on any MP machine with or without DV

Normally run on MP - never encountered a problem acquiring the lock in the DPC before - so I assume the lock is not held by the framework while the DPC is called (and I would not expect it to be given the configured scope)

dropped release

I’ve checked very carefully for that and not found anything (yet) but in that analysis can I assume that if the acquire was actually being called twice then that itself would always cause an exception? - similarly if release was called without an acquire? i.e. can I exclude these as possibilities in this particular instance given the fact that the exception I’m actually getting is a DPC timeout due to the acquire never completing.

OSR_Community_User · March 4, 2010, 3:50pm

Framework doesn’t hold a lock while calling continuous reader’s EvtDataReadComplete (similarly for request completion callback), exactly to avoid potential deadlocks.

The callbacks for which the automatic synchronization applies are described in the link below:

http://msdn.microsoft.com/en-us/library/aa490059.aspx

Automatic serialization is the only purpose for which fx uses callback locks (and not for its own internal synchronization, and thus there is no danger that fx is holding the lock for its own purpose).

OP can please check if code of any of the callbacks mentioned in the link above leaks the lock. Or the thread holding the device lock (assuming the lock below is device object lock) may be blocked on something.

For the first case please check the code and/or use the tracking Doron mentioned below. For the second case please use !stacks with in the filter string to see if anything pops up.

HTH,
Praveen

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Doron Holan
Sent: Wednesday, March 03, 2010 10:06 PM
To: Windows System Software Devs Interest List
Subject: RE: Re:[ntdev] Re:Re:WdfObjectAcquireLock race-condition on Windows 7

Correct. The post was not about which OS supports UP or not, rather how on UP you can get away with recursively acquiring a spinlock (incorrectly) while on MP you can’t and that might be one of the differences in his it works here but not there scenarios

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 8:25 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] Re:Re:WdfObjectAcquireLock race-condition on Windows 7

I thought UP kernel is not shipped anymore (Since Win 6.1?)

“Doron Holan” wrote in message news:xxxxx@ntdev…
Yes, DV finds that. My point was if he was doing that, his driver would have not worked on any MP machine with or without DV. It might have worked on a UP machine since the spinlock semantics are a little different between the 2

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 3:33 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] Re:WdfObjectAcquireLock race-condition on Windows 7

So OP’s DPC callback EvtDataReadComplete may be called with the lock held, and he’s trying to acquire the lock recursively?

Does driver verifier detect recursive spinlock acquisition? It should be really easy to implement (rather than set the DPC to 1, set it to the current processor number+1).

“Doron Holan” wrote in message news:xxxxx@ntdev…
Caveat: this is one of the areas of KMDF I was never fully comfortable or knowedgable about. Depending on the sync scope you ask for, KMDF will hold a lock while making a call into the DPC. It will not acquire any lock on calling the preprocess callback. The lock acquired when calling the is the same lock as the one acquired by WdfObjectAcqireLock depending on the sync scope. But if he were acquiring the lock that was held before invoking the DPC, the DPC acquiring the lock would have never worked and would have deadlocked.

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Alexander Grigoriev
Sent: Wednesday, March 03, 2010 1:40 PM
To: Windows System Software Devs Interest List
Subject: Re:[ntdev] WdfObjectAcquireLock race-condition on Windows 7

By any chance, does framework call those callbacks while holding the object lock? Could that be that the OP is trying to acquire the lock in the callback which is already held by the framework?

“Doron Holan” wrote in message news:xxxxx@ntdev…
I wouldn’t call this a race condition, this is either a dropped release or someone is holding on to the lock for too long. Any reason you are using the object’s lock instead of a WDFSPINLOCK that you allocate? If you use your own WDFSPINLOCK and enable KMDF verifier, the wdfspinlock will keep a history of acquires and releases (visible via !wdfkd.wdfspinlock) that may help debug this

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@farsite.co.uk
Sent: Wednesday, March 03, 2010 10:11 AM
To: Windows System Software Devs Interest List
Subject: [ntdev] WdfObjectAcquireLock race-condition on Windows 7

I am currently encountering a race-condition with a KMDF (1.7) USB driver on Windows 7. Not seen this before on Vista,XP etc.
Note sure if it is down to some difference in Win7? I have 2 instances of my WDF device running at the same time.

Firstly - any ideas as to how to get more out of this dump - both procs are running code in my driver: Proc0 is running my DPC (EvtDataReadComplete) which is calling WdfObjectAcquireLock. Proc 1 is running my EvtWdfDeviceWdmIrpPreprocess which is also calling WdfObjectAcquireLock (for the same device as Proc0.

I’m getting a

Assertion: *** DPC execution time exceeds system limit
This is NOT a break in update time
This is a BUG in a DPC routine
Perform a stack trace to find the culprit
The time out limit will be doubled on continuation
Use gh to continue!!

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

DPC_RUNTIME: 283

DPC_TIME_LIMIT: 282

presumably due to my DPC blocking on its call to WdfObjectAcquireLock

Presumably this is either a race-condition within WdfObjectAcquireLock itself or the lock has already been acquired elsewhere so both of these Procs are blocked.

1: kd> !running -t

System Processors: (00000003)
Idle Processors: (00000000)

Prcbs Current Next
0 81945d20 83aa1d48 …

ChildEBP RetAddr
8078ac28 81887342 nt!KeAccumulateTicks+0x316
8078ac68 818871ef nt!KeUpdateRunTime+0x145
8078acc4 8188c577 nt!KeUpdateSystemTime+0x613
8078acc4 81c2f74f nt!KeUpdateSystemTimeAssist+0x13
8078ad48 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x3f
8078ad58 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
8078ad74 88539e73 Wdf01000!imp_WdfObjectAcquireLock+0xc1
8078adb0 81f93ea5 EvtDataReadComplete+0xf1 8078addc 81fa8317 Wdf01000!FxUsbPipeContinuousReader::_FxUsbPipeRequestComplete+0x3c
8078ae08 81f8cc36 Wdf01000!FxRequestBase::CompleteSubmitted+0xf6
8078ae24 81f8ccde Wdf01000!FxIoTarget::RequestCompletionRoutine+0x12d
8078ae34 818a5896 Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
8078ae5c 81884b33 nt!IopUnloadSafeCompletion+0x45
8078aea0 8b7b3868 nt!IopfCompleteRequest+0x128
8078aed0 8b7b4178 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x6e0
8078aefc 8b7b79af USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
8078af24 8b7b1d18 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
8078af48 818843b5 USBPORT!USBPORT_Xdpc_Worker+0x173
8078afa4 81884218 nt!KiExecuteAllDpcs+0xf9
8078aff4 818839dc nt!KiRetireDpcList+0xd5
8078aff8 89073b10 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
818839dc 00000000 0x89073b10

1 807ea120 85692158 …

ChildEBP RetAddr
95f20a10 81fa8a72 hal!KeAcquireSpinLockRaiseToSynch+0x39
95f20a20 81fc28c4 Wdf01000!FxCallbackSpinLock::Lock+0x55
95f20a3c 88536898 Wdf01000!imp_WdfObjectAcquireLock+0xc1
95f20a7c 81fa72c7 EvtWdfDeviceWdmIrpPreprocess+0x62 …

Can I determine the current state of the device lock and, if it is already locked, anymore about where it was locked etc.?

Thanks

Will

—
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

—
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

—
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

—
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

—
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

OSR_Community_User · March 4, 2010, 5:01pm

Fantasic “!stacks with ” got it! - a 3rd thread blocked in a call to EvtWdfDeviceWdmIrpPreprocess whilst holding the lock
Thanks very much indeed for your help