태그 : debugging
2009/07/10   Monitor Lock에 의한 hang 현상 debugging
2009/07/08   일부 레지스터의 사용에 관하여
2009/07/01   메시지(Window Message) 따라 디버깅
2009/06/22   성능로그를 통한 GC에 의한 High CPU 확인
2009/06/15   Internet Explorer+VB Runtime에서의 Crash 현상
Monitor Lock에 의한 hang 현상 debugging

.NET에서 lock 을 목적으로 가장 많이 사용되는 것이 Monitor 가 아닐까 한다. (사실 Multiple Processes사이에서의 Lock이 필요하다면, Mutex를 이용하는 데, 그렇지 않은 경우라면 좀처럼 Mutex를 이용하지 않는 다. 이유는 대략 Monitor에 비해 50여배정도의 low Performance를 나타낸다고 한다. –C# 3.0 in a nutshell에 의하면) 쉽게 Enter/TryEnter Exit 을 통해 Object Lock 을 거는 형태인데, single thread 만 허용하도록 하는 데 목적이 있다. C#에서는 단순하게 lock keyword 를 사용하는 경우가 Monitor를 대신하는 역할을 한다. 그러므로, Exit이 호출되기까지 마치 Critical Section Lock이 걸린 듯하게 된다. 그러므로, Multiple Threaded 환경에서 Exit이 되지 않은 상태에서 Exception이 발생하거나 Thread Drop되는 경우 등등에서 Application Hang이 발생할 수도 있고, 또한 DeadLock이 발생할 수도 있다. 이런 hang 상태일 경우를 메모리dump에서 확인하는 과정은 !syncblk 라는 SOS Extension에서 제공하는 Command를 이용하는 방법이다.

 

0:005> !syncblk

Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner

   20 0017439c            7         1 0018fe10   a5c  17   08e05824 System.Web.Compilation.BuildManager

 

0:005> !threads

ThreadCount: 14

UnstartedThread: 0

BackgroundThread: 14

PendingThread: 0

DeadThread: 0

Hosted Runtime: no

                                      PreEmptive   GC Alloc           Lock

       ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception

   5    1  aac 00151e18   2008220 Enabled  04e843b8:04e84fe8 00191270     1 Ukn

  11    2  69c 00160500      b220 Enabled  00000000:00000000 00157258     0 MTA (Finalizer)

  12    3  ad8 00176250    80a220 Enabled  00000000:00000000 00157258     0 MTA (Threadpool Completion Port)

  13    4  a0c 0018d698   8801220 Enabled  00000000:00000000 00157258     0 Ukn (Threadpool Completion Port)

  14    5  aa4 0018dd30   380b220 Enabled  08e8e38c:08e8efe8 00191270     1 MTA (Threadpool Worker)

  15    6  a94 0018e5f8   8801220 Enabled  00000000:00000000 00157258     0 Ukn (Threadpool Completion Port)

   1    7  948 0018eda0   880a220 Enabled  00000000:00000000 00157258     0 MTA (Threadpool Completion Port)

  16    8  ab4 0018f658   8801220 Enabled  00000000:00000000 00157258     0 Ukn (Threadpool Completion Port)

  17    9  a5c 0018fe10   180b220 Enabled  0ce914f8:0ce92fe8 00191270     4 MTA (Threadpool Worker)

  18    a  ae0 00190918      1220 Enabled  00000000:00000000 00157258     0 Ukn

  19    b  aa8 00192e18   180b220 Enabled  0cecf71c:0ced0fe8 00191270     1 MTA (Threadpool Worker)

  21    c  7a4 001dc8e0   180b222 Disabled 04eec338:04eecfe8 00191270     3 MTA (Threadpool Worker)

  22    d  664 00201108   380b220 Enabled  0ceca780:0cecafe8 00191270     1 MTA (Threadpool Worker)

25    e  500 0021b030   180b220 Enabled  00f10350:00f10814 00191270     1 MTA (Threadpool Worker)

 

!syncblk의 결과값을 보면, 오브젝트 System.Web.Compilation.BuildManager(08e05824) Lock이 걸려있는 상태임을 알 수 있다. 그리고, MonitorHeld 7이라는 것은 (7-1)/2 하여 대략 3개의 Thread가 해당 Object를 접근하려고 기다리는 것임을 알 수 있다. 보통은 아래와 같은 Thread가 접근하는 Thread가 되겠다.

 

ChildEBP RetAddr  Args to Child             

1ce4edec 7c59a23d 00000001 1ce4ee14 00000001 NTDLL!ZwWaitForMultipleObjects+0xb

1ce4ee3c 79f8ead4 1ce4ee14 00000001 00000000 KERNEL32!WaitForMultipleObjectsEx+0xea

1ce4eea4 79f17522 00000001 001743b0 00000000 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0x6f

1ce4eec4 79f17493 00000001 001743b0 00000000 mscorwks!Thread::DoAppropriateAptStateWait+0x3c

1ce4ef48 79f1732f 00000001 001743b0 00000000 mscorwks!Thread::DoAppropriateWaitWorker+0x144

1ce4ef98 79f8ea4d 00000001 001743b0 00000000 mscorwks!Thread::DoAppropriateWait+0x40

1ce4eff4 79e77f50 ffffffff 00000001 00000000 mscorwks!CLREvent::WaitEx+0xf7

1ce4f004 7a0fd9c3 ffffffff 00000001 00000000 mscorwks!CLREvent::Wait+0x17

1ce4f090 7a0fdbbf 00201108 ffffffff 0017439c mscorwks!AwareLock::EnterEpilog+0x94

1ce4f0ac 7a0fdd2a f6aa917c 00201108 00201108 mscorwks!AwareLock::Enter+0x61

1ce4f110 7a094352 ffffffff f6aa91dc 0ceca598 mscorwks!AwareLock::Contention+0x16c

1ce4f1b0 65fb7bcf 79e73dce 08e05824 00000000 mscorwks!JITutil_MonContention+0xa3

1ce4f1f0 65fcf629 00000000 00000000 00000000 System_Web_ni!System.Web.Compilation.BuildManager.GetBuildResultFromCacheInternal(System.String, Boolean, System.Web.VirtualPath, Int64)+0x77

1ce4f26c 65fcf2ef 00000000 00000000 00000000 System_Web_ni!System.Web.Compilation.BuildManager.GetVPathBuildResultFromCacheInternal(System.Web.VirtualPath)+0x29

1ce4f26c 65fcf266 00000000 00000000 00000000 System_Web_ni!System.Web.Compilation.BuildManager.GetVPathBuildResultInternal(System.Web.VirtualPath, Boolean, Boolean, Boolean)+0x37

1ce4f2a8 66036b2d 00000000 00000000 00000000 System_Web_ni!System.Web.Compilation.BuildManager.GetVPathBuildResultWithNoAssert(System.Web.HttpContext, System.Web.VirtualPath, Boolean, Boolean, Boolean)+0x5e

1ce4f2d4 661528dc 00000000 00000000 00000000 System_Web_ni!System.Web.Compilation.BuildManager.GetVPathBuildResult(System.Web.HttpContext, System.Web.VirtualPath)+0x31

1ce4f2d4 69926307 00000000 00000000 00000000 System_Web_ni!System.Web.UI.WebServiceParser.GetCompiledType(System.String, System.Web.HttpContext)+0x2c

1ce4f2ec 65fb94bc 00000000 00000000 00000000 System_Web_Services_ni!System.Web.Services.Protocols.WebServiceHandlerFactory.GetHandler(System.Web.HttpContext, System.String, System.String, System.String)+0x47

1ce4f32c 65fce689 00000000 00000000 00000000 System_Web_ni!System.Web.HttpApplication.MapHttpHandler(System.Web.HttpContext, System.String, System.Web.VirtualPath, System.String, Boolean)+0xb0

 

Monitor Lock의 내부적인 구조는 mscorwks!AwareLock이다. 그러므로, mscorwks!AwareLock::Enter Monitor Lock Enter에 해당한다고 보면 된다. 그리고, !syncblk의 결과에서 owning threadLock안에 들어가 있는 Thread가 된다. 그러므로, 17 Thread가 현재 System.Web.Compilation.BuildManager(08e05824)를 잡고 있는 Thread이므로 해당 Thread에서 exit 되지 않으며 다른 3개의 Thread에서의 처리를 요청한 User Hang을 느낄 수 있다.

 

0:017> !dso

OS Thread Id: 0xa5c (17)

ESP/REG  Object   Name

. . .

1a3cf2f0 08e05824 System.Web.Compilation.BuildManager

 

0:017> kb

ChildEBP RetAddr  Args to Child             

1a3ccd60 7c59a072 000001cc 00000000 00000000 NTDLL!ZwWaitForSingleObject+0xb

1a3ccd88 79e77fd1 000001cc ffffffff 00000000 KERNEL32!WaitForSingleObjectEx+0x71

1a3ccdcc 79e77f9a 000001cc ffffffff 00000000 mscorwks!PEImage::LoadImage+0x199

1a3cce1c 79e77f50 ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117

1a3cce2c 79f3b282 ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17

1a3cce3c 79f75d6a 00000000 f072ae20 00000000 mscorwks!SVR::GCHeap::WaitUntilGCComplete+0x32

1a3cce78 79e7ada1 f072aedc 00000000 1a3ccef8 mscorwks!Thread::RareDisablePreemptiveGC+0x1a1

1a3cceb0 79e7a6c9 79e7a6bd 0014a290 79e7a2c3 mscorwks!CrstBase::Enter+0x1e6

1a3cceb4 79e7a6bd 0014a290 79e7a2c3 7a38cf40 mscorwks!EEEnterCriticalSection+0x9

1a3ccebc 79e7a2c3 7a38cf40 0014a290 79eab324 mscorwks!CExecutionEngine::AcquireLock+0x9

1a3ccec8 79eab324 0014a290 002148f0 7a144ea3 mscorwks!ClrEnterCriticalSection+0xf

1a3cced4 7a144ea3 f072af58 00000000 002148f0 mscorwks!CCriticalSection::Lock+0x17

1a3cdb80 7a14560a 00000000 0000000a 00000000 mscorwks!CAssemblyCacheItem::MoveAssemblyToFinalLocation+0x31f

1a3cdbc8 7a143a97 0000000a 00000000 00000000 mscorwks!CAssemblyCacheItem::LegacyCommit+0x245

1a3cdc04 7a15e4b4 002148f0 00000000 00000000 mscorwks!CAssemblyCacheItem::Commit+0x5d

1a3ce2b0 7a15e936 1a3ce644 001f79c0 1a3ce328 mscorwks!CAsmDownloadMgr::CreateAssembly+0x85b

1a3ce2ec 7a15f074 1a3ce644 001f79c0 1a3ce328 mscorwks!CAsmDownloadMgr::DoSetupPushToCache+0x50

1a3ce574 79f8e8f8 001fc230 001f79c0 1a3ce644 mscorwks!CAsmDownloadMgr::DoSetup+0x26a

1a3ce5c0 79f8c05c 1a3ce644 00000000 f0728598 mscorwks!CAssemblyDownload::DoSetup+0x7b

1a3ce5f4 79f8bf74 00000000 1a3ce644 00000000 mscorwks!CAssemblyDownload::DownloadComplete+0xb6

 

상위에서는 PEImage Load 될 때까지는 Lock이 풀리지 않을 듯

by 강세윤 | 2009/07/10 17:33 | Windows debugging | 트랙백 | 덧글(0)
일부 레지스터의 사용에 관하여

레지스터는 CPU 연산에 필요한 데이타를 사용하기 위한 저장고이다. IA32 체계에서 EAX, EBX ECX, ESI, EDI 등등의 명칭으로 사용되고 있는 데, register가 사용되는 용도가 구분되어 있다. (참고: http://ko.wikipedia.org/wiki/IA32#.EB.A0.88.EC.A7.80.EC.8A.A4.ED.84.B0) Debugging 하다 보면, Assembly 언어를 분석할 때, register의 용도에 따라서 적절히 분석되는 것이 필요한데 몇가지 문서에 언급외에 독특한 register의 사용에 대해서 언급하고자 한다.

 

0:000> u 766dbf97-10 766dbf97+10

wininet!MEMMAP_FILE::ValidateListGroupOffset+0x38:

766dbf87 038d34118bc6    add     ecx,dword ptr [ebp-3974EECCh]

766dbf8d 5e              pop     esi

766dbf8e 5d              pop     ebp

766dbf8f c20400          ret     4

766dbf92 90              nop

766dbf93 90              nop

766dbf94 90              nop

766dbf95 90              nop

766dbf96 90              nop

wininet!MEMMAP_FILE::GrowMapFile:

766dbf97 8bff            mov     edi,edi

766dbf99 55              push    ebp

766dbf9a 8bec            mov     ebp,esp

766dbf9c 56              push    esi

766dbf9d 8bf1            mov     esi,ecx

766dbf9f 8b4604          mov     eax,dword ptr [esi+4]

766dbfa2 8b4e18          mov     ecx,dword ptr [esi+18h]

766dbfa5 69c080ed0100    imul    eax,eax,offset <Unloaded_es_kr.dll>+0x1ed6f (0001ed80)

 

Nop No-operation이다. 근데, Function starting point (노란색 블럭)mov edi, edi 가 보인다. 사실 그 아래 push ebp; mov ebp, esp; 는 일반적으로 Stack Frame을 만드는 시작 code이다. ebp stack base address이므로, 앞선 Function stack frame에 대한 base address stack save 하여 보존하고, 현 시점의 stack pointer base address로 지정하여 새로운 stack frame을 시작하도록 하는 역할을 한다. 그러므로, 그 앞서서 있는 mov edi, edi는 아무런 의미가 없다. , nop와 동일하다. 다른 점이라면, 2bytes opcode로써의 nop라는 점이다. 이는 나중에 jmp code로 변경하여 Hot patching에 이용되도록 집어 넣어둔 code이다. 이와 같은 방식은 CLR에서 method jitting의 경우도 방법자체로 보면 유사하다. MethodDesc RVA라는 거의 의미 없는 값을 가지고 있다가 나중에 JIT에 의해서 code generation된 이후에는 jmp instruction으로 해당 code address를 가리키도록 op code가 변경되는 구조를 갖는 다.

 

그 다음은 ecx/esi 에 대한 부분이다. ecx는 일반적으로 loop counter역할을 담당한다. 하지만, Debugging 할때 가장 많이 경험하는 것은 counter의 역할보다는 this pointer를 넘기는 데, 많이 사용된다. 

 

ChildEBP RetAddr  Args to Child             

00125bfc 76698bd7 00004000 00125c74 00000020 wininet!MEMMAP_FILE::GrowMapFile+0xb0 (FPO: [1,0,0])

00125c38 7667ff81 00001000 00000031 00000000 wininet!MEMMAP_FILE::AllocateEntry+0x4d (FPO: [Non-Fpo])

 

0:000> ub 76698bd7

. . .

76698bcf 50              push    eax

76698bd0 8bcb            mov     ecx,ebx   <- - - this pointer wininet!MEMMAP_FILE Class

76698bd2 e8c0330400      call    wininet!MEMMAP_FILE::GrowMapFile (766dbf97)

 

This pointer는 곧바로 esi register mov 된다. ecx register Frame 안에서 counter와 같은 범용레지스터로 사용되기 때문에 this pointer보존을 위해 esi mov 하고, esi+offset 형태로 this class member function이나 member property에 접근할 수 있다. 아래와 같은 assembly code 형태가 말해준다.

 

766dbf9c 56              push    esi

766dbf9d 8bf1            mov     esi,ecx

766dbf9f 8b4604          mov     eax,dword ptr [esi+4]

766dbfa2 8b4e18          mov     ecx,dword ptr [esi+18h]

 

그리고, 또한 eax register 의 역할이다. 아래 assembly code를 보면, function call되기 전에 push에 의해서 parameter를 전송하는 아름다운 모습이 보인다. 이는 Function calling convention에 의존적이다. 그리고, 나면, 저 아래께 쯤에 cmp instruction에 뜬금없는 eax ecx의 비교가 보인다. ecx esi+offset의 언급한 this class member property로 부터 온것임을 알 수 있다. 그럼, eax는 무엇인가 .

 

766dbfc2 6a02            push    2

766dbfc4 6a00            push    0

766dbfc6 57              push    edi

766dbfc7 ff761c          push    dword ptr [esi+1Ch]

766dbfca ff1570116676    call    dword ptr [wininet!_imp__SetFilePointer (76661170)]

766dbfd0 8b4e18          mov     ecx,dword ptr [esi+18h]

766dbfd3 03cf            add     ecx,edi

766dbfd5 3bc1            cmp     eax,ecx

 

이는 SetFilePointer function return value 이다. eax는 항상 function call이후에 return 값을 저장하는 데, 사용된다.

by 강세윤 | 2009/07/08 14:06 | Windows debugging | 트랙백 | 덧글(0)
메시지(Window Message) 따라 디버깅

 

Message 기반의 Window에서 특히 MFC Application 같은, Debugging 시에 특정 Button Click 하면 Button Click에 대한 Function Call이 호출되고 어쩌구저쩌구 하는 경우, 간혹, 정확한 정보를 모르는 상태에서 Debugging을 하다 보면 난감할 때가 있다. 이런 경우, 가장 유용한 방법이 SPY Tool을 이용하는 것이다. 예를 들어, button하나 누르는 MFC Application을 가지고 살펴보면, 아래는 SPYmain window를 잡은 화면이다. 지금 하고자 하는 것은 button click하는 함수를 찾아 들어가는 것이다. (굳이 왜 이런 짓을 ..

SPY TOOL을 열어놓고, 메뉴의 Search 에서 Find Window 하여 MFC Application Main window drag하면 Windows1 화면에서 Highlighted Window가 바로 그놈 이다. 이름이 MfcBtnTest 라는 놈이다. 그리고, View 메뉴에서 속성을 확인하면 Property Inspector라는 창이 뜬다. 원하는 정보는 WinProc 이다. 여기에 5804f141 이라는 Address가 보인다. 이게 뭘까 …. WinDbg로 해당 Application에 걸면 WinProc Function이 보일 테이다. 아래와 같다. 아시다시피 AfxWndProcBase 이다. MFC Application의 기본적인 WinProc 이 되겠다. 보통 일반적인 Window Application 이라면, WindowProc (http://msdn.microsoft.com/en-us/library/ms633573(VS.85).aspx) 일 텐데..

 

0:001> ln 5b04f141

f:\dd\vctools\vc7libs\ship\atlmfc\src\mfc\afxstate.cpp(439)  ß아시다시피 해당 소스는 VS에서 구할 수 있다. C:\Program Files\Microsoft Visual Studio 9.0\VC\atlmfc\src

(5b04f141)   mfc90u!AfxWndProcBase   |  (5b04f1c1)   mfc90u!AfxGetAppModuleState

Exact matches:

    mfc90u!AfxWndProcBase (struct HWND__ *, unsigned int, unsigned int, long)

 

조금은 복잡하게 됐다. 그리고, button click에 대한 Function을 쫓아 갈 차례다. WindowProc이건 AfcWndProcBase 건 간에 Message ID로 주고 받는 다. 이것도 역시 SPY로 정보를 얻을 수 있다. Main Window에서 Message Filtering을 하는 데, WM_COMMAND 를 잡으면 된다.

wID Msg 정보를 나타낸다. 1000(0x3e8) 이것이 Message 정보이다. 그러므로, Message Handler 0x3e8 이 처리되는 것이 바로 내가 원하는 Button Click 시의 Message 를 나타낸다. 간단하게는 WindowProc Assembly Code에서 0x3e8 Handling 하는 놈을 찾으면 되겠다. MFC에서는 _AfxDispatchCmdMsg 함수에서 0x3e8(두 번째 parameter) Handling 하여 원하는 Function으로 보낸다.

 

0:000> kp

ChildEBP RetAddr 

001af54c 5b080346 mfc90u!_AfxDispatchCmdMsg(class CCmdTarget * pTarget = 0x001afc20, unsigned int nID = 0x3e8, int nCode = 1766796, <function> * pfn = 0x01031440, void * pExtra = 0x00000000, unsigned int nSig = 0, struct AFX_CMDHANDLERINFO * pHandlerInfo = 0x00000000) [f:\dd\vctools\vc7libs\ship\atlmfc\src\mfc\cmdtarg.cpp @ 54]

001af568 5b070e92 mfc90u!CCmdTarget::OnCmdMsg(unsigned int nID = 0x3e8, int nCode = 0, void * pExtra = 0x00000000, struct AFX_CMDHANDLERINFO * pHandlerInfo = 0x00000000)+0x124 [f:\dd\vctools\vc7libs\ship\atlmfc\src\mfc\cmdtarg.cpp @ 381]

. . .

 

0:000> ln 0x01031440

g:\codes\mfcbtntest\mfcbtntest\mfcbtntestdlg.cpp(154)

(01031440)   MfcBtnTest!CMfcBtnTestDlg::OnBnClickedButton1   |  (01031460)   MfcBtnTest!CDialog::Create

Exact matches:

    MfcBtnTest!CMfcBtnTestDlg::OnBnClickedButton1 (void)

 

0:000> uf 0x01031440

MfcBtnTest!CMfcBtnTestDlg::OnBnClickedButton1 [g:\codes\mfcbtntest\mfcbtntest\mfcbtntestdlg.cpp @ 154]:

  154 01031440 6a00            push    0

  156 01031442 68e0350301      push    offset MfcBtnTest!`string' (010335e0)

  156 01031447 68e0350301      push    offset MfcBtnTest!`string' (010335e0)

  156 0103144c 6a00            push    0

  156 0103144e ff15b8300301    call    dword ptr [MfcBtnTest!_imp__MessageBoxW (010330b8)]

157 01031454 c3              ret

 

아 왜 이런 쓸데없는 짓을 그냥 OnBnClickButton1 Break을 걸면 되지 않나.. 머 이럴수도 있겠다만, 맞는 말이다. 하지만, 여러 3rd party application Debugging 하다 보면, 복잡한 UI에서 도대체 Button Click 하면 어떤 Function으로 들어가는지 아무도 모르는 경우가 존재한다. 또 그런 Application Debugging 할 기회(?)도 존재한다. 그와 같은 때 유용하며, 이렇게 SPY WinDBG를 통해서 Message를 쫓아가는 경우는 여러 가지 응용도 가능하겠다.

by 강세윤 | 2009/07/01 16:43 | Windows debugging | 트랙백 | 덧글(0)
성능로그를 통한 GC에 의한 High CPU 확인

Garbage Collector(GC) .Net Framework / CLR 에서 Memory를 관리해주는 Module 이다. 그러므로, 개발자의 의도와 상관없이 적절한 시점에 GC가 수행하고, 그것도 비동기적으로 발생하며, 그에 의해 메모리를 효율적으로 사용할 수 있도록 해준다. 문제는 GC가 비동기적으로 수행됨에 의해 임의의 시점에 GC의 수행과 더불어 응용프로그램의 성능에 영향을 줄 수도 있다라는 것이다. 성능에 영향을 미친다는 것은 예상보다 긴 시간 동안에 GC가 수행되고 이에 의해 High CPU상태가 User가 견디기 힘들 정도로 지속될 수 도 있다는 것이다.

 

그렇다면, .NET Application High CPU일 경우에 GC에 의해 영향을 받은 것인지 어떻게 체크할 수 있을 까. 사실 해당 작업은 그렇게 쉽게 확인할 수 없지만, 몇 가지 요소를 통해서 문제를 좁혀나갈 수 있다.

 

첫 번째로는 %Time IN GC/.NET CLR Memory 성능 카운터의 값을 확인하는 것이다. 이 값은 최근 GC가 수행함에 의해 소요된 시간의 백분율 값이다. 설명은 그렇게 되어 있는 데, 일단, 50% 이상으로 높다라면, Managed Heap에서 Allocation 되는 패턴을 확인해야 한다. 일반적으로 평균 5% 정도나 10%이하라면 신경 쓸 필요가 없어 보인다. 그리고, 5% 이하라면 의미 있는 Data가 아니므로, 어떠한 판단을 하기가 어렵다. 하지만, 50% 이상이라면, Allocated Bytes/sec 를 확인하여 Allocation rate 를 확인하는 것이 필요하다.

 

실제로, Performance Monitoring을 통해서 % Processor Time High CPU상태로 어느 정도 지속이 된다면, 문제라고 판단한다. 그러므로, High CPU를 유발하는 Thread Check 하고, Thread Stack Check하여 Looping과 같은 Code에 의해 Thread High CPU를 유발하는 것이 아닌가 확인하는 작업이 필요하게 되는 데, 해당 Thread가 역시 GC Thread일 수도 있다. 이는 Memory Dump에서 성능로그에 High CPU를 유지하는 Thread ID Check하여 해당 Thread ID에 대한 메모리 덤프의 Thread Check했을 때, SOS extension에서 제공하는 !threads result GC라고 표시된 Thread와 일치한다면, GC에 의해서 High CPU라고 확인할 수 있을 것이다. 또는 %Time IN GC의 값이 변동이 있을 때, 예를 들어, High에서 Low로 떨어지거나 Low에서 High로 상승하는 시점에 %Processor Time Peak를 친다면, GC에 의해서 High CPU가 유발되었다고 추측할 수도 있다. 이는 메모리 덤프에 의한 Double check가 필요하다.

 

% Time IN GC가 높아서 High CPU라는 것은 결국, GC가 너무 자주 수행되거나 오랫동안 수행된다는 것이다. 그러므로, 이미 언급한 것처럼, 일반적인 Allocation rate이 높아서 GC가 자주 발생하는 것이라면, Allocation pattern에 대한 체크가 필요하며, 두 번째는 # GenX GC counters를 확인하는 것이다. 이는 얼마나 자주 GC가 수행되는 지 확인할 수 있을 것이다. 일반적으로 초점이 되는 것은 Gen2 GC이다. Gen0/Gen1 Performance에 크게 영향을 주지 않는 다. 하지만, Gen2 Large Object Heap의 경우는 Performance에 영향을 많이 준다. 일반적으로 gen2:gen1 의 비율이 1:10+ 정도라면 크게 우려할 정도가 아니다. 하지만, 그렇지 않다면, gen2에서의 GC 수행이 영향을 미쳤다고 추측하게 된다. 이 경우는 응용프로그램이 gen2에 적재되어 있을 수 있고, 계속해서 promotion gen1으으부터 이뤄지고 있다고 판단할 수 있는 데, 결국, gen2까지 살아남은 Objects에 대한 Verification이 필요하다. Gen2까지 살아 남을 필요가 있는 Objects들인가.. 이는 메모리 덤프에서 SOS !dumpheap –stat –gen2 command를 통해서 Objects를 확인할 수 있다. 그러므로, 응용프로그램의 Performance를 위해서 Objects의 조기에 release 하는 Code적인 장치가 필요할 수도 있다. 결국, 이러한 경우에는 개발자가 성능적인 이유를 위해서 적절한 Objects release 를 간여해야 한다는 것이다. GC만을 믿을 수 없다.

 

마지막으로는 모호하긴 하지만, #induced GC값이다. 해당 값은 프로세스가 시작된 이후에 GC의 발생횟수를 나타낸다. 이 값이 너무 큰 값이라면, 이는 응용프로그램의 버그를 의심할 수 있다. 가끔 메모리 힙의 크기가 증가되는 것을 줄이기 위해서 강제적으로 GC.Collect 를 호출하는 경우가 있는 데, 이로 인하여 오히려 performance 에 문제가 된 것은 아닌지 확인해 볼 수도 있을 것 같으며, 그렇지 않으면, Heap Corruption 발생하여 비 정상적인 동작이 있을 수도 있다. 이 경우도 High CPU가 될 수 있음을 확인해야 할 것이다

 

 

by 강세윤 | 2009/06/22 11:33 | Windows debugging | 트랙백 | 덧글(0)
Internet Explorer+VB Runtime에서의 Crash 현상

사실 아직까지 VB runtime Internet Explorer에 올라가 있다는 것은 그리 놀랍지 않다. COM개발이 도입이 되면서 ActiveX Control의 개발은 VB가 대체로 대세였다. 개발의 속도 면에서 그리고, User Interface를 쉽게 제공해주는 면에서 거부할 수 없는 선택 이였다. 하지만, VB runtime의 태생적인 Threading Model의 한계는 Internet Explorer가 마치 Server Application Environment 처럼 변모하면서 너무나 많은 제약을 얻을 수 밖에 없게 되었다. 다음의 Crash 현상 역시 이러한 변화 속에서 드러나는 단면이다.

 

0:000> kbL

ChildEBP RetAddr  Args to Child             

WARNING: Frame IP not in any known module. Following frames may be wrong.

001273e8 66107873 0eddbd00 00000000 00127494 <Unloaded_es_kr.dll>+0x64ff81

00127400 66107bec 00000000 00127424 03ffe070 MSVBVM60!ExHandleLBFailure+0x20

00127458 661079e5 03ffe070 80010003 00000004 MSVBVM60!ExLateIdNamed+0xca

00127484 66108b9a 03ffe070 80010003 fffffffd MSVBVM60!ExLateIdSt+0x4a

0012749c 06977430 03ffe070 80010003 00000004 MSVBVM60!__vbaLateIdSt+0x16

00127508 660ca914 0cd4f1d0 00000000 0cd4f1d0 ttt!DllCanUnloadNow+0x2e61e

00127564 660cae57 00000006 00000001 0e801210 MSVBVM60!RUN_INSTMGR::ExecuteInitTerm+0x178

00127598 660caab3 00000000 00000013 0400758c MSVBVM60!RUN_INSTMGR::CreateObjInstanceWithParts+0x1e4

00127618 660cbc3a 0cd4f1ec 00000000 00127a00 MSVBVM60!RUN_INSTMGR::CreateObjInstance+0x14d

001278cc 66072b6e 001278e4 00000000 03ffa66d MSVBVM60!TipCreateInstanceEx+0xd5

00127908 66078642 01572100 06930000 00000000 MSVBVM60!CThreadPool::CreateInstanceFactory+0xfd

00127a04 66078226 03ff4e8c 00000000 00000000 MSVBVM60!CPrivClassFactory::CreateInstanceLic+0x16e

00127a20 7e605619 03ff4e8c 00000000 7e3a3028 MSVBVM60!CPrivClassFactory::CreateInstance+0x1a

00127a5c 7e60aa10 031d8e48 031d9654 80004005 mshtml!COleSite::InstantiateObjectFromCF+0x114

00129ae0 7e60b386 7e3b919c 03ff4e8c 031d9654 mshtml!COleSite::CreateObjectNow+0xa5

00129b04 7e60bc1a 031d9610 7e3b919c 03ff4e8c mshtml!CCodeLoad::OnObjectAvailable+0x84

00129b78 7e60bf76 7e391b04 00129c68 031d8e00 mshtml!CCodeLoad::BindToObject+0x460

00129b98 7e605369 031d8e00 00129c68 7e60f904 mshtml!CCodeLoad::Init+0x287

00129c18 7e60f85c 00129c68 13ca5100 031d9470 mshtml!COleSite::CreateObject+0x26d

0012ddc8 7e5f393b 7e4306e9 13c9b6c0 00000020 mshtml!CObjectElement::CreateObject+0x72a

 

es_kr.dll unload되었다고 믿기 어렵다. 최종 Stack에서 Assembly Check하더라고 이것이 정확한 instruction인지 믿기 어려운 상황이다.

 

0:000> u

<Unloaded_es_kr.dll>+0x64ff81:

00650072 6f              outs    dx,dword ptr [esi]

00650073 bc46c045c0      mov     esp,0C045C046h

00650078 0000            add     byte ptr [eax],al

0065007a 0000            add     byte ptr [eax],al

0065007c e8e8448a00      call    <Unloaded_es_kr.dll>+0xef4478 (00ef4569)

00650081 0000            add     byte ptr [eax],al

00650083 0000            add     byte ptr [eax],al

00650085 008001000000    add     byte ptr [eax+1],al

 

이러한 경우는 최종적으로 Thread Stack이 정상적으로 보이는 Frame에서 EIP가 잘못될 가능성이 없는 지를 Check 해야 한다.

 

ChildEBP RetAddr  Args to Child

001273e8 66107873 0eddbd00 00000000 00127494 <Unloaded_es_kr.dll>+0x64ff81

00127400 66107bec 00000000 00127424 03ffe070 MSVBVM60!ExHandleLBFailure+0x20

 

0:000> ub 66107873

MSVBVM60!ExHandleLBFailure+0xc:

6610785f ff15b8100066    call    dword ptr [MSVBVM60!_imp__TlsGetValue (660010b8)]

66107865 8bd8            mov     ebx,eax  <--- eax TlsGetValue return

66107867 8b03            mov     eax,dword ptr [ebx]

66107869 85c0            test    eax,eax

6610786b 7409            je      MSVBVM60!ExHandleLBFailure+0x23 (66107876)

6610786d 8b08            mov     ecx,dword ptr [eax]  <--- ecx eax address

6610786f 50              push    eax

66107870 ff5108          call    dword ptr [ecx+8]

 

0:000> r

eax=0eddbd00 ebx=001e1f38 ecx=0ce1ef38 edx=04009b10 esi=00127494 edi=00000000

eip=00650072 esp=001273ec ebp=00127400 iopl=0         nv up ei pl nz na pe nc

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

<Unloaded_es_kr.dll>+0x64ff81:

00650072 6f              outs    dx,dword ptr [esi]   ds:0023:00127494=fffffffd

 

0:000> ? 0ce1ef38+8

Evaluate expression: 216133440 = 0ce1ef40 <--- call dword ptr[0ce1ef40]

 

하지만, 아래 data를 보면, Method로 보이진 않는 다. 단지 String Data로 보인다. 그러므로, Tls Broken 된 것으로 추측할 수 있다.

 

0:000> dc 0ce1ef40

0ce1ef40  00650072 003a0072 00680020 00740074  r.e.r.:. .h.t.t.

0ce1ef50  003a0070 002f002f 00300037 0032002e  p.:././.7.0...2.

0ce1ef60  0031002e 00300034 0031002e 00300034  ..1.4.0...1.4.0.

0ce1ef70  0039003a 00310030 002f0036 00740068  :.9.0.1.6./.h.t.

0ce1ef80  006c006d 00700043 002f0063 00720070  m.l.C.p.c./.p.r.

0ce1ef90  002f006f 0048004d 0046005f 00310030  o./.M.H._.F.0.1.

0ce1efa0  0030005f 002e0031 0073006a 000d0070  _.0.1...j.s.p...

0ce1efb0  0041000a 00630063 00700065 002d0074  ..A.c.c.e.p.t.-.

 

0:000> dc 0ce1ef40-10

0ce1ef30  00a20016 030a01ee 0e98bb18 00650066  ............f.e.

0ce1ef40  00650072 003a0072 00680020 00740074  r.e.r.:. .h.t.t.

0ce1ef50  003a0070 002f002f 00300037 0032002e  p.:././.7.0...2.

0ce1ef60  0031002e 00300034 0031002e 00300034  ..1.4.0...1.4.0.

0ce1ef70  0039003a 00310030 002f0036 00740068  :.9.0.1.6./.h.t.

0ce1ef80  006c006d 00700043 002f0063 00720070  m.l.C.p.c./.p.r.

0ce1ef90  002f006f 0048004d 0046005f 00310030  o./.M.H._.F.0.1.

0ce1efa0  0030005f 002e0031 0073006a 000d0070  _.0.1...j.s.p...

 

0:000> u MSVBVM60!ExHandleLBFailure 66107873

MSVBVM60!ExHandleLBFailure:

66107853 55              push    ebp

66107854 8bec            mov     ebp,esp

66107856 53              push    ebx

66107857 56              push    esi

66107858 57              push    edi

66107859 ff357cee1066    push    dword ptr [MSVBVM60!g_itlsEbthread (6610ee7c)]

6610785f ff15b8100066    call    dword ptr [MSVBVM60!_imp__TlsGetValue (660010b8)]

66107865 8bd8            mov     ebx,eax

66107867 8b03            mov     eax,dword ptr [ebx]

66107869 85c0            test    eax,eax

6610786b 7409            je      MSVBVM60!ExHandleLBFailure+0x23 (66107876)

6610786d 8b08            mov     ecx,dword ptr [eax]

6610786f 50              push    eax

66107870 ff5108          call    dword ptr [ecx+8]

 

Thread Stack은 다르더라도 상위의 TLS(Thread Local Storage)연산에 대한 Assembly code는 기억해둘 필요가 있다. VB runtime Thread Safe 한 처리를 이유로 주로 TLS를 이용한다. 하지만, IE7 이상의 Browser에서 TAB Browser의 처리에 따라서 동일한 VB ActiveX Control이 중복해서 하나의 Browser load되는 가능성도 커졌다. 이에 따라서 TLS slot이 고갈되어 VB Runtime TLS 연산에서 crash가 발생하는 경우가 빈번해졌다. 만일, Vista OS 사용한다면, 같이 shipping VB runtime에서는 문제되지 않지만, XP machine이라면 이러한 Crash를 볼 수 있다.

 

최근에 Internet Explorer와 같은 Multiple Threaded 환경에서 ActiveX Control로써 VB 를 사용하는 경우는 확실히 줄었지만, 과거의 Control을 유지 보수하는 차원에서 존재하는 것이라면, VB Runtime에서의 Crash는 당황될 수 있다. 가장 많이 보고 되는 것이 1) vb6ko.dll 이라는 모듈이 System32 Directory에 존재하지 않아서 Crash가 발생하는 경우와 2)TLS Operation에서의 VB runtime에서의 Crash이다. (설마 아직도 IE/VB Control을 Single Threading으로 사용하여 Crash되는 경우가 있을 거라고는 ... 생각치 않는다.) TLS Operation에서의 VB runtime Crash의 경우는 쉽게 Vista OS shipping VB Runtime XP Box copy하여 배포하는 경우도 있고, KB930828에서 제공하는 VB runtime으로 Update 하는 방법이 존재한다. 이 경우는 Microsoft 기술지원부를 Contact해야 하는 번거로움이 존재한다.

 

by 강세윤 | 2009/06/15 17:16 | Windows debugging | 트랙백 | 덧글(0)
< 이전페이지 다음페이지 >