NDIS OID handling, ndisMDispatchReceiveNetBufferListsWithLock- DPC_WATCHDOG_VIOLATION

Hi

This is in Win8 x64.

I see below bugcheck when my protocol is trying to make an OID call (using the same thread that NDIS used to indicate an NBL to my miniport).

  1. I will next run with verifier

  2. Also I see a lock version of ndis in ndisMDispatchReceiveNetBufferListsWithLock.
    Not sure if this is the same lock that NDIS is spinning on when I make the OID call?
    Anyways will try to issue the OID from a PASSIVE worker thread to see if that ‘workarounds’ the problem.

  3. See miniport OID state as well.
    I guess NDIS serializes OIDs at the miniport; i.e. if the first
    OID is stuck, we won’t get a better response by queuing another OID behind the
    first.
    But from protocol I do not know if a miniport is in such state.
    Looking into miniport as well to see what below OID dump means, is any OID stuck or just processing normally.

  4. Also there seems to be standard MS filter between my protocol and miniport.
    Not sure what it means here. Will try disabling that as well?


ALL PENDING OIDs

Miniport fffffa80187d41a0 - NIC1
Current OID OID_TCP_OFFLOAD_PARAMETERS
Queued OIDs OID_GEN_MEDIA_CONNECT_STATUS
Filter fffffa8010b74c80 - NIC1-WFP Native MAC Layer LightWeight Filter-0000
Current OID OID_TCP_OFFLOAD_PARAMETERS
Filter fffffa800e2fcbf0 - NIC1-QoS Packet Scheduler-0000
Current OID OID_TCP_OFFLOAD_PARAMETERS
Queued OIDs OID_GEN_STATISTICS


DPC_WATCHDOG_VIOLATION (133)
The DPC watchdog detected a prolonged run time at an IRQL of DISPATCH_LEVEL
or above.
Arguments:
Arg1: 0000000000000000, A single DPC or ISR exceeded its time allotment. The offending
component can usually be identified with a stack trace.
Arg2: 0000000000000283, The DPC time count (in ticks).
Arg3: 0000000000000282, The DPC time allotment (in ticks).
Arg4: 0000000000000000

Stack is below

fffff80215d53ca8 fffff80215fd881e : 0000000000000133 0000000000000000 0000000000000283 0000000000000282 : nt!KeBugCheckEx
fffff80215d53cb0 fffff80215e7dc31 : fffffa800e96c000 fffff802160f6180 fffff80215d53e60 fffff78000000320 : nt! ?? ::FNODOBFM::string'+0x14488 fffff80215d53d30 fffff80215e781d9 : ffffffffffd10270 ffffffffffd10270 fffff80216591502 fffff80215d53f80 : nt!KeUpdateRunTime+0x51 fffff80215d53d60 fffff80216567cae : ffffffffffd10270 fffff80216591502 fffffa800764b9c0 fffffa800b9db200 : nt!KeUpdateTime+0x3e9 fffff80215d53f50 fffff80215e48ed7 : 00000000c4d02b60 000000004fdbff90 fffff80216591580 0000000000000000 : hal!HalpTimerClockInterrupt+0x86 fffff80215d53f80 fffff80215ef2db0 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiInterruptDispatchNoLockNoEtw+0x1a7 fffff80215d54110 fffff80215e80fe5 : 0000000000000002 0000000000000000 fffffa8011072534 0000000000000000 : nt!KxWaitForSpinLockAndAcquire+0x20 fffff80215d54140 fffff88001494c60 : fffffa8007c66000 0000002000000001 fffffa800b9db1a0 0000000000000000 : nt!KeAcquireSpinLockRaiseToDpc+0x35 fffff80215d54170 fffff880014968d8 : fffffa800e96c001 0000000000000000 fffffa800b9db1a0 000000000000ffff : NDIS!ndisQueueOidRequest+0x60 fffff80215d541e0 fffff88007fe0dea : fffff80215e09000 00000000ffffffff fffffa8010d9cf80 00000000`00000001 : NDIS!ndisMOidRequest+0xc4

