Invalid Handle 문제 중에 많이 발생하는 pattern은 이미 Handle을 Close 했는데 이후에 다시 동일한 Handle을 Close 하려고 시도하는 경우가 빈번하다. 이 경우에는 Crash Dump를 받더라도 누가 이전에 Close 했는지 Trace 해보지 않는 한 문제를 Fix하기가 어렵다. 이러한 경우에, Debug Diagnostics Tool을 이용하여 다소 무식한 방법이 될 수도 있지만, kernel32!CloseHandle 에서 BreakPoint를 걸고 log를 남기는 방법이 유용할 수 있다.

 

Crash Rule에서 따라가다 보면, 아래와 같은 advanced Configuration 창이 있으며, BreakPoints를 설정할 수 있다.

BreakPoints를 Click 하면, Configure breakpoints 창이 나오고 add 하여 Kernel32!CloseHandle에 BP를 걸도록 설정한다.

Action Type은 Log Stack Trace 를 하도록 하고, Action Limit은 0인데, 언제 문제 재현이 될지도 모르기 때문에 제한 없이(사실 Hard disk의 제약을 받는 다) Log File에 CloseHandle이 불리는 경우의 stack을 남기도록 설정한다. 문제 재현까지 오랜 시간이 걸린다면, Log File이 상당히 커질 수 있으며, 문제를 Isolation 하기 어려운 상황이 올 수도 있기 때문에 여러 가지 상황을 고려하여 시도해보면 좋을 듯 하다.

Application이 Crash가 발생하거나 혹은, Hang 현상이 발생할 경우에, Application Logic 만 가지고 추측하여 문제가 발생하는 지점을 찾아 Fix하는 것은 쉽지 않다. 만일, 그게 가능하다면, 사실 개발단계에서 그런 문제점을 고려하지 못했던 것을 탓해야 할 것이지만, 그렇지 못하기 때문에 대부분의 문제는 Application 운영 중 예상치 못한 시점에 발생한다. 이 경우에 Application에 대한 Debugging은 어떻게 접근하는 것이 좋을 까. 무엇보다도 문제 시점에 데이타를 보는 것이 빠른 접근이 아닐까 한다. Application은 일반적으로 logic에 따라 데이터의 흐름으로써 처리가 되며 그 결과를 보여주는 형태이다. 그러므로, 예상치 못한 시점의 예상치 못한 결과, Crash나 Hang이 발생했다면, 그 시점에 존재하는 연관된 데이타들은 Programmer가 예상한 시나리오에서의 올바른 데이터가 아니거나 고려하지 못한 흐름이라고 볼 수 있으며, 데이터와 logic을 보면서 verify 함으로써, logic의 수정이나 피치 못할 예외처리라든가 여러 가지 Application을 안정화하는 code를 추가할 수 있게 된다. 그러므로, Debugging은 전반적인 Logic을 보는 과정에 앞서서 문제 시점의 데이타를 분석하는 것이 우선이고 중요하다.

 

메모리 덤프는 Application이 Crash가 발생하거나 Hang이 발생하는 시점에 Debugging Tool을 이용하여 Application이 사용하는 메모리를 그대로 file Drop시킨 것이다. 그러므로, 그 시점에 register, heap memory나 assembly code등을 windbg.exe와 같은 tool을 이용하여 살펴볼 수 있는데, 메모리 덤프를 이용하여 Debugging하는 경우, 데이터 분석 시 가장 익숙하지 않고 어려운 부분은 Assembly code에 숨어 있는 데이터구조를 이해하는 것이 아닐까 한다. 예를 들어, array와 같은 Data Structure, linked list 그리고 Class와 같은 것들이다. 그러므로, 이들이 Memory Dump에서 어떻게 보여지고 이를 어떻게 해석해야 하는 지를 조금 언급해 볼까 한다.

 

먼저, 살펴볼 것은 array 구조에 대한 assembly code이다.

 

mov eax, DWORD PTR [ebp-20h]

mov ecx, DWORD PTR [ebp+eax*8-24h]

 

ebp-20h로부터 load 된 eax 값은 array의 index 값이고, ebp-24h 는 array의 base pointer이다. 여기서 *8 연산을 하는 것은 array의 저장된 item의 size(예를 들어, long 형)를 eax 즉, index에 곱해줘서 원하는 위치의 array item을 구하기 위한 offset 연산이 된다. 그리고, 동일하지만, shift 연산을 사용하는 다음과 같은 경우도 존재한다.

 

 mov eax, DWORD PTR [ebp-20h]

 shl eax, 2

 mov ecx, DWORD PTR [ebp+eax-24h]

 

