Critical Section 사용에서의 hang issue에서도 언급했지만, Process hang 이슈 중에 Low CPU hang의 거의 많은 부분이 Critical Section Lock에 의한 경우가 차지한다. 그 중에서도 Internet Explorer등의 Process에서 자주 발생하는 Critical Section Lock에는 Loader Lock Issue가 있다. Loader Lock은 Process가 수행되기 위해 Image(Exe 또는 DLL)를 Load할 때, Critical Section을 이용한 리소스 Lock 처리가 존재하는 데, 임의의 문제되는 상황에서 Loader Lock에 의한 Hang 현상이 발생할 수도 있다. 이에 대하여 최근에 경험한 case를 소개하고자 한다.

0:000> kb

ChildEBP RetAddr  Args to Child             

0012dba4 7c93df3c 7c94b22b 0000006c 00000000 ntdll!KiFastSystemCallRet

0012dba8 7c94b22b 0000006c 00000000 00000000 ntdll!NtWaitForSingleObject+0xc

0012dc30 7c931046 019ab178 7c944a33 7c9ab178 ntdll!RtlpWaitForCriticalSection+0x132

0012dc38 7c944a33 7c9ab178 00000000 0012dd70 ntdll!RtlEnterCriticalSection+0x46

0012dc74 7c9468d0 00000000 00000000 0012dcb8 ntdll!LdrLockLoaderLock+0x146

0012dce8 7c946698 00000001 00000000 00000000 ntdll!LdrGetDllHandleEx+0x8b

0012dd04 76d96a12 00000000 00000000 0012dd5c ntdll!LdrGetDllHandle+0x18

0012ded4 77e79452 0012e388 00000001 0012deec apphelp!ApphelpCheckShellObject+0x193

0012def4 7d5d1695 0012e388 00000000 00000401 shlwapi!SHCoCreateInstanceAC+0x1d

0012e2d8 7d5d2a48 0012e388 00000000 00000401 shell32!_SHCoCreateInstance+0x127

0012e318 7d5d2a07 00000000 0012e388 00000000 shell32!SHExtCoCreateInstance2+0x41

0012e338 7d5d2102 00000000 0012e388 00000000 shell32!SHExtCoCreateInstance+0x1e

0012e39c 7d5cb7bc 04c52c90 00000000 4310db7c shell32!CRegFolder::_CreateAndInit+0x106

0012e3c4 7d5cb3af 04c52c90 00000000 4310db7c shell32!CRegFolder::_BindToItem+0x55

0012e3e8 7d5cb822 00148340 04c52c90 00000000 shell32!CRegFolder::BindToObject+0x45

0012e40c 7d5cc207 00148340 04c52c90 00000000 shell32!SHBindToObjectEx+0x3f

0012e430 7d5cc24c 00000000 04ae1d88 4310db7c shell32!SHBindToFolderIDListParent+0x26

0012e44c 4319d07b 04ae1d88 4310db7c 0012e474 shell32!SHBindToIDListParent+0x18

0012e46c 4319d7bd 00000000 0012e49c 0012e4a0 ieframe!GetPidlIconIndex+0x1d

0012e4b4 4319d779 04ae1d88 0012e4dc 4319d744 ieframe!CAddressList::_UpdateIcon+0x3b

상위의 Callstack은 대표적인 DLL Load시에 Loaderlock을 위한 CriticalSection에 Enter되는 상황인데, 보시다시피 Wait 하는 상태이다. 만일, 정상적이라면 Wait는 추후 풀려야 하지만 현 상태는 5분여 동안 Internet Explorer process가 wait되는 상황이었다. 그러므로, 이에 대해서는 CriticalSection에 의한 DeadLock이 존재하는 지 Check해봐야 한다.

0:000> !locks

CritSec ntdll!LdrpLoaderLock+0 at 7c9ab178

LockCount          8

RecursionCount     2

OwningThread       1e00

EntryCount         7b

ContentionCount    7b

*** Locked

CritSec +821cfe8 at 0821cfe8

LockCount          7667828

RecursionCount     6619250

OwningThread       73

EntryCount         9

ContentionCount    9

*** Locked

CritSec <Unloaded_rrr50.dll>+608 at 0c600608

LockCount          1

RecursionCount     0

OwningThread       0

EntryCount         1

ContentionCount    1

*** Locked

CriticalSection Lock 여부를 살펴보면, 1e00 Thread가 ntdll!LdrpLoaderLock 을 잡고 있는 것을 확인할 수 있다. 그러므로, loaderlock의 owner Thread의 상태를 확인하는 과정이 필요하다.

0:000> ~~[1e00]s

eax=00000000 ebx=00000000 ecx=00000000 edx=006506ec esi=0c600608 edi=00000000

eip=7c93e4f4 esp=0c79f68c ebp=0c79f714 iopl=0         nv up ei pl zr na pe nc

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

ntdll!KiFastSystemCallRet:

7c93e4f4 c3              ret

0:024> kb