fffff80215d542d0 fffff88007fdfe96 : 0000000000000000 fffffa8011072534 00000000ff0207e3 0000000000000001 : my_protocol!nprotOIDRequest+0x296
fffff80215d546d0 fffff88001493eec : fffffa800e96c000 0000000000000000 fffffa800b9db1a0 fffff88000000001 : my_protocol!ProtocolReceiveNetBufferLists+0x67c

fffff80215d547a0 fffff880014ac3bc : 0000000000000002 0000000000000000 fffffa8000000000 fffffa8000000001 : NDIS!ndisMIndicateNetBufferListsToOpen+0x11c
fffff80215d54840 fffff88001493d98 : fffffa800b9db1a0 fffffa800b9db1a0 fffffa801663ec20 fffffa800b9db1a0 : NDIS!ndisMDispatchReceiveNetBufferListsWithLock+0x238
fffff80215d548d0 fffff88001494085 : fffffa800b9db1a0 0000000000000000 0000000000000801 0000000000000000 : NDIS!ndisInvokeNextReceiveHandler+0x7f8
fffff80215d54990 fffff8800a8dea1a : fffffa800b2fc000 fffffa800b9db1a0 fffffa80164f7810 0000000000000801 : NDIS!NdisMIndicateReceiveNetBufferLists+0xc5

fffff80215d54a10 fffff8800a8df49e : 0000000000000000 0000000000000001 0000000000000001 0000000000000001 : my_miniport!IndicateNBLs+0x14a

fffff80215d54c80 fffff8800149353e : fffffa800b2570e8 00000000ffffffff fffffa800b256000 0000000000000000 : NDIS!ndisMiniportDpc+0xfe
fffff80215d54d20 fffff80215e753fc : fffff802160f6180 fffff80215d54eb0 0000000000000000 0000000000000000 : NDIS!ndisInterruptDpc+0x9e
fffff80215d54db0 fffff80215e74cb5 : 0000000000000000 fffff802160f6180 fffff802160f9520 fffffa80176a0b00 : nt!KiRetireDpcList+0x20c
fffff80215d54fb0 fffff80215e74ab9 : 0000000000000000 0000000000000000 0000000000000000 fffff80215e7c3ee : nt!KxRetireDpcList+0x5
fffff880058fc980 fffff80215f3be88 : ffff17e7f74f9803 0000000000000000 0000000000000006 0000000000000000 : nt!KiDispatchInterruptContinue
fffff880058fc9b0 fffff80215e7704c : 0000000000000000 0000000000000000 fffffa800cbca240 fffff80200000000 : nt!KiDpcInterrupt+0xc8
fffff880058fcb40 fffff80215e788e0 : fffff80215e5f5c5 fffff80216088b40 0000000000000000 fffffa8017adc440 : nt!KiCommitThreadWait+0x25c
fffff880058fcc00 fffff80215e81cb2 : fffff80216088c50 fffffa80176a0b00 fffff80215eaa600 fffffa800c762000 : nt!KeRemoveQueueEx+0x290
fffff880058fccb0 fffff80215e31ec9 : 0000000000000000 fffffa80176a0b00 0000000000000080 0000000080010000 : nt!ExpWorkerThread+0x102
fffff880058fcd50 fffff80215e34386 : fffff880022d6180 fffffa80176a0b00 fffff880022e2540 fffffa8006a1d200 : nt!PspSystemThreadStartup+0x59
fffff880058fcda0 0000000000000000 : fffff880058fd000 fffff880058f7000 0000000000000000 0000000000000000 : nt!KiStartSystemThread+0x16

What NdisBindingHandle you’re sending the OID to?

Hi

I send all my oids to BindingHandle I got from NdisOpenAdapterEx

Thanks.

Are you sending them to my_miniport driver?

Yes that is correct.
(I have INF stuff in my_miniport and my_protocol which makes my_protocol only boundable to my_miniport)

Looks like the miniport spinlock is taken, and NDIS is trying to take it again.

I see below in OID state.

About REQUEST_TIMEOUT flag I see below at MS link
http://blogs.msdn.com/b/ndis/archive/2010/08/18/debugging-with-ndiskd.aspx

If I am interpreting above link correct, looks like OID_ TCP_ OFFLOAD__PARAMETERS is taking long time (and NDIS will issue a **RESET** soon).
But not sure how that resulted in a DPC_WATCHDOG_VIOLATION BSOD.