이러한 pattern은 array 연산의 대표적인 형태이다.

다음은 Linked List 데이터 구조의 경우인데, 하나의 node는 Item과 Next node pointer를 갖고 있는 형태로 assembly code에서는 다음과 같이 처리된다.

 

 mov     eax,dword ptr [ebp+8]

 mov     ecx,dword ptr [eax]

 mov     edx,dword ptr [ecx]

 cmp     edx,dword ptr [ebp+0Ch]

 

보면, ebp+8은 current node pointer이다. 그러므로, current node pointer를 ecx로 load 하고, 다시 해당 address를 edx로 load 한 후에 이를 ebp+0ch 값과 비교하는 것을 봐서 edx에 load된 값은 node structure의 첫 번째 item을 얻어 온 것이다.

 

                     if ((*n)->data == i)

                     { /* …  */

                     }

 

그리고, 연계하여,

 

  mov     eax,dword ptr [ebp+8]

  mov     ecx,dword ptr [eax]

  add     ecx,4

  mov     dword ptr [ebp+8],ecx

이것은 current node pointer인 ecx에 +4를 하는 것으로 보아 첫 번째 item은 int 와 같은 data type일 가능성이 있고, 4만큼 offset 이동하여 node struct의 두 번째 item을 얻어오는 것을 알 수 있다. 이는 Linked list 구조상 Next Pointer가 되는 데, 이를 current node pointer로 mov 하는 것이므로, Next node로 이동하는 다음과 같은 code 이다.

 

                     n = &(*n)->next;

 

이러한 pattern이 대표적인 Linked List 구조이다.

그리고, 다음에 언급할 구조는 class 구조이다.

 

High Level Language에서는 상위의 그림처럼 작성이 되지만, 메모리 layout은 좀 차이가 있다. 예를 들어, 상위의 C2 class의 경우는 아래와 같은 메모리 layout을 갖는 다.

 

0:000> dt rvsTest!C2

   +0x000 __VFN_table : Ptr32

   +0x004 b_m              : Int4B

   +0x008 c_m              : Int4B

   +0x00c c2_m             : Int4B

 

보면, Virtual Function Table과 public 하게 inherited 된 fields가 hierarchical 하게 메모리를 점유하고 있다. 그리고, Virtual function Table의 실제 memory layout을 살펴보면 다음과 같다.

 

 0:000> dt rvsTest!C2 0x00235e38

   +0x000 __VFN_table : 0x002e7768

   +0x004 b_m              : 1

   +0x008 c_m              : 2

   +0x00c c2_m             : 3

 

 0:000> dds 002e7768

002e7768  002e120d rvsTest!ILT+520(?b_vf1CUAEXXZ)

002e776c  002e11f9 rvsTest!ILT+500(?b_vf2CUAEXXZ)

002e7770  002e1073 rvsTest!ILT+110(?c_vf1C2UAEXXZ)

002e7774  00000000

002e7778  002e86d0 rvsTest!C::`RTTI Complete Object Locator'

002e777c  002e120d rvsTest!ILT+520(?b_vf1CUAEXXZ)

002e7780  002e11f9 rvsTest!ILT+500(?b_vf2CUAEXXZ)

002e7784  002e1217 rvsTest!ILT+530(?c_vf1CUAEXXZ)

002e7788  00000000

002e778c  002e86e8 rvsTest!B::`RTTI Complete Object Locator'

002e7790  002e11b8 rvsTest!ILT+435(?b_vf1BUAEXXZ)

002e7794  002e11a9 rvsTest!ILT+420(?b_vf2BUAEXXZ)

…

 

그러므로, 이러한 구조상에서 Virtual Function Call이 이뤄지게 된다. 다음의 assembly code를 보면,

 

   mov     eax,dword ptr [ebp-14h]

   mov     edx,dword ptr [eax]

   mov     esi,esp

   mov     ecx,dword ptr [ebp-14h]

   mov     eax,dword ptr [edx+8]

   call    eax

 