ChildEBP RetAddr  Args to Child             

0c79f688 7c93df3c 7c94b22b 000018e0 00000000 ntdll!KiFastSystemCallRet

0c79f68c 7c94b22b 000018e0 00000000 00000000 ntdll!NtWaitForSingleObject+0xc

0c79f714 7c931046 00600608 7c940805 0c600608 ntdll!RtlpWaitForCriticalSection+0x132

0c79f71c 7c940805 0c600608 0c602790 0c602310 ntdll!RtlEnterCriticalSection+0x46

0c79f7e4 200494f9 0c600000 00000000 0c602310 ntdll!RtlFreeHeap+0x2c2

WARNING: Stack unwind information not available. Following frames may be wrong.

0c79f82c 2004e9c6 0c602310 00000000 00000000 xxx14N!L_StartDithering+0x819

0c79f864 7c93118a 1fff0000 00000001 00000000 xxx14N!L_StartDithering+0x5ce6

0c79f884 7c94e024 2004a38a 1fff0000 00000000 ntdll!LdrpCallInitRoutine+0x14

0c79f97c 7c80ac87 13ec0000 0c79fda8 0c79fdf0 ntdll!LdrUnloadDll+0x41c

0c79f990 769c0155 13ec0000 0c79fe14 769c0169 kernel32!FreeLibrary+0x3f

0c79f99c 769c0169 0c79fdb4 76a967e0 00000000 ole32!CClassCache::CDllPathEntry::CFinishObject::Finish+0x2f

0c79f9b0 7699008f 76971ac0 00000000 00000000 ole32!CClassCache::CFinishComposite::Finish+0x1d

0c79fe14 7698fd7b 07e777d8 00000080 00000001 ole32!CClassCache::CleanUpDllsForApartment+0x1b5

0c79fe40 7698fca9 00000000 0c79fe8c 76a967e8 ole32!FinishShutdown+0xcd

0c79fe5c 7698f231 00000000 00000000 07e777d8 ole32!ApartmentUninitialize+0x7e

0c79fe74 7698ee98 0c79fe8c 00000000 00000001 ole32!wCoUninitialize+0x41

0c79fe90 769bc269 00000001 76970000 7698d1ba ole32!CoUninitialize+0x5b

0c79fe9c 7698d1ba 0c79fec4 7698d159 76970000 ole32!DoThreadSpecificCleanup+0x4f

0c79fea4 7698d159 76970000 00000003 00000000 ole32!ThreadNotification+0x37

0c79fec4 7698d101 76970000 00000003 00000000 ole32!DllMain+0x147

Loaderlock owner Thread 즉, 24번 Thread는 CoUninitialize Call에 의해서 DLL을 Unloaded 하는 Thread로 확인되었다. 문제는 임의의 DLL을 unload 하는 동안에 Deadlock을 유발했다고 생각할 수 있다. 일단, 8번 과 9번 Frame을 살펴보면, 각 첫 번째 parameter는 Unload할 DLL의 instance 가 된다.

0:024> kvn

 # ChildEBP RetAddr  Args to Child             

. . .

08 0c79f97c 7c80ac87 13ec0000 0c79fda8 0c79fdf0 ntdll!LdrUnloadDll+0x41c (FPO: [Non-Fpo])

09 0c79f990 769c0155 13ec0000 0c79fe14 769c0169 kernel32!FreeLibrary+0x3f (FPO: [1,0,0])

MZ으로 시작하는 것을 보면, DLL이 맞다.

0:024> dc 13ec0000

13ec0000  00905a4d 00000003 00000004 0000ffff  MZ..............

13ec0010  000000b8 00000000 00000040 00000000  ........@.......

13ec0020  00000000 00000000 00000000 00000000  ................

13ec0030  00000000 00000000 00000000 000000f0  ................

13ec0040  0eba1f0e cd09b400 4c01b821 685421cd  ........!..L.!Th

13ec0050  70207369 72676f72 63206d61 6f6e6e61  is program canno

13ec0060  65622074 6e757220 206e6920 20534f44  t be run in DOS

13ec0070  65646f6d 0a0d0d2e 00000024 00000000  mode....$.......

lm command로는 해당 module 정보가 보이지 않는 것이 특이하다.

. . .

13360000 135f3000   rrr30   (deferred)            

13c00000 13ce5000   teesmall   (deferred)            

148b0000 148c8000   MenuCtrl   (deferred)            

148d0000 148f1000   NcMenu     (deferred)            

1fff0000 2006a000   xxx14N C (export symbols)       xxx14N.dll

. . .

이와 같은 경우,  debugger command로 .imgscan 을 이용할 수 있다.

.imgscan <options> - scan memory for PE images

MZ at 13ec0000, prot 00000002, type 01000000 - size 425000

  Name: xxxx50.ocx