Debuuging more and will update.

Thx


NIC1

Ndis handle fffffa80187d41a0
Ndis API version v6.30
Adapter context fffffa8018800000
Miniport driver fffffa800b489bc0 - my_miniport v0.0
Network interface fffffa80071faa50

Media type 802.3

AUTOMATIC DIAGNOSTICS

This miniport will operate in a slow path until 9 more protocol(s) bind, or
until a 30-second timeout expires.

STATE

Miniport Running
Device PnP Started Show state history
Datapath Normal
Interface Up
Media Connected
Power D0
References 0n15 Show detail
User handles 1
Total resets 0
Pending OID OID_TCP_OFFLOAD_PARAMETERS
Flags BUS_MASTER, 64BIT_DMA, SG_DMA, DEFAULT_PORT_ACTIVATED,
SUPPORTS_MEDIA_SENSE, DOES_NOT_DO_LOOPBACK,
MEDIA_CONNECTED
PnP flags PM_SUPPORTED, DEVICE_POWER_ENABLED, RECEIVED_START,
HARDWARE_DEVICE
More flags PROCESSING_REQUEST, REQUEST_TIMEOUT

RUn it with deadlock detection enabled in the Driver Verifier for NDIS.SYS and for your drivers.

Hi

This issue repro rate is very rare.
From problem reprot it seems this happens only after fresh ghost and during the first install after that.

Have made a change to send my OID from a passive thread (but due to above difficult repro, doesn’t mean anything if it doesn’t reprobut I guess atleast means sending OID down from a dispatch level thread is not excasbeating the issue.)

Will also do verifier on suggested components.

>Looks like the miniport spinlock is taken, and NDIS is trying to take it again.<<
Pls can you eloborate on this ‘miniport lock’.
Is it anything like below
“there is a per miniport slock that ndis creates. NDIS took it as part of pkt indication to my_protocol. Then when my_protocol made the OID call in that same thread context, NDIS tried to take that same miniport_lock?..”

Thx

Below is stack on rest of procs.
NDIS is all over the place and top of stack is a spinlock

