windbg 분석 사례 - 닷넷 프로파일러의 GC 콜백 부하
희한한 현상이 발생했습니다. 새로 개발한 닷넷 프로파일러가 설치되면 "Performance Monitor" MMC에서 "ASP.NET v4.0.30319" 범주의 "Requests Queued"에 큐잉 현상이 발생하는 것입니다.
현상이 발생하는 PC에서 Process Explorer를 통해 살펴보면 유독 다음과 같은 식의 콜 스택이 자주 보이는 것을 확인할 수 있었습니다.
ntdll.dll!ZwWaitForSingleObject+0xa
KERNELBASE.dll!WaitForSingleObjectEx+0x98
clr.dll!CoUninitializeEE+0x27eef
clr.dll!CoUninitializeEE+0x27ea3
clr.dll!CoUninitializeEE+0x27e64
clr.dll!GetMetaDataInternalInterface+0x327b9
clr.dll!ClrCreateManagedInstance+0x2e13
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
clr.dll!ClrCreateManagedInstance+0x2e13
KERNEL32.DLL!BaseThreadInitThunk+0x22
ntdll.dll!RtlUserThreadStart+0x34
닷넷 프로파일러를 빼면 "ClrCreateManagedInstance" 메서드의 호출 발생이 현저하게 줄어듭니다. ClrCreateManagedInstance는 현재 deprecated 상태로 비-관리 코드에서 관리 코드를 호출할 때 사용하는 API입니다.
ClrCreateManagedInstance Function
; https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/hosting/clrcreatemanagedinstance-function
어쨌든 여기까지의 정보로는 뭔가 부족하군요. ^^
좀 더 자세한 정보가 필요하면 역시나 덤프뿐이 없습니다. 큐잉 현상이 나타나는 순간에 풀 덤프를 뜬 후 ClrCreateManagedInstance가 발생하는 스레드의 (sos를 이용한) 콜 스택을 확인했습니다.
0:012> !clrstack
OS Thread Id: 0x18bc (12)
Unable to walk the managed stack. 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
오호~~~ 해당 스레드가 ASP.NET 요청을 처리하는 스레드가 아니었군요. 그렇다면 네이티브 콜스택을 확인해 볼까요?
0:012> k
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!SVR::gc_heap::walk_heap+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
(덤프 뜨는 순간이 하필 달라서였을 수도 있지만) Process Explorer에서의 콜스택과 다른 것이 흥미롭습니다. 하지만 결정적으로, 문제가 되던 그 스레드는 바로 GC 스레드였던 것입니다. 여기까지 생각하니 감이 오는 것이 있었습니다. 바로 .NET Profiler에서 원하는 콜백을 받기 위해 설정하는 옵션 중에 GC 관련한 것이 있었다는 점입니다.
COR_PRF_MONITOR
; https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/profiling/cor-prf-monitor-enumeration
COR_PRF_MONITOR 열거 값에서 GarbageCollectionStarted, GarbageCollectionFinished, FinalizeableObjectQueued 콜백이 필요해서 COR_PRF_MONITOR_GC를 걸었었는데요. 사실, COR_PRF_MONITOR_GC 열거 값을 설정하면 다음의 콜백들도 함께 발생합니다.
- MovedReferences
- MovedReferences2
- SurvivingReferences
- SurvivingReferences2
- ObjectReferences
- ObjectsAllocatedByClass
- RootReferences
- RootReferences2
- HandleCreated
- HandleDestroyed
재미있는 것은, 제가 저 메서드들의 콜백에 대해 E_NOTIMPL을 반환값으로 했기 때문에 한번 호출된 이후로는 더 이상 안 불릴 거라고 가정했다는 점입니다.
STDMETHOD(MovedReferences2)(ULONG cMovedObjectIDRanges, ObjectID oldObjectIDRangeStart[], ObjectID newObjectIDRangeStart[], SIZE_T cObjectIDRangeLength[])
{
UNREFERENCED_PARAMETER(cObjectIDRangeLength);
return E_NOTIMPL;
}
그런데... E_NOTIMPL 반환값에 상관없이 필요할 때마다 매번 불렸습니다. ^^; 이 점이 상황을 악화시켰는데요, 가령 MovedReferences2 같은 경우에는, GC 발생 시 살아남은 객체 중 이동이 있으면 매번 발생하는 것이기 때문에 이런 것들이 합쳐져 은근히 부하를 주었던 것입니다. (하지만... 그래도 이상하긴 합니다. 아무리 콜백이 불려지는 것이지만 단순히 return 코드만 있는 것 뿐인데!)
정리해 보면, (디버깅 목적으로 제외하고) 실제 운영될 서버에 COR_PRF_MONITOR_GC 옵션이 붙은 닷넷 프로파일러를 넣는 것은 사용자 응답 시간이 길어진다는 단점으로 인해 사용해서는 안됩니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]