그러므로, 문제는 xxxx50.ocx 를 unload 할 때 Deadlock이 발생한 것이다. 일반적으로는 Internet Explorer와 같은 process가 이와 같은 DeadLock현상이 발생하고 이 원인이 3rd party 모듈로 인한 경우라면, 해당 Module을 제거한 후에도 DeadLock 현상이 동일하게 발생하는 지 Check 해 보는 것이 일반적인데, 이와 같이 Deadlock을 유발하는 Control 중에 대부분이 IE를 사용하는 User가 알지 못하는 DLL 또는 OCX일 가능성이 높기 때문에 User에게 필요한 Control이 아니라면 제거해서 Deadlock을 avoid 하도록 하는 것이 해결책이 될 수 있다.

그렇다면, 상위의 case는 왜 deadlock이 발생했을 까? 상위의 case는 crash를 의심할 수 있다.

callstack을 좀 더 확인하면, xxxx50.ocx 가 ntdll!LdrUnloadDll 함수에 의해 unload되는 과정에 xxx14N.dll 이라는 Module의 임의의 Function이 Call되고 있는 것을 확인할 수 있다. 그 이후에 CriticalSection이 Enter되는 과정이 보이는 데, 하나 주의해서 볼 것은 RtlFreeHeap 이라는 heap Function이다.

0:024> kvn

 # ChildEBP RetAddr  Args to Child             

00 0c79f688 7c93df3c 7c94b22b 000018e0 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

01 0c79f68c 7c94b22b 000018e0 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])

02 0c79f714 7c931046 00600608 7c940805 0c600608 ntdll!RtlpWaitForCriticalSection+0x132 (FPO: [1,26,4])

03 0c79f71c 7c940805 0c600608 0c602790 0c602310 ntdll!RtlEnterCriticalSection+0x46 (FPO: [1,0,0])

04 0c79f7e4 200494f9 0c600000 00000000 0c602310 ntdll!RtlFreeHeap+0x2c2 (FPO: [Non-Fpo])

WARNING: Stack unwind information not available. Following frames may be wrong.

05 0c79f82c 2004e9c6 0c602310 00000000 00000000 ltkrn14N!L_StartDithering+0x819

06 0c79f864 7c93118a 1fff0000 00000001 00000000 ltkrn14N!L_StartDithering+0x5ce6

07 0c79f884 7c94e024 2004a38a 1fff0000 00000000 ntdll!LdrpCallInitRoutine+0x14

08 0c79f97c 7c80ac87 13ec0000 0c79fda8 0c79fdf0 ntdll!LdrUnloadDll+0x41c (FPO: [Non-Fpo])

해당 heap Function은 0c600000 이라는 heap 영역을 Clear 하도록 시도하며, 그 이후에 CriticalSection Lock이 걸리게 되는 데, 해당 Heap영역은 이미 unloaded된 rrr50.dll의 영역임을 확인할 수 있다.

0:024> !address 0c600000

    0c600000 : 0c600000 - 00008000

                    Type     00020000 MEM_PRIVATE

                    Protect  00000004 PAGE_READWRITE

                    State    00001000 MEM_COMMIT

                    Usage    RegionUsageHeap

                    Handle   0c600000

0:024> lm

start    end        module name

00400000 0049b000   iexplore   (deferred)            

. . .

. . .

Unloaded modules:

. . .

0c600000 0c60c000   rrr50.dll

다시 !locks 정보를 보면, 아래와 같은 정보가 존재했던 것을 기억할 수 있다.

CritSec <Unloaded_rrr50.dll>+608 at 0c600608

LockCount          1

RecursionCount     0

OwningThread       0

EntryCount         1

ContentionCount    1

*** Locked

추측컨데, rrr50.dll은 CriticalSection lock을 풀지 못하고 Unloaded가 된 것일 지도 모른다. 이는 Heap corruption이나 crash가 원인일 수 있다. 앞서서 말했지만 만일, 해당 DLL이 User가 모르는 3rd party control이라면, 제거하여 문제를 피해야겠고 그렇지 않다면, debugger를 attach하여 1st chance crash 또는 pageheap enable하여 Crash를 다시 한번 debugging하거나 해당 모듈의 unloaded되는 procedure에 문제가 없는 지 Check 하는 것이 Deadlock 을 피할 수 있는 방법을 찾는 데 도움이 될 수 있다.

No-Touch Deployment Application, 즉, 흔히 Smart Client Application이라고 부르는 이런 종류의 Application은 Internet Explorer를 통해서 수행이 된다. 보통 IE의 Url 입력 창에 해당 exe의 Url Path와 함께 입력하면, IE를 통해서 Download가 되고 IEExec.exe가 실행되면서 해당 Application이 hosting된다. 또한, 참조되는 DLL들(Satellite assemblies) 역시 Url을 통해서 참조되고 Load(assembly loader에 의해, assembly.load or loadfrom) 된다. 그러므로, 이러한 배경하에 가장 흔하게 발생하는 문제는 해당 assemblies 들이 load되지 않거나 수행되지 않는 현상에 의한 FileNotFoundException 이거나 혹은 "~ 클래스를 로드 할 수 없습니다." 와 같은 에러 메시지일 것이다. 물론, Assembly가 Load 될 때 Crash가 발생할 수도 있다. 그러한 경우는 IEExec.exe에 debugger를 attach 하여 assembly가 Crash될 때의 Exception을 분석하는 작업이 필요할 것이다. 이는 일반적인 Crash debugging작업의 수순을 따른다.

 How to debug managed-client applications that are started by using a URL in Visual Studio .NET or in Visual Studio 2005

