Compartilhar via

Crash Dump Analysis Patterns (Part 14)

  • Artigo

Crash Dump Analysis Patterns (Part 14)

번역: 김희준(drost@naver.com, https://insidekernel.net)

 

다음 패턴은 높은 CPU 점유율 스레드(Spiking Thread) 입니다. 만약 여러분이 고객으로부터 여러 스레드가 실행중인 프로세스 덤프를 받았고, 어떤 스레드가 CPU의 대부분 점유하고 있는지 찾아내기 어려울 때 높은 CPU 점유율의 스레드ID나 프로세스ID를 보여주는 QSlice나 Process Explorer의 스크린 샷이나 노트를 첨부해주면 매우 좋습니다. 후자 프로세스 ID의 경우에는 올바른 프로세스로부터 프로세스 덤프를 가져왔는지 확신할 수도 있습니다. 마이크로소프트의 userdump.exe처럼 새로운 프로세스 덤프 툴들은 스레드 시간 정보를 저장하기 때문에 여러분은 덤프를 열어보고 !runaway 명령어를 입력함으로써 유저모드와 커널 모드에서 소비된 시간을 보실 수 있습니다. 그러나 만약 저 명령어가 비슷한 CPU 소비시간을 가진 여러 스레드들을 보여준다면 크래쉬 덤프가 만들어질 당시에 높은 점유율의 특정 스레드를 찾아내지 못할 것이기 때문에 이러한 경우엔 스크린샷이 여전히 유용한 방법입니다.

만약 높은 점유율의 스레드ID를 모른다면 무엇을 해야 할까요? 모든 스레드를 살펴보고 기다리고 있지 않은 스레드들을 찾습니다. 모든 스레드들은 대부분의 경우 거의 모든 시간 동안 대기중입니다. 그래서 보통 프로세스들을 덤프해보면 active 스레드는 매우 적은 것을 볼 수 있습니다. 만약 스레드가 기다리고 있다면 스택의 꼭대기에 있는 함수는 보통 아래와 같습니다(XP/W2K3/Vista)

 

ntdll!KiFastSystemCallRet

 

그리고 그 아래에는 동기화 오브젝트나 Sleep API 호출, IO 컴플리션이나 LPC reply를 기다리는 블록킹 호출들을 보실 수 있습니다:

 

0:085> ~*kv
...
...
...
64 Id: 1b0.120c Suspend: -1 Teb: 7ff69000 Unfrozen
ChildEBP RetAddr Args to Child
02defe18 7c90e399 ntdll!KiFastSystemCallRet
02defe1c 77e76703 ntdll!NtReplyWaitReceivePortEx+0xc
02deff80 77e76c22 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0xf4
02deff88 77e76a3b rpcrt4!RecvLotsaCallsWrapper+0xd
02deffa8 77e76c0a rpcrt4!BaseCachedThreadRoutine+0×79
02deffb4 7c80b683 rpcrt4!ThreadStartRoutine+0×1a
02deffec 00000000 kernel32!BaseThreadStart+0×37

65 Id: 1b0.740 Suspend: -1 Teb: 7ff67000 Unfrozen
ChildEBP RetAddr Args to Child
02edff44 7c90d85c ntdll!KiFastSystemCallRet
02edff48 7c8023ed ntdll!NtDelayExecution+0xc
02edffa0 57cde2dd kernel32!SleepEx+0×61
02edffb4 7c80b683 component!foo+0×35
02edffec 00000000 kernel32!BaseThreadStart+0×37

66 Id: 1b0.131c Suspend: -1 Teb: 7ff66000 Unfrozen
ChildEBP RetAddr Args to Child
02f4ff38 7c90e9c0 ntdll!KiFastSystemCallRet
02f4ff3c 7c8025cb ntdll!ZwWaitForSingleObject+0xc
02f4ffa0 72001f65 kernel32!WaitForSingleObjectEx+0xa8
02f4ffb4 7c80b683 component!WorkerThread+0×15
02f4ffec 00000000 kernel32!BaseThreadStart+0×37

67 Id: 1b0.1320 Suspend: -1 Teb: 7ff65000 Unfrozen
ChildEBP RetAddr Args to Child
02f8fe1c 7c90e9ab ntdll!KiFastSystemCallRet
02f8fe20 7c8094e2 ntdll!ZwWaitForMultipleObjects+0xc
02f8febc 7e4195f9 kernel32!WaitForMultipleObjectsEx+0×12c
02f8ff18 7e4196a8 user32!RealMsgWaitForMultipleObjectsEx+0×13e
02f8ff34 720019f6 user32!MsgWaitForMultipleObjects+0×1f
02f8ffa0 72001a29 component!bar+0xd9
02f8ffb4 7c80b683 component!MonitorWorkerThread+0×11
02f8ffec 00000000 kernel32!BaseThreadStart+0×37

68 Id: 1b0.1340 Suspend: -1 Teb: 7ff63000 Unfrozen
ChildEBP RetAddr Args to Child
0301ff1c 7c90e31b ntdll!KiFastSystemCallRet
0301ff20 7c80a746 ntdll!ZwRemoveIoCompletion+0xc
0301ff4c 57d46e65 kernel32!GetQueuedCompletionStatus+0×29
0301ffb4 7c80b683 component!AsyncEventsThread+0×91
0301ffec 00000000 kernel32!BaseThreadStart+0×37
…
…
…
# 85 Id: 1b0.17b4 Suspend: -1 Teb: 7ffd4000 Unfrozen
ChildEBP RetAddr Args to Child
00daffc8 7c9507a8 ntdll!DbgBreakPoint
00dafff4 00000000 ntdll!DbgUiRemoteBreakin+0×2d

 

그래서 만약 아래에 있는 예처럼 다른 함수를 스택에 가진 스레드가 있다면 그것이 가장 높게 CPU를 사용하고 있는 그 스레드일 가능성이 있습니다:

 

58 Id: 1b0.9f4 Suspend: -1 Teb: 7ff75000 Unfrozen
ChildEBP RetAddr Args to Child
0280f64c 500af723 componentB!DoSomething+32
0280f85c 500b5391 componentB!CheckSomething+231
0280f884 500b7a3f componentB!ProcessWorkIteme+9f
0301ffec 00000000 kernel32!BaseThreadStart+0x37

 

스택의 최상단에 KiFastSystemCallRet 가 없고 그리고 현재 실행하고 있는 인스트럭션을 살펴보면 어떤 카피 오퍼레이션을 하고 있습니다:

 

0:085> ~58r
eax=00000000 ebx=0280fdd4 ecx=0000005f edx=00000000 esi=03d30444 edi=0280f6dc
eip=500a4024 esp=0280f644 ebp=0280f64c iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00010202
componentB!DoSomething+32:
500a4024 f3a5 rep movs dword ptr es:[edi],dword ptr [esi] es:0023:0280f6dc=00000409 ds:0023:03d30444=00000409

 

커널이나 전체 메모리 덤프에서 높은 CPU 점유율 스레드들은 KernelTime이나 UserTime을 체크함으로써 볼 수 있습니다:

 

0: kd> !thread 88b66768
THREAD 88b66768 Cid 01fc.1550 Teb: 7ffad000 Win32Thread: bc18f240 RUNNING on processor 1
IRP List:
89716008: (0006,0094) Flags: 00000a00 Mdl: 00000000
Impersonation token: e423a030 (Level Impersonation)
DeviceMap e3712480
Owning Process 8a0a56a0 Image: SomeSvc.exe
Wait Start TickCount 1782229 Ticks: 0
Context Switch Count 877610 LargeStack
UserTime 00:00:01.0078
KernelTime 02:23:21.0718

- Dmitry Vostokov -

Comments