성태의 닷넷 이야기
홈 주인
모아 놓은 자료
프로그래밍
질문/답변
사용자 관리
사용자
메뉴
아티클
외부 아티클
유용한 코드
온라인 기능
MathJax 입력기
최근 덧글
[정성태] How can I tell whether two programs...
[정성태] The case of the fail-fast crashes c...
[정성태] Creating Docker multi-arch images f...
[정성태] BinaryFormatter removed from .NET 9...
[정성태] Extending the Windows Shell Progres...
[우광현] 와..... 범위를 잡았으니 클라이언트가 해당 범위를 확인해본다...
[정성태] 딱히, 그것 이상으로 더 설명할 내용이 없습니다. 동적 포...
[정성태] If Windows 3.11 required a 32-bit p...
[정성태] What is a hard error, and what make...
[괴물신인] 질문작성자인데 이 글을 이제봤네요 ㄷㄷ 이 글처럼 타입별로 인...
글쓰기
제목
이름
암호
전자우편
HTML
홈페이지
유형
제니퍼 .NET
닷넷
COM 개체 관련
스크립트
VC++
VS.NET IDE
Windows
Team Foundation Server
디버깅 기술
오류 유형
개발 환경 구성
웹
기타
Linux
Java
DDK
Math
Phone
Graphics
사물인터넷
부모글 보이기/감추기
내용
<div style='display: inline'> <h1 style='font-family: Malgun Gothic, Consolas; font-size: 20pt; color: #006699; text-align: center; font-weight: bold'>windbg 분석 사례 - 닷넷 프로파일러의 GC 콜백 부하</h1> <p> 희한한 현상이 발생했습니다. 새로 개발한 닷넷 프로파일러가 설치되면 "Performance Monitor" MMC에서 "ASP.NET v4.0.30319" 범주의 "Requests Queued"에 큐잉 현상이 발생하는 것입니다.<br /> <br /> 현상이 발생하는 PC에서 <a target='tab' href='https://docs.microsoft.com/en-us/sysinternals/downloads/process-explorer'>Process Explorer</a>를 통해 살펴보면 유독 다음과 같은 식의 콜 스택이 자주 보이는 것을 확인할 수 있었습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > ntdll.dll!ZwWaitForSingleObject+0xa KERNELBASE.dll!WaitForSingleObjectEx+0x98 clr.dll!CoUninitializeEE+0x27eef clr.dll!CoUninitializeEE+0x27ea3 clr.dll!CoUninitializeEE+0x27e64 clr.dll!GetMetaDataInternalInterface+0x327b9 <span style='color: blue; font-weight: bold'>clr.dll!ClrCreateManagedInstance+0x2e13</span> KERNEL32.DLL!BaseThreadInitThunk+0x22 ntdll.dll!RtlUserThreadStart+0x34 clr.dll!TranslateSecurityAttributes+0xa780c clr.dll!ClrCreateManagedInstance+0x28a5e clr.dll!TranslateSecurityAttributes+0xa6cee clr.dll!TranslateSecurityAttributes+0x14e95b clr.dll!TranslateSecurityAttributes+0x192985 clr.dll!ClrCreateManagedInstance+0xa13b3 clr.dll!GetMetaDataInternalInterface+0x326f2 <span style='color: blue; font-weight: bold'>clr.dll!ClrCreateManagedInstance+0x2e13</span> KERNEL32.DLL!BaseThreadInitThunk+0x22 ntdll.dll!RtlUserThreadStart+0x34 </pre> <br /> 닷넷 프로파일러를 빼면 "ClrCreateManagedInstance" 메서드의 호출 발생이 현저하게 줄어듭니다. ClrCreateManagedInstance는 현재 deprecated 상태로 비-관리 코드에서 관리 코드를 호출할 때 사용하는 API입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > ClrCreateManagedInstance Function ; <a target='tab' href='https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/hosting/clrcreatemanagedinstance-function'>https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/hosting/clrcreatemanagedinstance-function</a> </pre> <br /> 어쨌든 여기까지의 정보로는 뭔가 부족하군요. ^^<br /> <br /> <hr style='width: 50%' /><br /> <br /> 좀 더 자세한 정보가 필요하면 역시나 덤프뿐이 없습니다. 큐잉 현상이 나타나는 순간에 풀 덤프를 뜬 후 ClrCreateManagedInstance가 발생하는 스레드의 (sos를 이용한) 콜 스택을 확인했습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:012> <span style='color: blue; font-weight: bold'>!clrstack</span> OS Thread Id: 0x18bc (12) <span style='color: blue; font-weight: bold'>Unable to walk the managed stack.</span> The current thread is likely not a managed thread. You can run !threads to get a list of managed threads in the process Failed to start stack walk: 80070057 </pre> <br /> 오호~~~ 해당 스레드가 ASP.NET 요청을 처리하는 스레드가 아니었군요. 그렇다면 네이티브 콜스택을 확인해 볼까요?<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:012> <span style='color: blue; font-weight: bold'>k</span> Child-SP RetAddr Call Site 00000043`a0d1f9d8 00007ff8`69219fb6 clr!CallbackShimElementPcData<&CMicrodomManifestWalker::Handler_assembly_description_pcdata> 00000043`a0d1f9e0 00007ff8`69282f8e clr!Object::GetGCSafeTypeHandleIfPossible+0x7a 00000043`a0d1fa20 00007ff8`6927a110 clr!SafeGetClassIDFromObject+0xe 00000043`a0d1fa50 00007ff8`692be145 clr!AllocByClassHelper+0x6d 00000043`a0d1faa0 00007ff8`68f7fb67 clr!<span style='color: blue; font-weight: bold'>SVR::gc_heap::walk_heap</span>+0xb5 00000043`a0d1faf0 00007ff8`68e45882 clr!SVR::gc_heap::garbage_collect+0x4e5 00000043`a0d1fb80 00007ff8`68ee15c7 clr!SVR::gc_heap::gc_thread_function+0xdb 00000043`a0d1fbb0 00007ff8`70e113d2 clr!SVR::gc_heap::gc_thread_stub+0x94 00000043`a0d1fcf0 00007ff8`737a5454 kernel32!BaseThreadInitThunk+0x22 00000043`a0d1fd20 00000000`00000000 ntdll!RtlUserThreadStart+0x34 </pre> <br /> (덤프 뜨는 순간이 하필 달라서였을 수도 있지만) Process Explorer에서의 콜스택과 다른 것이 흥미롭습니다. 하지만 결정적으로, 문제가 되던 그 스레드는 바로 GC 스레드였던 것입니다. 여기까지 생각하니 감이 오는 것이 있었습니다. 바로 .NET Profiler에서 원하는 콜백을 받기 위해 설정하는 옵션 중에 GC 관련한 것이 있었다는 점입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > COR_PRF_MONITOR ; <a target='tab' href='https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/profiling/cor-prf-monitor-enumeration '>https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/profiling/cor-prf-monitor-enumeration</a> </pre> <br /> COR_PRF_MONITOR 열거 값에서 GarbageCollectionStarted, GarbageCollectionFinished, FinalizeableObjectQueued 콜백이 필요해서 COR_PRF_MONITOR_GC를 걸었었는데요. 사실, COR_PRF_MONITOR_GC 열거 값을 설정하면 다음의 콜백들도 함께 발생합니다.<br /> <br /> <ul> <li>MovedReferences</li> <li>MovedReferences2</li> <li>SurvivingReferences</li> <li>SurvivingReferences2</li> <li>ObjectReferences</li> <li>ObjectsAllocatedByClass</li> <li>RootReferences</li> <li>RootReferences2</li> <li>HandleCreated</li> <li>HandleDestroyed</li> </ul> <br /> 재미있는 것은, 제가 저 메서드들의 콜백에 대해 E_NOTIMPL을 반환값으로 했기 때문에 한번 호출된 이후로는 더 이상 안 불릴 거라고 가정했다는 점입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > STDMETHOD(MovedReferences2)(ULONG cMovedObjectIDRanges, ObjectID oldObjectIDRangeStart[], ObjectID newObjectIDRangeStart[], SIZE_T cObjectIDRangeLength[]) { UNREFERENCED_PARAMETER(cObjectIDRangeLength); <span style='color: blue; font-weight: bold'>return E_NOTIMPL;</span> } </pre> <br /> 그런데... E_NOTIMPL 반환값에 상관없이 필요할 때마다 매번 불렸습니다. ^^; 이 점이 상황을 악화시켰는데요, 가령 MovedReferences2 같은 경우에는, GC 발생 시 살아남은 객체 중 이동이 있으면 매번 발생하는 것이기 때문에 이런 것들이 합쳐져 은근히 부하를 주었던 것입니다. (하지만... 그래도 이상하긴 합니다. 아무리 콜백이 불려지는 것이지만 단순히 return 코드만 있는 것 뿐인데!)<br /> <br /> 정리해 보면, (디버깅 목적으로 제외하고) 실제 운영될 서버에 COR_PRF_MONITOR_GC 옵션이 붙은 닷넷 프로파일러를 넣는 것은 사용자 응답 시간이 길어진다는 단점으로 인해 사용해서는 안됩니다.<br /> </p><br /> <br /><hr /><span style='color: Maroon'>[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]</span> </div>
첨부파일
스팸 방지용 인증 번호
1717
(왼쪽의 숫자를 입력해야 합니다.)