가장 큰 고민은 FileNotFoundException과 같은 File이 존재하지 않는 다는 오류일 경우이다. 이로 인한 "~클래스를 로드 할 수 없습니다."가 생각보다 T-shooting하기가 까다롭다. 이 경우는 대부분 Fusion Log를 수집하는 과정을 통해 해당 Assembly가 정상적으로 download가 되었는지 확인하는 것이 중요하다.

 IanWho's bLog : Fuslogvw.exe and diagnosing .NET assembly binding issues

최근에 경험했던 Case 는 "~클래스를 로드 할 수 없습니다" 라는 오류였기 때문에 해당 machine에 해당 클래스를 포함한 Assembly가 download 되었는지 확인을 위해서 Fusion Log를 확인하였었다.

The operation was successful.

Bind result: hr = 0x0. 작업을 완료했습니다.

...

=== Pre-bind state information ===

LOG: Where-ref bind. Location = http://10.10.10.34/MyApps/MyUI.dll

LOG: Appbase = C:\Program Files\MyApps\Client-side\

LOG: Initial PrivatePath = NULL

LOG: Dynamic Base = NULL

LOG: Cache Base = NULL

LOG: AppName = NULL

Calling assembly : (Unknown).

===

LOG: Processing DEVPATH.

LOG: Private path hint found in configuration file: bin;3rdControls;WebServices;Controls;Common;Resources.

LOG: Policy not being applied to reference at this time (private, custom, partial, or location-based assembly bind).

LOG: Attempting download of new URL http://10.10.10.34/MyApps/MyUI.dll.

LOG: Assembly download was successful. Attempting setup of file: C:\Documents and Settings\Administrator\Local Settings\Temporary Internet Files\Content.IE5\PK4MR3V2\MyUI[1].dll

LOG: Entering download cache setup phase.

보면, 정상적으로 Download 되는 것은 확인할 수가 있다. Url이 잘못되었거나 Download에 문제가 있다면, 해당 Log에 표시가 될 것이다. 그런데 그 다음의 Fusion Log가 이상하다.

The operation failed.

Bind result: hr = 0x80070002. 지정된 파일을 찾을 수 없습니다.

...

--- A detailed error log follows.

=== Pre-bind state information ===

LOG: DisplayName =MyUI, Version=1.0.0.0, Culture=neutral, PublicKeyToken=7b9221e697c2c163

 (Fully-specified)

LOG: Appbase = C:\Program Files\MyApps\Client-side\

LOG: Initial PrivatePath = NULL

LOG: Dynamic Base = NULL

LOG: Cache Base = NULL    <---- 상위 로그에서는 Cache에 정상적으로 download되었다.

LOG: AppName = NULL

Calling assembly : (Unknown).

===

...

LOG: All probing URLs attempted and failed.

이와 같은 경우는 다소 이상하다. Download 가 정상적으로 되었는데, 해당 File을 찾을 수 없다는 오류이고, 해당 Cache directory를 확인하면 해당 DLL이 존재하는 것을 확인할 수 있었다. 하여, 이는 assembly loader에서 exception이 발생한 것은 아닌지 Exception을 확인해 볼 필요가 있었다. 하여 확인한 결과 아래와 같은 exception을 확인 할 수 있었다.

Exception 011d56b4 in MT 79bcbe74: System.Security.SecurityException

_message: System.Security.Permissions.SecurityPermission, mscorlib, Version=1.0.5000.0, Culture=neutral, PublicKeyToken=b77a5c561934e089 형식의 사용 권한을 요청하지 못했습니다.

상위의 "형식의 사용 권한을 요청하지 못했습니다" 라는 SecurityException 오류나 아래와 같은 PolicyException이 발생한다면, CAS(Code Access Security) Policy를 의심하는 것이 필요하다.

Message : Execution permission cannot be acquired.

   at System.Reflection.Assembly.nLoad(AssemblyName fileName, String codeBase, Boolean isStringized, Evidence assemblySecurity, Boolean throwOnFileNotFound, Assembly locationHint, StackCrawlMark& stackMark)

경험했던 Issue는 해당 Url에 대한 FullTrust 권한을 해당 machine에 Codegroup으로 추가한 이후에 문제가 해결된 case 이다. caspol.exe command program을 통해서(l option?) codegroup list를 확인할 수 있으므로, 이와 같은 문제 발생시 필요한 권한이 정상적으로 설정되었는지 Check하는 것도 도움이 될 것이다.

Managed Debugging은 Native Debugging과는 다르다. 다음의 Callstack을 보자

