BugCheck 0x133 DPC_WATCHDOG_VIOLATION

요 며칠 이 BugCheck 때문에 머리에 열좀 받았다.

가끔 테스트시 아래와 같이 WinDBG에 걸리는 경우가 계속 있었는데, 어디선가 그냥 warning 같은거라고 보면 된다고 하여 그냥 아무 생각없이 매번 gh를 입력하여 넘기곤 했는데 기어코 수면위로 떠올랐다.

Assertion failure - code c0000420 (first chance) nt!KeAccumulateTicks+0x575: fffff800`7d88f2e5 cd2c            int     2Ch

앞으로 있을 고행의 시발..점

win32k 인라인 훅이 PatchGuard에 걸리는지 테스트 할 일이 있어 테스트를 하다가 커널 디버깅 중에는 PatchGuard에 탐지가 안되어 WinDBG를 떼고 테스트 하던중 DPC_WATCHDOG_VIOLATION BSOD가 계속 발생을 하는 것이다.

아래는 해당 덤프의 내용이다.

******************************************************************************* *                                                                             * *                        Bugcheck Analysis                                    * *                                                                             * *******************************************************************************   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: 0000000000000281, The DPC time count (in ticks). Arg3: 0000000000000280, The DPC time allotment (in ticks). Arg4: 0000000000000000   Debugging Details: ------------------     CUSTOMER_CRASH_COUNT:  2   DEFAULT_BUCKET_ID:  VISTA_DRIVER_FAULT   BUGCHECK_STR:  0x133   PROCESS_NAME:  System   CURRENT_IRQL:  d   LAST_CONTROL_TRANSFER:  from fffff8035c64d5df to fffff8035c4f4040   STACK_TEXT:  fffff803`5b97a528 fffff803`5c64d5df : 00000000`00000133 00000000`00000000 00000000`00000281 00000000`00000280 : nt!KeBugCheckEx fffff803`5b97a530 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt! ?? ::FNODOBFM::`string'+0x13ba4     STACK_COMMAND:  kb   FOLLOWUP_IP: nt! ?? ::FNODOBFM::`string'+13ba4 fffff803`5c64d5df cc              int     3   SYMBOL_STACK_INDEX:  1   SYMBOL_NAME:  nt! ?? ::FNODOBFM::`string'+13ba4   FOLLOWUP_NAME:  MachineOwner   MODULE_NAME: nt   IMAGE_NAME:  ntkrnlmp.exe   DEBUG_FLR_IMAGE_TIMESTAMP:  5010ac4b   FAILURE_BUCKET_ID:  X64_0x133_nt!_??_::FNODOBFM::_string_+13ba4   BUCKET_ID:  X64_0x133_nt!_??_::FNODOBFM::_string_+13ba4   Followup: MachineOwner

DPC_WATCHDOG_VIOLATION

http://msdn.microsoft.com/en-us/library/windows/hardware/jj154556(v=vs.85).aspx

MSDN에 있는 해당 BugCheck에 대한 설명을 보면 할당된 DPC 시간을 초과했을 경우라고 나온다.

Arg2, 3을 보면 281, 280으로 할당된 Tick을 초과하여 발생한 것으로 보인다.

http://www.osronline.com/showthread.cfm?link=245939

위의 포럼에 보면 나와 비슷한 문제로 고생하고 있는 동지가 있었다.

안되는 영어로 열심히 해석해가면서 봐본 결과, SpinLock을 너무 오래 잡고 있다거나 DISPATCH_LEVEL에 머물 경우 발생을 하는 것으로 추정이 되며, 얼마의 시간동안 Lock을 걸고 있을때 걸리는 것인지 등등을 논의하고 있다.

이런 문제가 발생하는 곳은 다음과 같은 코드가 있는 곳이었다.

멀티 코어 환경에서 다른 코어의 접근을 제한하기 위한 동기화 방법으로 DISPATCH_LEVEL 상승 이후, KeInitializeDpc, KeSetTargetProcessorDpc, KeInsertQueueDpc 함수를 사용하여 각 코어에서 실행될 함수를 DPC Queue에 삽입한다. 그리고 해당 함수에서는 InterLocked 계열의 함수를 사용하여 while문을 돌게하고, 원하는 코드 수행 후 빠져나오도록 하는 그런 코드였다.

예를 들면 인라인 후킹이나 공유 자원 사용시 동기화를 하기 위한 코드였는데, 한마디로 SpinLock 함수를 InterLocked 계열의 함수로 구현해놓은 것이었다. 전임자가 해놓은 코드라 왜 SpinLock을 안썼는지 모르겠지만.. 어쨌든 문제는 찾았다.

처음에는 Lock을 걸고 난 이후에 해제 전까지 실행되는 코드의 실행 시간이 길어져서 발생을 할 것이라고 추측을 했었다. 그런데 예상과는 다르게 KeInsertQueueDpc 함수 호출후에 각 코어에서 while문을 돌거나 돌기전부터 발생을 하고 있었다. Lock을 걸고 실제 수행해야될 코드는 실행도 못해보고 계속 저상황이 발생을 했다. Lock을 걸고 푸는 함수에 문제가 있나 싶어 수없이 검증해보았지만 코드 자체에서는 문제가 없었다.

다만 사용상에 문제가 있었던 것 같다.

한쪽에서 이미 Lock을 건 상태에서 아직 풀기전에 다른 곳에서 또 Lock을 걸려고 할 경우 교착 상태에 빠진 것으로 보인다.

KeAcquireSpinLock / KeReleaseSpinLock으로 변경하더라도 SpinLock을 Release 하기 전에 다른곳에서 또 획득을 하려고 할 경우에는 동일한 상황이 발생을 한다.