일반적인 Virtual Function Calling의 형태이다. Ebp-14는 Class Object를 가리키고 있으며, edx는 상위에서 언급한 것처럼, Virtual Function Table의 Pointer이다. 그러므로, edx+8 은 002e7768+8=002e7770 즉, rvsTest!ILT+110(?c_vf1C2UAEXXZ)를 가리킨다. 그러므로, 다음은 Virtual Function의 disassembly code가 된다.

 

0:000> uf 002e1073

rvsTest!C2::c_vf1 [c:\codes\examples\rvstest\rvstest\rvstest.cpp @ 101]:

  101 002e1c30 55              push    ebp

  101 002e1c31 8bec            mov     ebp,esp

  101 002e1c33 81eccc000000    sub     esp,0CCh

  101 002e1c39 53              push    ebx

  101 002e1c3a 56              push    esi

  101 002e1c3b 57              push    edi

  101 002e1c3c 51              push    ecx

  101 002e1c3d 8dbd34ffffff    lea     edi,[ebp-0CCh]

  101 002e1c43 b933000000      mov     ecx,33h

  101 002e1c48 b8cccccccc      mov     eax,0CCCCCCCCh

  101 002e1c4d f3ab            rep stos dword ptr es:[edi]

  101 002e1c4f 59              pop     ecx

  101 002e1c50 894df8          mov     dword ptr [ebp-8],ecx

  102 002e1c53 8bf4            mov     esi,esp

  102 002e1c55 680c782e00      push    offset rvsTest!`string' (002e780c)

  102 002e1c5a ff15e4b22e00    call    dword ptr [rvsTest!_imp__printf (002eb2e4)]

  102 002e1c60 83c404          add     esp,4

  102 002e1c63 3bf4            cmp     esi,esp

  102 002e1c65 e821f5ffff      call    rvsTest!ILT+390(__RTC_CheckEsp) (002e118b)

  103 002e1c6a 5f              pop     edi

  103 002e1c6b 5e              pop     esi

  103 002e1c6c 5b              pop     ebx

  103 002e1c6d 81c4cc000000    add     esp,0CCh

  103 002e1c73 3bec            cmp     ebp,esp

  103 002e1c75 e811f5ffff      call    rvsTest!ILT+390(__RTC_CheckEsp) (002e118b)

  103 002e1c7a 8be5            mov     esp,ebp

  103 002e1c7c 5d              pop     ebp

  103 002e1c7d c3              ret

 

rvsTest!ILT+110(?c_vf1C2UAEXXZ):

002e1073 e9b80b0000      jmp     rvsTest!C2::c_vf1 (002e1c30)

Application High CPU(또는 CPU 100%) Hang 현상은 Application의 일부 Logic에 지속적인 Loop 처리와 같은 CPU를 consuming 하는 작업의 진행으로 인하여 사용자 응답을 처리할 수 없는 상태로 Deadlock에 의한 Low CPU Hang과 차이가 있다. 그러므로, Application의 어떤 Thread에서 Loop와 같은 처리가 지속되고 있는 지를 Debugger에서 check하는 것이 중요한데, 이에 대한 정보는 일반적으로 성능로그에서 도움을 얻어야 한다.

성능로그에서 Process\% Processor Time을 확인하여 CPU 100%으로 의심하는 Process를 확인할 수 있으며, Thread\% Processor Time을 확인하여 해당 Process의 Thread 중에서 CPU 100%을 점유하고 있는 Thread를 상위 그림과 같이 확인할 수 있다. 물론, ID Thread의 값(3536) 역시 확인할 수 있는 데, 이러한 정보는 High CPU 상태의 Hang Memory Dump (Troubleshooting High CPU Hangs with a Debugger: http://technet.microsoft.com/en-us/library/cc757239.aspx )에서 반드시 Check 해야 하는 Thread가 된다. Hang Memory Dump는 성능로그와 동시에 수집되어야 의미가 있으며, High CPU Hang 현상이 지속적인 Loop와 같은 Time Consuming 작업이기 때문에 이를 verify하기 위해서 반드시 2-3 차례 일정 시간 동안 Memory Dump를 수집하여 동일한 pattern의 time consuming 작업이 있는 것인지 아니면 다른 여러 Task가 존대하는 것인지 확인해보는 것이 중요하게 된다.

 

성능로그에서 CPU 100% 시점의 시간을 아래와 같이 알 수 가 있는 데, 이 시점이 Memory Dump가 수집된 시간과 일치하는 지 확인해야만 Hang Memory Dump가 의미 있게 된다.

Memory Dump에서는 다음과 같이 Snapshot 시점의 시간을 확인할 수 있다.

 

0:001> .time

Debug session time: Wed Sep  3 11:04:22.000 2008 (GMT+9)

System Uptime: 3 days 12:32:51.099

Process Uptime: 0 days 0:17:26.000

  Kernel time: 0 days 0:00:00.000

  User time: 0 days 0:01:16.000

 

그리고, CPU의 사용 및 지속시간은 2-3차례 잡은 Memory Dump에서 아래와 같이 확인 할 수 있다.

 

0:001> !runaway

 User Mode Time

  Thread       Time

   0:dd0       0 days 0:01:16.734

   1:16bc      0 days 0:00:00.000

 

!runaway는 CPU를 점유하고 있는 Thread의 정보를 알 수 있고, 일정시간 간격으로 잡은 Dump에서 확인해 본다면, 해당 Thread가 진행 중인지를 알 수 있으므로, 좋은 정보가 되며, 성능로그에서 확인했던 Thread ID 정보와 함께 High CPU를 유발 하는 Thread로 좁혀갈 수 있는 정보가 된다. 예를 들어, High CPU를 점유한 Thread ID 3536은 Hex 값으로 dd0 이다.

 

0:001> ? dd0

Evaluate expression: 3536 = 00000dd0

 

하여, 해당 Thread 에 대한 Callstack 확인을 통해 왜 High CPU를 유발 했는지 Check 하면 된다.

0:001> ~~[dd0]s

eax=0000000a ebx=7ffd3000 ecx=00000224 edx=0000000a esi=0012e774 edi=76971a90

eip=00412031 esp=0012fe18 ebp=0012fe6c iopl=0         nv up ei pl nz na pe nc

cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000206

buggy!highCPU+0x31:

00412031 99              cdq

0:000> kbL

ChildEBP RetAddr  Args to Child             

0012fe6c 00412152 76971a90 0012e774 7ffd3000 buggy!highCPU+0x31

0012fedc 004125ba 00000001 00381570 00381618 buggy!wmain+0xf2

0012ffc0 7c817067 76971a90 0012e774 7ffd3000 buggy!wmainCRTStartup+0x16a

0012fff0 00000000 0041118b 00000000 78746341 kernel32!BaseProcessStart+0x23

0:000> lsa buggy!highCPU

   162: int f;

   163: f = 0;

   164:

   165: for (int i = 0; i < 0x2fffffff; i++)

>  166: {

   167:             f = (f + 10) / 548;

   168: }

   169:

   170: return;

   171: }

 

Windows 32bit System 하에서 하나의 Process는 대략 2GB(~7fffffff address) Virtual Address 영역을 사용한다. 이는 사용자 모드에서 사용 가능한 가상메모리이며, 커널모드에서는 2GB를 따로 사용한다. (물론, 3gb option을 사용하면, bfffffff 까지 User mode에서 사용가능하고, 나머지 1GB는 kernel이 사용한다. Win32가 2^32 arrange 를 갖는 다고 생각하면, 하나의 Process가 사용할 수 있는 Virtual Address layout는 4GB이며, 이를 Kernel과 User mode에서 나눠 갖는 다고 생각하면 된다.) 이는 Physical Memory와 관련 없이 하나의 Process가 사용하는 가상메모리영역이다. 그러므로, Win32 System의 Windows 하에서 실행하는 임의의 User Mode Application이 2GB에 이르기까지 메모리를 사용하고 있다면, 메모리부족오류가 발생할 수 있다.

해당 Application이 메모리관련오류, 특히 메모리누수와 같은 문제를 갖고 있다면, Process가 사용하는 Memory 상태를 확인하는 것은 중요하다. 여기서 메모리의 상태라는 것은 reserve, committed 그리고, Free 를 말한다. Virtual Memory는 성능 및 여러 가지 이유로 임의의 영역을 reserve 하고 나서 실제 사용시에 commit 한다. 물론, 다 사용하고 나면 free 시킬 수 있다. 임의의 Process 에 Windbg를 Attach 하여 !vadump –v command를 실행하면, 연속된 가상메모리의 상태를 다음과 같이 확인할 수 있다.

 

BaseAddress:       533f0000

AllocationBase:    533f0000

AllocationProtect: 00000004  PAGE_READWRITE

RegionSize:        00001000

State:             00001000  MEM_COMMIT

Protect:           00000004  PAGE_READWRITE

Type:              00020000  MEM_PRIVATE

 

BaseAddress:       533f1000

AllocationBase:    00000000

RegionSize:        0000f000

State:             00010000  MEM_FREE

Protect:           00000001  PAGE_NOACCESS

 

BaseAddress:       53400000

AllocationBase:    53400000

AllocationProtect: 00000004  PAGE_READWRITE

RegionSize:        00001000

State:             00001000  MEM_COMMIT

Protect:           00000004  PAGE_READWRITE

Type:              00020000  MEM_PRIVATE

 

BaseAddress:       53401000

AllocationBase:    00000000

RegionSize:        0000f000

State:             00010000  MEM_FREE

Protect:           00000001  PAGE_NOACCESS

 

BaseAddress:       53410000

AllocationBase:    53410000

AllocationProtect: 00000004  PAGE_READWRITE

RegionSize:        00001000

State:             00001000  MEM_COMMIT

Protect:           00000004  PAGE_READWRITE

Type:              00020000  MEM_PRIVATE

 

메모리가 상당히 조각화되어 있다면, 해당 log는 상당한 양이 될 수도 있다. 반드시, .logopen 하여 file logging을 하도록 한 후에, 연속된 메모리의 상태를 차근차근히 살펴볼 필요가 있다. (하지만, 굉장히 짜증나는 작업이 될 수도 있다.) 그러면, 규칙적으로 Allocation되어 있는 데이타 Block을 찾거나, 메모리 곳곳에 마치 pinning되어 메모리조각화를 유발하는 메모리 block을 찾을 수도 있게 된다. (dc command를 통해 메모리영역에 Application개발자가 인식 가능한 데이터가 존재하는 지 확인해 볼 수 있으며, dds command를 통해 stack 영역인지 여부를 Check 할 수도 있다.

 

0:000> dds 533f0000

533f0000  533f0040

533f0004  00001000

533f0008  61447720 msdtcprx!UTLink<CMMPageInfo<CITransaction> *>::`vftable'