0:010> kn

 # ChildEBP RetAddr 

00 042ad8ec 79f071ac kernel32!RaiseException+0x53

01 042ad94c 79f0a629 mscorwks!RaiseTheExceptionInternalOnly+0x2a8

02 042ada10 7963661a mscorwks!JIT_Throw+0xfc

03 07d40b60 79381dbe mscorlib_ni!System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)+0x2b466e

04 07d40b60 79381d16 mscorlib_ni!System.Security.Permissions.FileIOPermission.AddPathList(System.Security.Permissions.FileIOPermissionAccess, System.Security.AccessControl.AccessControlActions, System.String[], Boolean, Boolean, Boolean)+0x6a

05 07d3b3c0 0f2481d2 mscorlib_ni!System.Security.Permissions.FileIOPermission..ctor(System.Security.Permissions.FileIOPermissionAccess, System.String)+0x420:010> .frame 3

03 07d40b60 79381dbe mscorlib_ni!System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)+0x2b466e

...

0:010> dv /V

Integrated managed debugging does not support enumeration of local variables.

See http://dbg/managed.htm for more details.

Unable to enumerate locals, HRESULT 0x80004001

보다시피 Exception이 발생한 Callstack이다. 무심결에 Frame 3에 locals, parameters를 확인하게 위해서 dv command를 실행하거나 kv command를 날려도 HRESULT 0x80004001만 보게 된다. 이유는 해당 callstack은 Managed Callstack 이기 때문이며, 이 경우는 SOS extension에서 제공하는 clrstack -a 를 통해서 보통 Parameters나 Locals를 얻을 수 있다고 한다. 그렇게 해서 살펴보면, 아래와 같다.

0:010> !clrstack -a

OS Thread Id: 0x1aa4 (10)

ESP       EIP    

042ad974 7c812aeb [HelperMethodFrame: 042ad974]

042ada18 7963661a System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)

    PARAMETERS:

        str = <no data>

        needFullPath = <no data>

    LOCALS:

        <no data>

        <no data>

        <no data>

        <no data>

        <no data>

042ada34 79381dbe System.Security.Permissions.FileIOPermission.AddPathList(System.Security.Permissions.FileIOPermissionAccess, System.Security.AccessControl.AccessControlActions, System.String[], Boolean, Boolean, Boolean)

    PARAMETERS:

        this = 0x07d40b3c

        access = 0x00000001

        control = 0x00000000

        pathListOrig = <no data>

        checkForDuplicates = 0x00000000

        needFullPath = <no data>

        copyPathList = <no data>

    LOCALS:

        <no data>

        <no data>

. . .

살펴보면, 어떤 Parameters나 Locals는 데이터가 보이는 데, 어떤 것들은 <no data> 라고 되어 있다. NULL 도 아니고 <no data> 라는 것이 좀 이상하다. 예를 들어, CreateListFromExpressions 함수의 2개의 parameters가 둘 다 <no data> 이다. 사실 해당 parameters값을 정확히 알지 못하고 Debugging 한다는 것은 무리일 듯 하여 이들을 살펴 봐야 하는데 과연, 이것은 무슨 의미일까? 이것은 아마도 GC에 의해서 Data가 소멸 되었거나 관련된 register의 값이 assembly 연산 중에 overwrite 가 되었기 때문이 아닐까 한다. 예를 들어, 해당 call시점의 GCInfo를 확인하면 다음과 같다.

0:010> !u -gcinfo 7963661a

preJIT generated code

System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)

Begin 79381fac, size 238

79381fac 57              push    edi

79381fad 56              push    esi

79381fae 53              push    ebx

79381faf 55              push    ebp

79381fb0 83ec08          sub     esp,8

79381fb3 891424          mov     dword ptr [esp],edx

79381fb6 8be9            mov     ebp,ecx

000C        reg EBP becoming live

79381fb8 85ed            test    ebp,ebp

79381fba 0f8494452b00    je      mscorlib_ni!System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)+0x2b45a8 (79636554)

79381fc0 b968431079      mov     ecx,offset mscorlib_ni+0x44368 (79104368) (MT: System.Collections.ArrayList)

79381fc5 e8c636af00      call    mscorwks!JIT_Writeable_Thunks_Buf+0x160 (79e75690) (JitHelp: CORINFO_HELP_NEWSFAST)

001E        reg EAX becoming live

79381fca 8bf8            mov     edi,eax

0020        reg EDI becoming live

79381fcc ba34020000      mov     edx,234h

79381fd1 b901000000      mov     ecx,1

79381fd6 e8ed36af00      call    mscorwks!JIT_Writeable_Thunks_Buf+0x198 (79e756c8) (JitHelp: CORINFO_HELP_GETSHARED_GCSTATIC_BASE)

002F        reg EAX becoming dead

002F        reg EAX becoming live (iptr)

79381fdb 8b80c0010000    mov     eax,dword ptr [eax+1C0h]

