이번 덤프는 윈도우 8과 서버 2012부터 많은 사람들을 괴롭혔던 BugCheck 0x133: DPC_WATCHDOG_VIOLATION 이라는 특이한 오류다.
이 오류는 BugCheck 0x7F_8에 해당하는 커널 스택 오버 플로우와 매우 유사하다. 커널 스택 오버 플로우가 커널 스택에 대한 사용량 문제라면 0x133은 커널 시간에 대한 사용량 문제다. 커널에서는 일반적인 요청보다 좀 더 중요한 일을 처리해야 할 때 DPC(Deferred Procudure Call)/Dispatch라는 인터럽트 레벨에서 동작하게 된다. 문제는 이 DPC/Dispatch 레벨이 스레드 스케쥴링 등의 운영체제 주요 동작보다도 더 높은 레벨이라 DPC/Dispatch 레벨에서 작업이 지연되면 시스템이 느려지거나 행 증상이 발생할 수도 있다. 물론 운영체제만 사용 가능한 인터럽트 레벨이라면 큰 문제가 없겠지만 불행히도 DPC/Dispatch 레벨은 커널 드라이버라면 스핀락(SpinLock) 함수를 통해 쉽게 사용 가능하다. 상황이 이렇다보니 잘못 작성된 커널 드라이버가 스핀락을 획득하고 오랜 시간 반환하지 않으면 시스템이 멈추는 불상사가 발생한다. 이 문제를 해결하기 위해 새로 추가된 오류 코드가 바로 0x133이다. 커널에서는 별도의 감시자(Watchdog)를 통해 DPC/Dispatch 레벨에서의 동작 시간이 정해진 제한 시간(Time Out)을 넘으면 지체없이 이 오류 코드를 발생시킨다. 여러 모듈이 지연시키는 경우도 각각 동작 시간을 누적하여 제한 시간을 넘기면 이 오류 코드가 발생할 수 있다. 따라서 원인 분석을 위해 성능 지연 구간에 대한 별도의 성능 로그를 수집해야 할 수도 있다. 나는 이런 점에서 0x133을 매우 어려운 커널 스택 오버 플로우 이슈 정도로 생각한다.
물론 여기서는 덤프에서 원인 분석이 가능하도록 단일 모듈에서 성능 지연이 발생한 경우를 살펴볼 것이다.
먼저 !analyze -v 명령을 통해 기본 분석부터 시작해보자.
kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************
DPC_WATCHDOG_VIOLATION (133)
The DPC watchdog detected a prolonged run time at an IRQL of DISPATCH_LEVEL
or above.
Arguments:
Arg1: 00000001, The system cumulatively spent an extended period of time at
DISPATCH_LEVEL or above. The offending component can usually be
identified with a stack trace.
Arg2: 00001e00, The watchdog period.
Arg3: 00000000, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
additional information regarding the cumulative timeout
Arg4: 00000000
Debugging Details:
------------------
DUMP_CLASS: 1
DUMP_QUALIFIER: 401
BUILD_VERSION_STRING: 14393.693.x86fre.rs1_release.161220-1747
SYSTEM_MANUFACTURER: SAMSUNG ELECTRONICS CO.,LTD
SYSTEM_PRODUCT_NAME: Samsung Desktop System
SYSTEM_SKU: System SKUNumber
SYSTEM_VERSION: CAAAAAAF
BIOS_VENDOR: SAMSUNG ELECTRONICS CO.,LTD
BIOS_VERSION: 04NS
BIOS_DATE: 08/16/2011
BASEBOARD_MANUFACTURER: SAMSUNG ELECTRONICS CO.,LTD
BASEBOARD_PRODUCT: Samsung DeskTop System
BASEBOARD_VERSION: CAAAAAAA
DUMP_TYPE: 1
BUGCHECK_P1: 1
BUGCHECK_P2: 1e00
BUGCHECK_P3: 0
BUGCHECK_P4: 0
DPC_TIMEOUT_TYPE: DPC_QUEUE_EXECUTION_TIMEOUT_EXCEEDED
CPU_COUNT: 4
CPU_MHZ: cdd
CPU_VENDOR: GenuineIntel
CPU_FAMILY: 6
CPU_MODEL: 2a
CPU_STEPPING: 7
CPU_MICROCODE: 6,2a,7,0 (F,M,S,R) SIG: 29'00000000 (cache) 29'00000000 (init)
DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT
BUGCHECK_STR: 0x133
PROCESS_NAME: SMSS.exe
CURRENT_IRQL: 1c
ANALYSIS_SESSION_HOST: PAUL-PC
ANALYSIS_SESSION_TIME: 06-11-2018 22:34:11.0900
ANALYSIS_VERSION: 10.0.16299.91 amd64fre
LAST_CONTROL_TRANSFER: from 81b48d4e to 81b284a8
STACK_TEXT:
d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx
d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae
d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c
d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f
d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7
d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d
d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53
d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33
d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7
d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv+0xf149
d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d
d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall
042ffde8 00000000 00000000 00000000 00000000 0x77ce4d50
THREAD_SHA1_HASH_MOD_FUNC: 2a46f69c6139803d83a04cedcad275f72ac07d42
THREAD_SHA1_HASH_MOD_FUNC_OFFSET: 6f2b762ab8d468cacab44d7f866169a56cdce50c
THREAD_SHA1_HASH_MOD: bd912fdd2f42d7d45cc2017c378e8c588d451ef1
FOLLOWUP_IP:
SomeDrv+25c7
883125c7 8845fe mov byte ptr [ebp-2],al
FAULT_INSTR_CODE: 81fe4588
SYMBOL_STACK_INDEX: 8
SYMBOL_NAME: SomeDrv+25c7
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: SomeDrv
IMAGE_NAME: SomeDrv.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 57fde77c
STACK_COMMAND: .thread ; .cxr ; kb
BUCKET_ID_FUNC_OFFSET: 25c7
FAILURE_BUCKET_ID: 0x133_ISR_SomeDrv!unknown_function
BUCKET_ID: 0x133_ISR_SomeDrv!unknown_function
PRIMARY_PROBLEM_CLASS: 0x133_ISR_SomeDrv!unknown_function
TARGET_TIME: 2017-02-27T00:48:23.000Z
OSBUILD: 14393
OSSERVICEPACK: 0
SERVICEPACK_NUMBER: 0
OS_REVISION: 0
SUITE_MASK: 272
PRODUCT_TYPE: 1
OSPLATFORM_TYPE: x86
OSNAME: Windows 10
OSEDITION: Windows 10 WinNt TerminalServer SingleUserTS
OS_LOCALE:
USER_LCID: 0
OSBUILD_TIMESTAMP: 2016-12-21 13:24:07
BUILDDATESTAMP_STR: 161220-1747
BUILDLAB_STR: rs1_release
BUILDOSVER_STR: 10.0.14393.693.x86fre.rs1_release.161220-1747
ANALYSIS_SESSION_ELAPSED_TIME: ece
ANALYSIS_SOURCE: KM
FAILURE_ID_HASH_STRING: km:0x133_isr_SomeDrv!unknown_function
FAILURE_ID_HASH: {c26eac98-dd1d-7af7-3055-fbbff800604a}
Followup: MachineOwner
---------
출력 결과 중 BugCheck 파라미터 부분을 유심히 살펴보면 대략적인 발생 원인을 이해할 수 있다.
Arg1: 00000001, The system cumulatively spent an extended period of time at
DISPATCH_LEVEL or above. The offending component can usually be
identified with a stack trace.
Arg2: 00001e00, The watchdog period.
첫 번째 파라미터는 1이며, 시스템이 DISPATCH_LEVEL 이상에서 장시간 동작한 것이 원인이라고 말한다. 스택 추적을 통해 문제를 일으킨 원인을 확인할 수 있다고도 언급한다.
두 번째 파라미터는 감시 중인 제한 시간으로 Tick 단위다. 하나 혹은 복수의 커널 드라이버가 DISPATCH_LEVEL 이상에서 동작한 누적 시간 값이 제한 시간을 넘길 경우 이 오류가 발생한다.
이를 통해 누군가 DISPATCH_LEVEL 이상에서 0x1e00(7,680) Tick 만큼 장시간 동작한 것이 문제의 원인 임을 짐작할 수 있다. 커널에서 성능 지연이 감지되면 시스템을 멈추는 방식이므로 문제 발생 당시 실행 중인 스레드가 범인일 가능성이 높다. 첫 번째 파라미터 설명에서 실행 중인 콜 스택을 살펴보라는 것도 그런 이유에서다.
그렇다면 !thread 명령으로 현재 실행 중인 스레드 정보를 확인해보자.
kd> !thread
THREAD d8e548c0 Cid 2978.2c68 Teb: 0157e000 Win32Thread: 00000000 RUNNING on processor 0
Not impersonating
DeviceMap 88a03058
Owning Process d8bc6800 Image: SMSS.exe
Attached Process N/A Image: N/A
Wait Start TickCount 39290 Ticks: 7680 (0:00:02:00.000)
Context Switch Count 3651 IdealProcessor: 0
UserTime 00:00:00.062
KernelTime 00:02:00.046
Win32 Start Address 0x0fb738e0
Stack Init d461bca0 Current d461ba2c Base d461c000 Limit d4619000 Call 00000000
Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr Args to Child
d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx
d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae
d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c (FPO: [Non-Fpo])
d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f (FPO: [0,0,4])
d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7 (FPO: [0,2] TrapFrame @ d461b978)
d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d (FPO: [0,0,0])
d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53 (FPO: [Non-Fpo])
d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33 (FPO: [0,0,0])
d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7
d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv+0xf149
d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d (FPO: [Non-Fpo])
d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])
d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall (FPO: [0,3] TrapFrame @ d461bc14)
042ffde8 00000000 00000000 00000000 00000000
0x77ce4d50
스레드 정보의 Ticks 필드를 보면 정확하게 7680(0x1e00) Tick이 경과했음을 알 수 있다. 2분의 시간이 경과한 순간 커널이 제한 시간을 다 사용한 것으로 판단하여 0x133을 발생시킨 것이다.
이번에는 k명령으로 스레드의 콜 스택을 분석하며 문제가 발생한 상황을 좀 더 이해해보자.
kd> k
# ChildEBP RetAddr
00 d461b7d4 81b48d4e nt!KeBugCheckEx ç 3) 제한 시간이 경과하여 BSOD 발생
01 d461b804 81a3b08c nt! ?? ::FNODOBFM::`string'+0x9eae
02 d461b8d0 820336b7 nt!KeClockInterruptNotify+0x36c
03 d461b8e0 82044cdb hal!HalpTimerClockInterruptCommon+0x3f
04 d461b8e0 81a3d64d hal!HalpTimerClockInterrupt+0x1f7
05 d461b9f0 81ba85d0 nt!KxWaitForSpinLockAndAcquire+0x1d ç 2) 스핀락 획득 시도 중
06 d461ba14 81a54003 nt!KiAcquireSpinLockInstrumented+0x53
07 d461ba20 883125c7 nt!KfAcquireSpinLock+0x33
08 d461ba2c 8831f149 SomeDrv+0x25c7 ç 1) SomeDrv 모듈에서 스핀락 획득 함수 호출
09 d461bae0 81ca719d SomeDrv+0xf149
0a d461bbb8 81ca6f6a nt!IopXxxControlFile+0x21d
0b d461bbe4 81b36987 nt!NtDeviceIoControlFile+0x2a
0c d461bbe4 77ce4d50 nt!KiSystemServicePostCall
0d 042ffde8 00000000 0x77ce4d50
콜 스택을 보면 1)번에서 SomeDrv 모듈이 스핀락을 얻으려고 시도하고 있다. 하지만 스핀락을 획득하지 못해 2)번에서 nt! KxWaitForSpinLockAndAcquire 함수를 통해 획득하기를 기다리고 있다. 동작 자체로는 아무 문제가 없지만 락 획득을 빨리 하지 못한 것이 문제의 원인이다. 무려 2분 동안 락을 획득하지 못하고 있는 것은 정상적인 상황이 아니다. 하지만 이 문제를 분석하기에 앞서 확인해야할 부분이 하나 있다.
앞서 0x133이 발생하려면 제한 시간 외에도 인터럽트 레벨이 DISPATCH_LEVEL 이상이라는 조건이 있었다. 제한 시간 조건은 스레드의 Ticks 정보를 통해 만족함을 확인했지만 인터럽트 레벨 조건은 아직 확인하지 못했다.
문제 발생 당시 인터럽트 레벨을 어떻게 알 수 있을까? 문제의 콜 스택에서 스핀락을 얻으려는 부분이 보이는가? 커널에서 락이나 이벤트를 사용할 경우 내부에서는 동기화를 위해 인터럽트 레벨을 변경하는 경우가 많이 있다. 그렇다면 nt!KfAcquireSpinLock 함수를 디스어셈블링해서 인터럽트 레벨을 변경하는 부분이 있는지 살펴보면 답을 알 수 있다.
kd> u nt!KfAcquireSpinLock
nt!KfAcquireSpinLock:
81a53fd0 8bff mov edi,edi
81a53fd2 53 push ebx
81a53fd3 56 push esi
81a53fd4 8bf1 mov esi,ecx
81a53fd6 ff153891c381 call dword ptr [nt!_imp__KeRaiseIrqlToDpcLevel (81c39138)]
81a53fdc f60506b9c48121 test byte ptr [nt!PerfGlobalGroupMask+0x6 (81c4b906)],21h
81a53fe3 8ad8 mov bl,al
81a53fe5 7515 jne nt!KfAcquireSpinLock+0x2c (81a53ffc)
다행히 시작 부분에 KeRaiseIrqlToDpcLevel 함수를 통해 인터럽트 레벨을 Dpc/Dispatch로 상승시키는 코드가 확인된다. 0x133을 발생시키는 인터럽트 레벨과 제한 시간 조건 모두를 만족하는 상황이므로 SomeDrv 모듈에서 스핀락을 획득하는 동작이 문제의 발단이다.
이제 오랜 시간 동안 스핀락을 획득하지 못한 원인을 밝혀내야 한다. 먼저 스핀락을 획득하는 함수인 nt!KfAcquireSpinLock 함수의 원형을 살펴보자.
KIRQL
FASTCALL
KfAcquireSpinLock(
_Inout_ PKSPIN_LOCK SpinLock
);
<wdm.h>
typedef ULONG_PTR KSPIN_LOCK;
typedef KSPIN_LOCK *PKSPIN_LOCK;
KSPIN_LOCK 구조체의 포인터를 파라미터로 전달받고 있다. 뭔가 특별한 락 구조체인 것처럼 보이지만 wdm.h 헤더 파일을 보면 실은 단순한 unsigned long 변수다. 스핀락은 바로 이 변수를 통해 테스트 앤 셋(Test And Set) 방식으로 동기화를 수행한다. 이 방식을 단순하게 설명하면 락 변수 값이 0이면 스핀락 획득시 변수를 1로 설정하고 락 반환시 0으로 복원한다. 이미 1인 상태에서 스핀락 획득을 시도하면 0이 되길 지속적으로 기다린다(루프를 돌면서 기다리는 이 동작 때문에 스핀락이라고 부른다).
다시 본론으로 돌아와서 이번에는 nt! KfAcquireSpinLock 함수에 전달된 KSPIN_LOCK 변수가 정상인지 확인해야 한다. 콜 스택에서 nt!KfAcquireSpinLock 함수를 호출한 1)번 부분을 디스어셈블링해보자.
kd> ub SomeDrv+0x25c7
SomeDrv+0x25b1:
883125b1 cc int 3
883125b2 8bff mov edi,edi
883125b4 55 push ebp
883125b5 8bec mov ebp,esp
883125b7 51 push ecx
883125b8 c645ff00 mov byte ptr [ebp-1],0
883125bc b980d93388 mov ecx,offset SomeDrv+0x2d980 (8833d980) ç 1) 파라미터
883125c1 ff1508e03288 call
dword ptr [SomeDrv+0x1e008 (8832e008)] ç 2) nt!KfAcquireSpinLock 함수 호출
nt!KfAcquireSpinLock 함수 원형을 보면 호출 규약이 FASTCALL 이므로 첫 번째 파라미터는 ecx에 설정된다. 1)번을 보면 SomeDrv+0x2d980 위치의 값을 ecx에 설정하고 있다. 바로 SomeDrv+0x2d980가 KSPIN_LOCK 구조체 변수의 주소다. 2)번에서 호출된 함수는 ln 명령을 사용하면 nt!KfAcquireSpinLock 함수 임을 쉽게 알 수 있다.
kd> ln poi(8832e008)
Browse module
Set bu breakpoint
(81a53fd0) nt!KfAcquireSpinLock | (81a54010) nt!KfReleaseSpinLock
Exact matches:
nt!KfAcquireSpinLock (<no parameter info>)
KSPIN_LOCK 구조체 위치인 SomeDrv+0x2d980 주소도 dd 명령으로 확인해보자.
kd> dd SomeDrv+0x2d980 L1
8833d980 00490057
어라? KSPIN_LOCK 구조체 주소인 8833d980에 저장된 값이 뭔가 이상하다. 스핀락 획득 유무에 따라 0 아니면 1이 있어야 하는데 00490057이라는 비정상적인 값이 들어 있다. 왠지 불길한 예감이 든다. 이럴 때는 db 명령을 통해 8833d980 주소의 메모리를 확인해보면 의외의 단서를 찾을 수 있다.
kd> db 8833d980
8833d980 57 00 49 00 4e 00 44 00-4f 00 57 00 53 00 5c 00 W.I.N.D.O.W.S.\.
8833d990 53 00 59 00 53 00 54 00-45 00 4d 00 33 00 32 00 S.Y.S.T.E.M.3.2.
8833d9a0 5c 00 44 00 4e 00 53 00-41 00 50 00 49 00 2e 00 \.D.N.S.A.P.I...
8833d9b0 44 00 4c 00 4c 00 00 00-59 00 53 00 54 00 45 00 D.L.L...Y.S.T.E.
8833d9c0 4d 00 33 00 32 00 5c 00-44 00 4e 00 53 00 41 00 M.3.2.\.D.N.S.A.
8833d9d0 50 00 49 00 2e 00 44 00-4c 00 4c 00 43 00 3a 00 P.I...D.L.L.C.:.
8833d9e0 5c 00 57 00 49 00 4e 00-44 00 4f 00 57 00 53 00 \.W.I.N.D.O.W.S.
8833d9f0 5c 00
53 00 59 00 53 00-54 00 45 00 4d 00 33 00
\.S.Y.S.T.E.M.3.
역시 00490057은 KSPIN_LOCK 구조체의 정상적인 값이 아닌 어떤 문자열 값의 일부분이다. du 명령으로 약간 앞 쪽을 살펴보면 왠지 전체 문자열을 알 수 있을 것 같다.
kd> du 8833d980-6
8833d97a
"C:\WINDOWS\SYSTEM32\DNSAPI.DLL"
아하! "C:\WINDOWS\SYSTEM32\DNSAPI.DLL"이라는 파일 경로 문자열이 들어 있다. 아무래도 누군가 KSPIN_LOCK 구조체 위치에 이 문자열을 덮어 써버려 메모리를 손상시킨 것 같다. 정말 메모리 손상이 문제의 원인이 맞는지 알려면 스핀락을 획득하는 부분을 조금 더 분석할 필요가 있다. kv 명령으로 콜 스택을 다시 확인해보자.
kd> kv
# ChildEBP RetAddr Args to Child
00 d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx
01 d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae
02 d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c (FPO: [Non-Fpo])
03 d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f (FPO: [0,0,4])
04 d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7 (FPO: [0,2] TrapFrame @ d461b978) ç 2) 트랩 프레임
05 d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d (FPO: [0,0,0]) ç 1) 락 대기 함수
06 d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53 (FPO: [Non-Fpo])
07 d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33 (FPO: [0,0,0])
08 d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7
09 d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv +0xf149
0a d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d (FPO: [Non-Fpo])
0b d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])
0c d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall (FPO: [0,3] TrapFrame @ d461bc14)
0d 042ffde8 00000000 00000000 00000000 00000000
0x77ce4d50
1)번 nt!KxWaitForSpinLockAndAcquire함수는 스핀락을 획득하기 위해 시도하는 함수다. 2)번에는 트랩 프레임(TrapFrame)이 확인된다. 트랩 프레임이 있다는 것은 직전 1)번 함수 동작에 문제가 있어 인터럽트가 발생했다는 의미다. .trap 명령을 사용해 문제 발생 당시 상황으로 컨텍스트를 복원해보자.
kd> .trap d461b978
ErrCode = 00000000
eax=00490057 ebx=83000100 ecx=8833d980 edx=00000000 esi=520f94a9 edi=8833d980
eip=81a3d64d esp=d461b9ec ebp=d461ba14 iopl=0 nv up ei pl nz na pe nc
cs=0008 ss=0010 ds=8c3b es=01c8 fs=6b68 gs=ba20 efl=00000206
nt!KxWaitForSpinLockAndAcquire+0x1d:
81a3d64d f390 pause
edi 레지스터에 설정된 8833d980 값을 기억해두자(앞서 확인한 KSPIN_LOCK 구조체 주소다). esi 레지스터 값도 봐두면 좋다. 문제가 발생했던1)번 시점의 동작을 확인하기 위해 nt!KxWaitForSpinLockAndAcquire 함수를 처음부터 살펴봐야한다. 함수가 짧으니 너무 걱정하지 말자.
kd> u nt!KxWaitForSpinLockAndAcquire L14
nt!KxWaitForSpinLockAndAcquire:
81a3d630 8bff mov edi,edi
81a3d632 56 push esi
81a3d633 57 push edi
81a3d634 8bf9 mov edi,ecx
81a3d636 33f6 xor esi,esi ç 1) esi = 0
81a3d638 eb06 jmp nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640)
81a3d63a 8d9b00000000 lea ebx,[ebx]
81a3d640 46 inc esi ç 2) esi + 1(루프 시작)
81a3d641 853530e0c381 test dword ptr [nt!HvlLongSpinCountMask (81c3e030)],esi
81a3d647 0f84a2bc1000 je nt! ?? ::FNODOBFM::`string'+0xa44f (81b492ef)
81a3d64d f390 pause ç 3) 인터럽트 발생 위치(트랩 프레임)
81a3d64f 8b07 mov eax,dword ptr [edi] ç 4) edi 값을 eax에 설정
81a3d651 85c0 test eax,eax ç 5) eax 값이 0인지 확인
81a3d653 75eb jne nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640) ç 6) 0이 아니면 2)번 루프 시작 위치로 이동
81a3d655 f00fba2f00 lock bts dword ptr [edi],0
81a3d65a 72e4 jb nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640)
81a3d65c 5f pop edi
81a3d65d 8bc6 mov eax,esi
81a3d65f 5e pop esi
81a3d660 c3 ret
중요 위치마다 주석이 있어 함수 동작을 이해하는 데 무리가 없을 것이다. 1)번부터 살펴보자. 우선 esi 레지스터는 단순한 카운터 변수다. 2)번을 보면 루프 진입시마다 1씩 증가한다. 4)번에는 edi 값을 eax에 설정하고 5)번에서 eax가 0인지 확인한다. 참고로 edi는 KSPIN_LOCK 구조체 변수의 주소였다.
eax에 설정한 edi 값을 확인해보자.
kd> dd edi L1
8833d980
00490057
edi에 00490057 값이 있으므로 eax에도 00490057 값이 설정된다(앞서 00490057 값은 문자열의 일부였다). 6)번에서는 eax 값이 0이 아니므로 루프 시작 위치인 2)번으로 다시 이동한다. eax는 이미 문자열로 덮어 써져 0이 될 수 없으므로 계속 이 루틴이 반복된다. 즉 무한 루프 상태다. 과연 이 루프는 얼마나 수행됐을까? 카운터 변수인 esi 레지스터 값을 확인해보자.
kd> r esi
Last set context:
esi=520f94a9
맙소사! 0x520f94a9(1,376,752,809)라는 엄청나게 큰 값이 설정되어 있다. 무려 13억번이나 루프가 돌고 있었던 것이다! 그리고는 결국 제한 시간이 다 되어 3)번 위치의 pause 명령에서 0x133이 발생했다. 이제야 모든 것이 명확해졌다. 누군가 스핀락 변수를 문자열로 손상시켜 스핀락 획득 함수 내부에서 무한 루프에 빠져 버린 것이 원인이다(물론 대부분의 경우 누군가는 스핀락 사용 중인 SomeDrv 자신이다).
스핀락을 획득하려고 인터럽트 레벨을 상승시키고 무한 루프에 빠졌으니 DPC_WATCHDOG_VIOLATION(0x133) 버그체크가 발생하는 것은 어찌보면 당연하다.
여기서는 메모리 손상에 의한 0x133을 소개했지만 훨씬 까다로운 경우도 있다. 바로 스핀락을 획득하고 수행한 작업들 하나하나가 조금씩 성능 지연을 일으켜 누적에 의해 제한 시간을 넘기는 경우다. 단일 모듈이 아닌 다수의 모듈에서 지연이 발생하는 경우라면 더욱 골치아프다. 이 경우 별도의 성능 측정을 통해 모듈별로 매 작업마다 성능 지연이 발생하는 구간을 찾아내야해서 굉장히 어렵다. 이런 이유로 스핀락을 획득하고 시간 걸리는 작업은 아예 하지 않는 것이 정신 건강에 이롭다. 주로 다량의 엔트리가 삽입된 리스트를 검색할 때 성능 지연이 발생하는데 해시 테이블 등으로 자료 구조를 변경하거나 리스트에 삽입되는 최대 개수를 제한하는 등의 수정이 필요할 수 있다. 물론 가장 좋은 것은 개발 초기부터 이런 문제를 예상하며 성능을 고려한 설계를 하는 것이다.
앞으로 이 오류 코드가 발생한다면 이것 하나만 기억하자. “스핀락과 연관된 코드를 살펴보라!”
'Dump Analysis' 카테고리의 다른 글
[Hang] CPU 과점유 (0) | 2018.08.13 |
---|---|
[0xC5] 해제 리스트 손상 (0) | 2018.07.19 |
[0xC5] 풀 헤더 손상 (0) | 2018.07.16 |
[0x1A] 페이지 손상 (0) | 2018.07.12 |
[0x50] 해제된 핸들 (0) | 2018.07.09 |