533f000c  533f0000

533f0010  53380008

533f0014  53400008

533f0018  00000001

533f001c  6149b778 msdtcprx!g_MemMgrCITransaction+0x20

533f0020  61431910 msdtcprx!UTStaticList<CITransaction *>::`vftable'

…

…

 

0:000> dds 53400000

53400000  53400040

53400004  00001000

53400008  61447720 msdtcprx!UTLink<CMMPageInfo<CITransaction> *>::`vftable'

5340000c  53400000

53400010  533f0008

53400014  533a0008

53400018  00000001

5340001c  6149b778 msdtcprx!g_MemMgrCITransaction+0x20

53400020  61431910 msdtcprx!UTStaticList<CITransaction *>::`vftable'

…

)

메모리 누수의 경우는 DebugDiag 와 같은 Tool이나, gflag에서 +ust option(create user mode stack database)를 이용한 UMDH.exe 를 이용하는 것이 API level에서 확인할 수 있는 가장 좋은 접근이지만, 이와 같은 접근 전에 전반적으로 메모리의 상태를 보고 이후에 좀 더 구체적으로 메모리 문제에 접근한다는 점에서 Virtual address dump는 유용할 수 있다.

NET 1.0기반의 Application을 이제 얼마나 Debugging 할까마는 Live Debugging을 위해 “Debugging Tools-dbgnetfx.exe” http://www.microsoft.com/downloads/details.aspx?displaylang=en&FamilyID=7C6EC49C-A8F7-4323-B583-6A7A6AEB5E66 에서 제공하는 SOS.dll을 이용해야 한다. (SOS는 Son Of Strike 의 약자이다. 과거에는 strike.dll을 가지고 debugging을 했었고, 이제는 그 아들내미를 사용한다.) 그리고, 덤으로 SieextPub.dll 이라는 Debugger Extension도 제공하는 데, remote RPC call을 확인하거나, raw stack tracking 및 COM Threading 관련 extension으로 유용하다. (Microsoft에는 SIE라는 직급이 있었다. Solution RRE라고 하다가 지금은 PFE 라고 하는 데, Site에 방문하여 T-shooting 을 하는 Engineer들이다. 예전의 이름을 붙여서 SIE가 사용하는 EXTension 으로 PUBlic 하게 Open 된 것이라고 보면 된다.)