0035        reg EAX becoming dead

0035        reg EAX becoming live

79381fe1 8d5704          lea     edx,[edi+4]

0038        reg EDX becoming live (iptr)

79381fe4 e84735af00      call    mscorwks!JIT_Writeable_Thunks_Buf (79e75530)

003D        reg EDX becoming dead

79381fe9 33db            xor     ebx,ebx

79381feb 837d0400        cmp     dword ptr [ebp+4],0

79381fef 0f8e18010000    jle     mscorlib_ni!System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)+0x161 (7938210d)

0049        reg EAX becoming dead

79381ff5 3b5d04          cmp     ebx,dword ptr [ebp+4]

79381ff8 0f831d462b00    jae     mscorlib_ni!System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)+0x2b466f (7963661b)

79381ffe 837c9d0c00      cmp     dword ptr [ebp+ebx*4+0Ch],0

79382003 0f8477452b00    je      mscorlib_ni!System.Security.Util.StringExpressionSet.CreateListFromExpressions(System.String[], Boolean)+0x2b45d4 (79636580)

79382009 8b749d0c        mov     esi,dword ptr [ebp+ebx*4+0Ch]

0061        reg ESI becoming live

7938200d ba66040000      mov     edx,466h

79382012 b901000000      mov     ecx,1

79382017 e8b436af00      call    mscorwks!JIT_Writeable_Thunks_Buf+0x1a0 (79e756d0) (JitHelp: CORINFO_HELP_GETSHARED_NONGCSTATIC_BASE)

7938201c 89442404        mov     dword ptr [esp+4],eax

79382020 0fb7909c0a0000  movzx   edx,word ptr [eax+0A9Ch]

79382027 0fb788980a0000  movzx   ecx,word ptr [eax+0A98h]

7938202e 51              push    ecx

0083        push non-ptr (1)

7938202f 8bce            mov     ecx,esi

0085        reg ECX becoming live

79382031 3909            cmp     dword ptr [ecx],ecx

79382033 e8f2c6b200      call    mscorwks!COMString::Replace (79eae72a)

008C        reg EAX becoming live

008C        reg ECX becoming dead

008C        reg ESI becoming dead

. . .

살펴보면, 중간 중간에 ECX/EDX becoming dead, live 등의 marking된 정보를 볼 수 있는 데, Assembly의 연산에 따라서 각 Register의 값들의 변화에 따라서 live도 되고 dead도 되는 상태 표시이다. ECX/EDX registers가 parameters로 전달받은 Data라고 본다면(Managed Calling Convention에 따라), 기존의 값이 overwrite가 되거나 dead됨에 따라서 clrstack –a command에서 <no data> 라고 표시하게끔 하는 것으로 보인다.

그렇다면, 실질적인 parameters를 얻을 순 없을 까? 이러한 경우는 !dso command를 통해 해당 Thread의 stack에 살아있는 managed objects 를 list up 하여 해당 Function의 logic과 함께 유추하거나 raw stack에서 parameters를 유추할 수 밖에 없다. !clrstack이나 !dumpstack –EE command는 해당 Call function(또는  Method)의 ESP나 ChildEBP 정보를 보여주기 때문에 해당 ESP 정보를 통해서 다음과 같이 raw stack을 확인할 수 있다.

0:010> dds 042ada18

042ada18  00000001

042ada1c  0a052010

042ada20  07d40b60

042ada24  07d40b60

042ada28  07d40b3c

042ada2c  00000001

042ada30  79381dbe mscorlib_ni!System.Security.Permissions.FileIOPermission.AddPathList(System.Security.Permissions.FileIOPermissionAccess, System.Security.AccessControl.AccessControlActions, System.String[], Boolean, Boolean, Boolean)+0x6a

042ada34  07d3b3c0  <- - - - str?

042ada38  00000001  <- - - - needFullPath?

042ada3c  07d40b60

042ada40  07d40b3c

<일단, 심증이 가는 놈들을 일일이 다 확인해 본다.>
 

0:010> !do 07d3b3c0

Name: System.String

MethodTable: 790fd8c4

EEClass: 790fd824

