Getting DPC_WATCHDOG_VIOLATION while executing ExAllocatePoolWithTag

WINDBG
1

I have wfp network filter driver where we receive the packet and do scanning. But it is getting crash while executing ExAllocatePoolWithTag API which is getting call inside spin lock. Below is the code algo-

KeAcquireInStackQueuedSpinLockAtDpcLevel(&g_QLock, &LockHandle);
while(some condition)
{
ExAllocatePoolWithTag(); //////////////crashing here
}
KeReleaseInStackQueuedSpinLockFromDpcLevel(&LockHandle);

It does not crash everytime, in some scenarios it crashes while allocating memory. Below is the crash dump output.

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: 0000000000000501, The DPC time count (in ticks).
Arg3: 0000000000000500, The DPC time allotment (in ticks).
Arg4: fffff80674b74380, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
additional information regarding this single DPC timeout

DPC_TIMEOUT_TYPE: SINGLE_DPC_TIMEOUT_EXCEEDED

STACK_TEXT:
ffffe181978faba8 fffff8036389c867 : 0000000000000133 0000000000000000 0000000000000501 0000000000000500 : nt!KeBugCheckEx
ffffe181978fabb0 fffff80363711a4f : 00155db9219a5b70 ffffe18197900180 0000000000000286 0000000000069184 : nt!KeAccumulateTicks+0x1877a7
ffffe181978fac10 fffff8036360447c : 0000000000000000 ffffa48e1ace0400 ffffa30e9bcfc900 ffffa48e1ace04b0 : nt!KeClockInterruptNotify+0xcf
ffffe181978faf30 fffff8036377ca15 : ffffa48e1ace0400 0000000000000000 0000000000000001 ffff5554f24cbd06 : hal!HalpTimerClockIpiRoutine+0x1c
ffffe181978faf60 fffff8036384ba3a : ffffa30e9bcfc900 ffffa48e1ace0400 0000000000000000 0000000000000000 : nt!KiCallInterruptServiceRoutine+0xa5
ffffe181978fafb0 fffff8036384bf87 : 0000000000000000 0000000000000000 ffffa48e56392000 fffff8036379b9d8 : nt!KiInterruptSubDispatchNoLockNoEtw+0xfa
ffffa30e9bcfc880 fffff803637525c3 : ffffa48e1a602300 ffffa48e1a6028c0 ffffa48e1a602000 0000000000000030 : nt!KiInterruptDispatchNoLockNoEtw+0x37
ffffa30e9bcfca10 fffff803639e69bd : 0000000000000002 ffffa30e9bcfcb69 0000000000000200 0000000073706d74 : nt!ExAllocateHeapPool+0xca3
ffffa30e9bcfcaf0 fffff802ec2916d5 : 0000000000000dab 0000000000000270 ffffa48e55d02000 0000000000000000 : nt!ExAllocatePoolWithTag+0x3d
ffffa30e9bcfcbd0 fffff802ec2943d2 : ffffa48e544eb6b8 ffffac88b8eb2000 ffffa48e5528e000 0000000000000004 : MyDrvr!Function1+0x1b9
ffffa30e9bcfcc50 fffff802ec296562 : ffffa48e544eb601 ffffa48e00000004 ffffa48e5528e000 0000000000000001 : MyDrvr!Function2+0x262
ffffa30e9bcfcd40 fffff802ec293a43 : ffffa48e544eb6b8 ffffa48e544eb6b8 0000000000000001 ffffa30e9bcfd100 : MyDrvr!Function3+0x8e
ffffa30e9bcfcd70 fffff802ec296e43 : ffffa30e9bcfd100 ffffa30e9bcfd100 ffffa30e9bcfd100 ffffa48e1b5c9300 : MyDrvr!Function4+0x162b
ffffa30e9bcfce50 fffff802ec29c3db : fffff802ec2ab410 ffffa48e5528e000 0000000000000001 0000000000000000 : MyDrvr!Function5+0x8b3
ffffa30e9bcfd0a0 fffff802ec29afe2 : ffffa48e1b984b00 ffffa48e54246590 0000000000000004 0000000000140015 : MyDrvr!Function6+0x7bf
ffffa30e9bcfd2d0 fffff802ec2744d8 : 0000000000000000 0000000000000001 0000000000000001 ffffa48e1b984b00 : MyDrvr!Function7+0x16

And because thread is stuck at ExAllocatePoolWithTag api, spin lock is not getting acquired for new threads. In dump, current irql is 13 but our driver should run on dispatch level or lower. I know because of irql 13. ExAllcatePool and ndisAcquire lock will fail but no idea who is setting irql 13.

What could be the reason of this irql being set in between? Any help here would be appreciated. Thanks in advance.

2

The root cause of this, as the crash says, is that you are spending too much time at DISPATCH_LEVEL. In this case, 12.8us. You are not allowed to "camp out" at a raised IRQL. If you are doing string scanning or other CPU-intensive processing, then do it before you raise the IRQL.

3

What are you passing to ExAllocatePoolWithTag? Documentation states:

A caller executing at DISPATCH_LEVEL must specify a NonPaged Xxx value for PoolType .

4

I am passing NonPagedPoolNX pooltype. But in my case, I am doing complete scanning inside lock. I cant release the lock in between the scanning. Is there any other option which i can use instead of ExAllocatePool?

5

Correct. May be because of whole scanning, it is taking time. But every crash is pointing to ExAllocatePool API. Should we not use this API inside lock? If not, what could be the alternative?

6

My first question would be why do you need to allocate memory in the DPC at all? It is not something I would usually recommend someone do. I also just noticed you are doing it multiple times in a while loop too. Do you have any idea how many times it is calling ExAllocatePoolWithTag?

I am not sure why you need to allocate this memory if your goal is to "receive the packet and do scanning". But if you really need it I would suggest allocating it once outside the DPC and reusing it.

7

You are chasing a wild goose here. The memory allocation is a red herring. It is NOT the problem. The only reason you see ExAllocatePool here is that the deadman timer check can only happen when a some kernel routine triggers a call that checks the timer.

The PROBLEM is that your code takes too much time. End of story.