Child-SP RetAddr Call Site
fffff8800591c540 fffff80215e80fe5 nt!KxWaitForSpinLockAndAcquire+0x20
fffff8800591c570 fffff88001499d27 nt!KeAcquireSpinLockRaiseToDpc+0x35
fffff8800591c5a0 fffff880015990f8 NDIS!ndisNsiGetAllInterfaceInformation+0x97
fffff8800591c660 fffff88005e8d98a NETIO!NsiGetAllParametersEx+0x230
fffff8800591c770 fffff88005e8f7fa nsiproxy!NsippGetAllParameters+0x29e
fffff8800591c960 fffff88005e8f8d3 nsiproxy!NsippDispatchDeviceControl+0x92
fffff8800591c9a0 fffff802161f63dc nsiproxy!NsippDispatch+0x4b
fffff8800591c9d0 fffff80216240116 nt!IopXxxControlFile+0x7fa
fffff8800591cb60 fffff80215e4e353 nt!NtDeviceIoControlFile+0x56
fffff8800591cbd0 000007feac522e5a nt!KiSystemServiceCopyEnd+0x13
000000ea1010ed88 0000000000000000 0x000007feac522e5a 9: kd\> ~8 8: kd\> k Child-SP RetAddr Call Site fffff880077c5510 fffff88001498ff1 nt!KxWaitForSpinLockAndAcquire+0x20 fffff880077c5540 fffff8800149ba9b NDIS!ndisReferenceTopMiniportByNameForNsi+0x291 fffff880077c55f0 fffff8800149b9c6 NDIS!ndisNsiGetTopIfBlockFromMiniport+0x2b fffff880077c5630 fffff8800149b7a7 NDIS!ndisNsiGetTopIfBlockForRequest+0x8a fffff880077c5660 fffff8800159cabf NDIS!ndisNsiGetInterfaceInformation+0xcb fffff880077c56a0 fffff88005e8d3cb NETIO!NsiGetParameterEx+0x16f fffff880077c57c0 fffff88005e8f80b nsiproxy!NsippGetParameter+0x247 fffff880077c5960 fffff88005e8f8d3 nsiproxy!NsippDispatchDeviceControl+0xa3 fffff880077c59a0 fffff802161f63dc nsiproxy!NsippDispatch+0x4b fffff880077c59d0 fffff80216240116 nt!IopXxxControlFile+0x7fa fffff880077c5b60 fffff80215e4e353 nt!NtDeviceIoControlFile+0x56 fffff880077c5bd0 000007feac522e5a nt!KiSystemServiceCopyEnd+0x13 0000004c4804f3b8 0000000000000000 0x000007feac522e5a
8: kd> ~7
7: kd> k
Child-SP RetAddr Call Site
fffff88007692540 fffff80215e80fe5 nt!KxWaitForSpinLockAndAcquire+0x20
fffff88007692570 fffff88001499d27 nt!KeAcquireSpinLockRaiseToDpc+0x35
fffff880076925a0 fffff880015990f8 NDIS!ndisNsiGetAllInterfaceInformation+0x97
fffff88007692660 fffff88005e8d98a NETIO!NsiGetAllParametersEx+0x230
fffff88007692770 fffff88005e8f7fa nsiproxy!NsippGetAllParameters+0x29e
fffff88007692960 fffff88005e8f8d3 nsiproxy!NsippDispatchDeviceControl+0x92
fffff880076929a0 fffff802161f63dc nsiproxy!NsippDispatch+0x4b
fffff880076929d0 fffff80216240116 nt!IopXxxControlFile+0x7fa
fffff88007692b60 fffff80215e4e353 nt!NtDeviceIoControlFile+0x56
fffff88007692bd0 000007feac522e5a nt!KiSystemServiceCopyEnd+0x13
0000001df9b6e5e8 0000000000000000 0x000007feac522e5a 7: kd\> ~6 6: kd\> k Child-SP RetAddr Call Site fffff88007676600 fffff80215e80fe5 nt!KxWaitForSpinLockAndAcquire+0x1e fffff88007676630 fffff8800149b748 nt!KeAcquireSpinLockRaiseToDpc+0x35 fffff88007676660 fffff8800159cabf NDIS!ndisNsiGetInterfaceInformation+0x6c fffff880076766a0 fffff88005e8d3cb NETIO!NsiGetParameterEx+0x16f fffff880076767c0 fffff88005e8f80b nsiproxy!NsippGetParameter+0x247 fffff88007676960 fffff88005e8f8d3 nsiproxy!NsippDispatchDeviceControl+0xa3 fffff880076769a0 fffff802161f63dc nsiproxy!NsippDispatch+0x4b fffff880076769d0 fffff80216240116 nt!IopXxxControlFile+0x7fa fffff88007676b60 fffff80215e4e353 nt!NtDeviceIoControlFile+0x56 fffff88007676bd0 000007feac522e5a nt!KiSystemServiceCopyEnd+0x13 0000001df9a6f4a8 0000000000000000 0x000007feac522e5a
6: kd> ~5
5: kd> k
Child-SP RetAddr Call Site
fffff88009eae540 fffff80215e80fe5 nt!KxWaitForSpinLockAndAcquire+0x20
fffff88009eae570 fffff8800149a1dc nt!KeAcquireSpinLockRaiseToDpc+0x35
fffff88009eae5a0 fffff880015990f8 NDIS!ndisNsiGetAllInterfaceInformation+0x54c
fffff88009eae660 fffff88005e8d98a NETIO!NsiGetAllParametersEx+0x230
fffff88009eae770 fffff88005e8f7fa nsiproxy!NsippGetAllParameters+0x29e
fffff88009eae960 fffff88005e8f8d3 nsiproxy!NsippDispatchDeviceControl+0x92
fffff88009eae9a0 fffff802161f63dc nsiproxy!NsippDispatch+0x4b
fffff88009eae9d0 fffff80216240116 nt!IopXxxControlFile+0x7fa
fffff88009eaeb60 fffff80215e4e353 nt!NtDeviceIoControlFile+0x56
fffff88009eaebd0 000007feac522e5a nt!KiSystemServiceCopyEnd+0x13
00000053804eec78 0000000000000000 0x000007fe`ac522e5a