Size: 146(0x92) bytes

 (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

String: http://70.11.89.156/iexplore.exe.config

Fields:

      MT    Field   Offset                 Type VT     Attr    Value Name

79102290  4000096        4         System.Int32  1 instance       65 m_arrayLength

79102290  4000097        8         System.Int32  1 instance       39 m_stringLength

790ff328  4000098        c          System.Char  1 instance       68 m_firstChar

790fd8c4  4000099       10        System.String  0   shared   static Empty

    >> Domain:Value  057418f0:790d884c 0629a500:790d884c 062b2908:790d884c <<

7912dd40  400009a       14        System.Char[]  0   shared   static WhitespaceChars

    >> Domain:Value  057418f0:07be13e4 0629a500:07be7e18 062b2908:07c3f6e4 <<

0:010> !do 07d40b60   <- - - - locals??

Name: System.Object[]

MethodTable: 7912d8f8

EEClass: 7912de6c

Size: 20(0x14) bytes

Array: Rank 1, Number of elements 1, Type CLASS

Element Type: System.String

Fields:

None

0:010> !do 07d40b3c <- - - - locals??

Name: System.Security.Permissions.FileIOPermission

MethodTable: 79112b50

EEClass: 79112ae0

Size: 36(0x24) bytes

 (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

Fields:

      MT    Field   Offset                 Type VT     Attr    Value Name

79112c68  4001d04        4 ...ions.FileIOAccess  0 instance 00000000 m_read

79112c68  4001d05        8 ...ions.FileIOAccess  0 instance 00000000 m_write

79112c68  4001d06        c ...ions.FileIOAccess  0 instance 00000000 m_append

79112c68  4001d07       10 ...ions.FileIOAccess  0 instance 00000000 m_pathDiscovery

79112c68  4001d08       14 ...ions.FileIOAccess  0 instance 00000000 m_viewAcl

79112c68  4001d09       18 ...ions.FileIOAccess  0 instance 00000000 m_changeAcl

7910be50  4001d0a       1c       System.Boolean  1 instance        0 m_unrestricted

7912dd40  4001d0b      5bc        System.Char[]  0   shared   static m_illegalCharacters

    >> Domain:Value  057418f0:NotInit  0629a500:07c3eed8 062b2908:NotInit  <<

<아니면, !dso를 통해서 stack pointer address에 따른 살아있는 Object들을 확인 해본다.>
 

0:010> !dso

OS Thread Id: 0x1aa4 (10)

ESP/REG  Object   Name

042ad908 07d40bec System.ArgumentException

042ad954 07d40bec System.ArgumentException

042ad964 07d40b74 System.Collections.ArrayList

042ad968 07d40bec System.ArgumentException

042ad988 07d40b74 System.Collections.ArrayList

042ad998 07d40bec System.ArgumentException

042ad9a0 07d40bec System.ArgumentException

042ad9fc 07d40bec System.ArgumentException

042ada10 07d40b60 System.Object[]    (System.String[])

042ada20 07d40b60 System.Object[]    (System.String[])

042ada24 07d40b60 System.Object[]    (System.String[])

042ada28 07d40b3c System.Security.Permissions.FileIOPermission

042ada34 07d3b3c0 System.String    http://10.1.1.10/iexplore.exe.config

. . .

이와 같은 정보와 Managed Function의 Code를 review 하면서 해당 parameters를 추정 및 debugging을 전개해 나가면 된다.

Windows Service Application이 시작할 때, 오류로 인하여 구동되지 않고 실패하는 경우는 일반적으로 Process가 제대로 올라오지도 않은 상태에서 죽어버리기 때문에 Debugger를 Attach 할 시간적 여유가 없다는 것이 문제다. 하여, Application이 Debugger가 Attach 된 상태에서 launch 되어야 할 필요가 있다. Image File Execution options 를 이용하면 이것은 가능한데, Service Application의 경우는 LocalSystem 계정에 "Allow service to interact with desktop" 이 Check 되어 있어야 한다는 조건이 있다. 만일 그렇지 않다면, debugger의 UI를 확인할 수 없기 때문에 debugging을 할 수 없게 된다. 간혹, Windows 2003에서 이와 같은 조건을 충족시키지 못한 상태에서 debugging을 해야 하는 경우에는 다음과 같은 방법으로 Debugger를 Attach 하여 debugging을 하는 것이 가능하다.

먼저, Image File Execution options 를 이용하여 다음과 같이 Debugger를 설정한다. (이는 Image File Execution options blogging 참조)

   C:\Debuggers\cdb.exe -server npipe:pipe=foo

그리고, 나서 문제가 되는 service 를 start 하게 되면, cdb.exe(debugger)가 attach 되어 Service Application이 수행된다. 이와 같이 설정하면, 대략 서비스 Application이 create되는 데, 30sec 정도의 sleep이 존재하는데, 이 시점에 windbg.exe를 수행하여 named pipe를 통해 cdb.exe와 통신하여 debugging 을 할 수 있다. 이는 다음과 같이 수행한다.

   c:\debuggers\windbg.exe -remote npipe:server=<computerName>,pipe=foo

1: kd> !process 0 0

**** NT ACTIVE PROCESS DUMP ****

. . .

PROCESS 85b07d88  SessionId: 0  Cid: 03d0    Peb: 7ffd5000  ParentCid: 01a4

    DirBase: 3fbd6180  ObjectTable: e140a9c0  HandleCount: 137.

    Image: spoolsv.exe

PROCESS 85ae1458  SessionId: 0  Cid: 03e8    Peb: 7ffd4000  ParentCid: 01a4

    DirBase: 3fbd61a0  ObjectTable: e16397d0  HandleCount: 154.

    Image: msdtc.exe

PROCESS 85ac7d88  SessionId: 0  Cid: 0444    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd61c0  ObjectTable: e1aa3ac8  HandleCount:  71.

    Image: svchost.exe

PROCESS 85b04908  SessionId: 0  Cid: 0474    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd61e0  ObjectTable: e13d0ad0  HandleCount: 149797.

    Image: TestLauncher.exe

PROCESS 85af4d88  SessionId: 0  Cid: 0484    Peb: 7ffde000  ParentCid: 0474

    DirBase: 3fbd6200  ObjectTable: e1529820  HandleCount:  64.

    Image: Client.exe

PROCESS 85b022c0  SessionId: 0  Cid: 049c    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd6220  ObjectTable: e1937340  HandleCount: 360.

    Image: MainServer.exe

. . .

그러므로, PROCESS 85b04908, TestLauncher.exe 에서 Handle 정보를 확인할 필요가 있다.

1: kd> .PROCESS 85b04908 

Implicit process is now 85b04908

1: kd> !handle

processor number 1, process 85b04908

PROCESS 85b04908  SessionId: 0  Cid: 0474    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd61e0  ObjectTable: e13d0ad0  HandleCount: 149797.

    Image: TestLauncher.exe

Handle table at e1032000 with 149797 Entries in use

0004: Object: e10016f8  GrantedAccess: 00000003 Entry: e1b69008

Object: e10016f8  Type: (8658b390) KeyedEvent

    ObjectHeader: e10016e0 (old version)

        HandleCount: 36  PointerCount: 37

        Directory Object: e1002a88  Name: CritSecOutOfMemoryEvent

...

0054: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b690a8

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

. . .

00dc: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b691b8

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

00e0: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b691c0

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

00e4: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b691c8

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

. . .

1: kd> !process 85af4d88 7  

PROCESS 85af4d88  SessionId: 0  Cid: 0484    Peb: 7ffde000  ParentCid: 0474

    DirBase: 3fbd6200  ObjectTable: e1529820  HandleCount:  64.

    Image: client.exe

    VadRoot 85b1de18 Vads 72 Clone 0 Private 2380. Modified 0. Locked 2.

    DeviceMap e1000930

    Token                             e1b06558

    ElapsedTime                       1 Day 17:39:41.791

    UserTime                          00:00:00.031

    KernelTime                        00:00:00.015

    QuotaPoolUsage[PagedPool]         28620

    QuotaPoolUsage[NonPagedPool]      34632

    Working Set Sizes (now,min,max)  (2927, 50, 345) (11708KB, 200KB, 1380KB)

    PeakWorkingSetSize                2927

    VirtualSize                       32 Mb

    PeakVirtualSize                   32 Mb

    PageFaultCount                    2921

    MemoryPriority                    BACKGROUND

    BasePriority                      8

    CommitCharge                      2434

        THREAD 85b20908  Cid 0484.0488  Teb: 7ffdd000 Win32Thread: e15b0a38 WAIT: (Unknown) UserMode Non-Alertable

            85af3d08  Semaphore Limit 0xffff

            85b20980  NotificationTimer

        IRP List:

            865e2dd8: (0006,0190) Flags: 00000000  Mdl: 85b5c628

            85b18008: (0006,0190) Flags: 00000000  Mdl: 85b4aa98

        Not impersonating

        DeviceMap                 e1000930

        Owning Process            85af4d88       Image:         client.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      9586717        Ticks: 7 (0:00:00:00.109)

        Context Switch Count      81771                 LargeStack

        UserTime                  00:00:00.015

        KernelTime                00:00:00.015

        Win32 Start Address 0x00431523

        Start Address 0x7c8217f8

        Stack Init f6848000 Current f6847c60 Base f6848000 Limit f6844000 Call 0

        Priority 8 BasePriority 8 PriorityDecrement 0

        ChildEBP RetAddr  Args to Child             

        f6847c78 80833485 85b20908 85b209b0 00000001 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])

        f6847ca4 80829a82 00000000 f6847d14 00000000 nt!KiSwapThread+0x2e5 (FPO: [0,7,0])

        f6847cec 80938d0c 85af3d08 00000006 8088d701 nt!KeWaitForSingleObject+0x346 (FPO: [5,13,4])

        f6847d50 808897bc 0000006c 00000000 f6847d14 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

        f6847d50 7c9685ec 0000006c 00000000 f6847d14 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f6847d64)

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

        0012fcec 00383bb0 00000000 00000005 65534847 0x7c9685ec

        00000000 00000000 00000000 00000000 00000000 0x383bb0

Handle 정보를 확인한 결과, Type이 Process인 Handle이 과다하게 존재하는 것으로 봐서 해당 Issue는 상당히 많은 Process Leak(client.exe)으로 인한 handle Leak이 발생한 것을 알 수 있다. 쉽게 예상할 수 있는 원인은 TestLauncher.exe process가 CreateProcess* API 를 통하여 client process의 launch후에 정상적으로 handle 를 Close 하지 않아서 이와 같은 Handle Leak의 형태로 문제가 발생한 것으로 추정할 수 있다.