제니퍼 닷넷 적용 사례 (7) - 노후된 스토리지 장비로 인한 웹 서비스 Hang (멈춤) 현상
이번 고객사의 사례는 좀 특이하게도, 제니퍼 닷넷으로 현상만 확인할 수 있었던 경우입니다. 내용은 간단합니다. 서비스 도중 알 수 없는 이유로 인해 더 이상 웹 요청에 대한 처리가 되지 않고 제니퍼 닷넷 제품은 그 시점에 처리율이 0으로 떨어지는 모습만을 보여주는 현상이었습니다.
이런 경우, 어쨌든 해당 고객사의 성능 문제가 나왔기 때문에 일종의 서비스 차원에서 ^^ 제가 분석해 주기도 합니다.
사실 달리 방법이 없습니다. 이럴 때는 풀 덤프를 떠서 분석해야 합니다.
풀 덤프 파일을 남기는 방법
; https://www.sysnet.pe.kr/2/0/991
만약 가능하다면 덤프 파일 분석은 문제가 발생한 서버에서 하는 것이 좋습니다. 하지만, 대부분의 경우 운영 서버에서 이런 작업을 하는 것이 허용되지 않으므로 개발자 PC로 복사해 오기 마련인데요, 그런 경우 잊지 마시고 다음의 글에 따라,
windbg의 mscordacwks DLL 로드 문제 - 세 번째 이야기
; https://www.sysnet.pe.kr/2/0/11231
덤프 대상이었던 닷넷 응용 프로그램의 유형에 맞는 sos.dll, mscordacwks.dll 파일을 함께 복사해 와야 합니다.
자, 그럼 이제 ^^ 기지개 한번 켜고 분석을 해볼까요?
어렵게 windbg를 이용해 분석하기 전, Debug Diagnostic를 이용해 가볍게 한번 훑어 보시는 것이 좋습니다.
DebugDiag 1.1을 사용한 덤프 분석
; https://www.sysnet.pe.kr/2/0/1026
Debug Diagnostic Tool v2 Update 2
; https://www.microsoft.com/en-us/download/details.aspx?id=49924
이것만으로도, 다음과 같이 321번 스레드를 대기하고 있는 다른 스레드들이 많다는 사실을 알 수 있게 되었습니다.
위의 화면에서, 문제가 되는 321번 스레드 링크를 통해 확인한 콜 스택은 다음과 같고,
Thread 321 - System ID 3500
DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, UInt32, IntPtr ByRef, Int32 ByRef)+93
[[InlinedCallFrame] (System.Web.Hosting.UnsafeIISMethods.MgdGetSiteNameFromId)] System.Web.Hosting.UnsafeIISMethods.MgdGetSiteNameFromId(IntPtr, UInt32, IntPtrByRef, Int32ByRef)
System.Web.Configuration.ProcessHostConfigUtils.GetSiteNameFromId(UInt32)+8f
System.Web.Configuration.ProcessHostMapPath.MapPathCaching(System.String, System.Web.VirtualPath)+313
System.Web.Hosting.HostingEnvironment.MapPathActual(System.Web.VirtualPath, Boolean)+1db
System.Web.CachedPathData.GetPhysicalPath(System.Web.VirtualPath)+4f
System.Web.CachedPathData.GetConfigPathData(System.String)+3e8
System.Web.CachedPathData.GetConfigPathData(System.String)+343
System.Web.CachedPathData.GetConfigPathData(System.String)+343
System.Web.HttpContext.GetFilePathData()+2e
System.Web.HttpContext.SetImpersonationEnabled()+84
System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)+219
System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)+5c6
System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)+22
DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)+51
[[ContextTransitionFrame]]
321번에 대기하고 있는 스레드 중 아무거나 골라서(여기서는 320) 확인해 보니 다음과 같이 나옵니다.
Thread 320 - System ID 13236
Entry point clr!Thread::intermediateThreadProc
Create time 2017-06-26 9:00:22
Time spent in user mode 0 Days 00:00:03.525
Time spent in kernel mode 0 Days 00:00:00.249
This thread is waiting to enter a .NET Lock
분명히 ".NET Lock"이 걸렸다고는 하는데 스레드 콜 스택이 나오지 않아 좀 이상한데요. DebugDiag가 왜 callstack을 못 보여주는지는 알 수 없지만, 어쨌든 이런 식의 부족한 부분은 windbg + sos.dll을 이용해 해결할 수 있으니 상관없습니다.
그리하여, windbg를 통해 320번 스레드로 문맥 이동을 한 다음,
0:000> ~320s
ntdll!ZwWaitForMultipleObjects+0xa:
00000000`7749c2ea c3 ret
콜 스택을 확인하면 DebugDiag와는 달리 이렇게 잘 보입니다.
0:320> !clrstack
OS Thread Id: 0x33b4 (320)
Child SP IP Call Site
000000001232de68 000000007749c2ea [GCFrame: 000000001232de68]
000000001232e060 000000007749c2ea [GCFrame: 000000001232e060]
000000001232e098 000000007749c2ea [HelperMethodFrame: 000000001232e098] System.Threading.Monitor.Enter(System.Object)
000000001232e190 000007fe990cbc86 *** ERROR: Module load completed but symbols could not be loaded for System.Web.dll
System.Web.Configuration.ProcessHostMapPath.MapPathCaching(System.String, System.Web.VirtualPath)
000000001232e250 000007fe995aa62b System.Web.Hosting.HostingEnvironment.MapPathActual(System.Web.VirtualPath, Boolean)
000000001232e2f0 000007fe995aa33f System.Web.CachedPathData.GetPhysicalPath(System.Web.VirtualPath)
000000001232e350 000007fe995a4a68 System.Web.CachedPathData.GetConfigPathData(System.String)
000000001232e550 000007fe995a49c3 System.Web.CachedPathData.GetConfigPathData(System.String)
000000001232e750 000007fe995a49c3 System.Web.CachedPathData.GetConfigPathData(System.String)
000000001232e950 000007fe995a49c3 System.Web.CachedPathData.GetConfigPathData(System.String)
000000001232eb50 000007fe998e917e System.Web.HttpContext.GetFilePathData()
000000001232eb90 000007fe99910d24 System.Web.HttpContext.SetImpersonationEnabled()
000000001232ebe0 000007fe9990b049 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
000000001232ec70 000007fe998f2586 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
000000001232ee30 000007fe998f1f52 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
000000001232ee80 000007fe998f1631 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)
000000001232f0c8 000007fef86d2403 [ContextTransitionFrame: 000000001232f0c8]
예상했던 대로 System.Web.Configuration.ProcessHostMapPath.MapPathCaching에서 호출한 Monitor.Enter에 걸려 있는 것을 볼 수 있습니다. lock을 잡고 있다고 분석이 되었던 321번 스레드도 MapPathCaching을 호출했기 때문에 그 스레드에서 열어두었던 Monitor.Enter가 아직 안 풀렸다는 이야기가 됩니다.
확인을 위해 .NET Reflector로 소스 코드를 들여다볼까요?
private string MapPathCaching(string siteID, VirtualPath path)
{
// ...[생략]...
if (!info.Evaluated)
{
MapPathCacheInfo info2 = info;
lock (info2)
{
// ...[생략]...
if (!info.Evaluated)
{
try
{
uint num;
string originalResult = null;
if (uint.TryParse(siteID, out num))
{
originalResult = ProcessHostConfigUtils.MapPathActual(ProcessHostConfigUtils.GetSiteNameFromId(num), path);
}
// ...[생략]...
}
catch (Exception exception)
{
// ...[생략]...
}
info.Evaluated = true;
}
}
}
// ...[생략]...
return this.MatchResult(path2, info.MapPathResult);
}
321번의 콜 스택에서 보여준 MapPathCaching 메서드의 내부에 lock (info2) 코드가 있고 그 안에서 ProcessHostConfigUtils.GetSiteNameFromId 호출이 보입니다. 다시 그 메서드로 가 보면,
internal static string GetSiteNameFromId(uint siteId)
{
// ...[생략]...
try
{
str = ((UnsafeIISMethods.MgdGetSiteNameFromId(IntPtr.Zero, siteId, out zero, out cchSiteName) == 0) && (zero != IntPtr.Zero)) ? StringUtil.StringFromWCharPtr(zero, cchSiteName) : string.Empty;
}
finally
{
if (zero != IntPtr.Zero)
{
Marshal.FreeBSTR(zero);
}
}
if (siteId == 1)
{
s_defaultSiteName = str;
}
return str;
}
UnsafeIISMethods.MgdGetSiteNameFromId 호출이 보이지만 이후로는 이 메서드가 webengine4.dll 내부로의 P/invoke 호출이기 때문에,
[DllImport("webengine4.dll")]
internal static extern int MgdGetSiteNameFromId(IntPtr pConfigSystem, [MarshalAs(UnmanagedType.U4)] uint siteId, out IntPtr bstrSiteName, out int cchSiteName);
더 이상 분석할 수 없습니다. 하지만 kv 명령어를 이용해 321번 스레드의 native callstack을 조사해 보면,
0:321> kv
# Child-SP RetAddr : Args to Child : Call Site
00 00000000`3cb1cbb8 000007fe`fd3b1203 : 00000000`3cb1cc78 00000000`00000022 00000000`00000000 00000003`0006f080 : ntdll!ZwDelayExecution+0xa
*** ERROR: Symbol file could not be found. Defaulted to export symbols for iisutil.dll -
01 00000000`3cb1cbc0 000007fe`fa60642a : 00000000`00000064 000007fe`00000000 00000003`00000000 00000000`00000000 : KERNELBASE!SleepEx+0xb3
02 00000000`3cb1cc60 000007fe`fa60127d : 00000000`00000000 000007fe`990b5cd9 ffffffff`3cb1ccc0 00000000`00000000 : iisutil!CLKRLinearHashTable::_FreeSegmentDirectory+0xda
*** ERROR: Symbol file could not be found. Defaulted to export symbols for nativerd.dll -
03 00000000`3cb1cc90 000007fe`fa5511a6 : 00000000`0057cfc8 00000000`0057cfc8 00000000`3cb1d240 00000000`0000003a : iisutil!CReaderWriterLock3::_LockSpin+0xbd
04 00000000`3cb1ccd0 000007fe`fa558125 : 00000000`00000000 000007fe`fa55123d 00000000`00000000 00000000`00000000 : nativerd+0x11a6
05 00000000`3cb1cd00 000007fe`fa557d32 : 00000000`00578d30 000007fe`fa5af0d8 00000000`0057cfa0 00000000`0057cfa0 : nativerd!DllCanUnloadNow+0x2805
06 00000000`3cb1cd40 000007fe`fa5aa2fe : 00000000`00000011 00000000`00160230 00000006`824975f0 00000000`00000000 : nativerd!DllCanUnloadNow+0x2412
07 00000000`3cb1d6e0 000007fe`fa5aa5ac : 50000384`00000000 00000000`10000000 00000000`000005be 00000000`00160000 : nativerd!GetDefaultNativeConfigurationSystem+0x5d2e
08 00000000`3cb1d8b0 000007fe`fa5aa842 : 00000000`00000000 00000000`00260300 00000000`00160230 00000000`00000000 : nativerd!GetDefaultNativeConfigurationSystem+0x5fdc
*** ERROR: Symbol file could not be found. Defaulted to export symbols for webengine4.dll -
09 00000000`3cb1db60 000007fe`f91e60ef : 00000000`3cb1de48 00000003`000b7c38 00000003`000ba430 00000003`000ba430 : nativerd!GetDefaultNativeConfigurationSystem+0x6272
0a 00000000`3cb1ddf0 000007fe`f91e616d : 00000000`00000003 00000000`3cb1dfb0 00000000`00000000 000007fe`f86548d9 : webengine4!SetMinRequestsExecutingToDetectDeadlock+0x2db
0b 00000000`3cb1de20 000007fe`990b7483 : 000007fe`990b7483 00000000`3cb1dfb0 00000000`3cb1dec0 000007fe`990b89c2 : webengine4!MgdGetSiteNameFromId+0x51
GetDefaultNativeConfigurationSystem 메서드 호출에서 걸렸다는 것을 알 수 있고 구체적인 원인은 알 수 없었지만 그 함수 이름 자체가 어찌 보면 도움일 수 있습니다.
그럼, 중간 정리를 해 볼까요?
321번 스레드는 lock을 소유한 MapPathCaching 메서드를 호출하고는 어찌 된 일인지 그 상태에서 hang이 걸렸고, 나머지 179개의 연 이은 요청 스레드들은 마찬가지로 MapPathCaching을 호출했다가 321번 스레드가 소유한 lock으로 인해 덩달아 hang 상태로 빠진 것입니다.
그런데, 아직 문제의 원인을 찾을 수가 없군요. 좀 더 들여다봐야겠습니다. ^^ (참고로, 이제부터는 IIS에 대한 약간의 감이 필요합니다.)
320번 스레드가 호출한 MapPathCaching의 호출 인자들의 값을 다음과 같이 알 수 있습니다.
0:320> !clrstack -p
OS Thread Id: 0x33b4 (320)
Child SP IP Call Site
000000001232de68 000000007749c2ea [GCFrame: 000000001232de68]
000000001232e060 000000007749c2ea [GCFrame: 000000001232e060]
000000001232e098 000000007749c2ea [HelperMethodFrame: 000000001232e098] System.Threading.Monitor.Enter(System.Object)
000000001232e190 000007fe990cbc86 System.Web.Configuration.ProcessHostMapPath.MapPathCaching(System.String, System.Web.VirtualPath)
PARAMETERS:
this (0x000000001232e250) = 0x00000003000ba2d0
siteID (0x000000001232e258) = 0x00000003000ba430
path (0x000000001232e260) = 0x0000000740148e48
...[생략]...
000000001232e950 000007fe995a49c3 System.Web.CachedPathData.GetConfigPathData(System.String)
PARAMETERS:
configPath (0x000000001232eb50) = 0x0000000740148a38
...[생략]...
이 중에서 siteID 문자열 값을 조사해 보니 "1"이 나옵니다.
0:320> !DumpObj /d 00000003000ba430
Name: System.String
MethodTable: 000007fe99074d58
EEClass: 000007fe9905f5d0
Size: 28(0x1c) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: 1
Fields:
MT Field Offset Type VT Attr Value Name
000007fe9903fb10 40000aa 8 System.Int32 1 instance 1 m_stringLength
000007fe9903d4d8 40000ab c System.Char 1 instance 33 m_firstChar
000007fe99074d58 40000ac 18 System.String 0 shared static Empty
>> Domain:Value 0000000004e880e0:NotInit 00000000306ae5c0:NotInit <<
이와 함께 path 값은 "/jstatic"이 나옵니다.
0:320> !DumpObj /d 0000000740148e48
Name: System.Web.VirtualPath
MethodTable: 000007fe9924f6e0
EEClass: 000007fe99258fe0
Size: 40(0x28) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\System.Web\v4.0_4.0.0.0__b03f5f7f11d50a3a\System.Web.dll
Fields:
MT Field Offset Type VT Attr Value Name
000007fe99074d58 4002a25 8 System.String 0 instance 0000000000000000 _appRelativeVirtualPath
000007fe99074d58 4002a26 10 System.String 0 instance 0000000740148e18 _virtualPath
000007fe9924f650 4002a27 18 ...SimpleBitVector32 1 instance 0000000740148e60 flags
000007fe9924f6e0 4002a28 3380 ...m.Web.VirtualPath 0 shared static RootVirtualPath
>> Domain:Value 0000000004e880e0:00000006000310d0 00000000306ae5c0:000000030010b420 <<
0:320> !DumpObj /d 0000000740148e18
Name: System.String
MethodTable: 000007fe99074d58
EEClass: 000007fe9905f5d0
Size: 42(0x2a) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: /jstatic
Fields:
MT Field Offset Type VT Attr Value Name
000007fe9903fb10 40000aa 8 System.Int32 1 instance 8 m_stringLength
000007fe9903d4d8 40000ab c System.Char 1 instance 2f m_firstChar
000007fe99074d58 40000ac 18 System.String 0 shared static Empty
>> Domain:Value 0000000004e880e0:NotInit 00000000306ae5c0:NotInit <<
결국, SiteID가 1인 웹 사이트 내의 가상 디렉터리 "/jstatic"으로 요청이 들어온 것입니다. 그런데 어떤 요청이었을지 궁금한데요, 이를 위해 320번의 콜 스택 중에 GetConfigPathData 메서드의 configPath 인자를 보면 답이 나옵니다.
0:320> !DumpObj /d 0000000740148a38
Name: System.String
MethodTable: 000007fe99074d58
EEClass: 000007fe9905f5d0
Size: 142(0x8e) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: machine/webroot/1/jstatic/service.js
Fields:
MT Field Offset Type VT Attr Value Name
000007fe9903fb10 40000aa 8 System.Int32 1 instance 58 m_stringLength
000007fe9903d4d8 40000ab c System.Char 1 instance 6d m_firstChar
000007fe99074d58 40000ac 18 System.String 0 shared static Empty
>> Domain:Value 0000000004e880e0:NotInit 00000000306ae5c0:NotInit <<
재미있는 것은 321번 스레드 역시 콜 스택에 있는 인자 값들의 상황이 320번과 마찬가지였다는 점입니다. 321번도 MapPathCaching에는 siteId=1, virtualPath = /jstatic이 지정되어 있었고, GetConfigPathData의 configPath는 machine/webroot/1/jstatic/overwrite.js였습니다.
이쯤에서, 대충 원인이 나옵니다. 정리해 보면!
321번 스레드로 웹 요청이 들어왔고 그 대상이 되는 파일이 존재하는 /jstatic이라는 가상 디렉터리는 사이트 ID가 1번인 웹 사이트에 속해 있는 것입니다. IIS는 1번 사이트의 정보를 얻기 위해 GetDefaultNativeConfigurationSystem 호출을 했지만 여기서 hang이 걸렸고 나머지 179개의 스레드들은 321번의 lock을 대기하느라 다시 hang이 걸려 해당 웹 서버의 서비스 자체가 멈춘 것처럼 보인 것입니다.
게다가 콜 스택을 보면 왜 제니퍼 닷넷 제품이 원인 파악을 할 수 없었는지 이유가 나옵니다. 제니퍼 닷넷은 고객사의 코드에 대한 모니터링을 하는 APM 제품으로 .aspx/.asmx/WCF 등으로의 요청에 대한 성능을 분석하는 역할을 합니다. 반면 321번 스레드의 상황은 IIS가 요청을 처리하기 위해 준비를 하는 단계에서 hang이 걸렸으므로 아직 제니퍼 닷넷 제품은 해당 요청에 대한 어떠한 프로파일도 할 수 없었던 것입니다. 따라서, 처리율만 0으로 떨어지는 결과를 보이는 현상만 보여줄 뿐 원인을 파악할 수는 없었던 것입니다.
어쨌든, 원인이 대충 나왔습니다. 해당 고객사를 담당하는 엔지니어에게 위의 상황을 설명했고, 분명히 "/jstatic" 가상 디렉터리 경로에 대한 처리가 늦어져서 발생한 것으로 아마도 "네트워크 드라이브"로 연결된 가상 디렉터리가 제대로 동작하지 않아서 그런 것 같다고 했습니다. 따라서 급한 대로 네트워크 드라이브로 /jstatic을 연결하지 말고 로컬 장비의 하드 디스크에 배포하면 해결될 것이라고 했습니다.
일단, 여기까지는 제가 담당이었고 위의 설명을 들은 담당 엔지니어는 다음 날 고객사를 방문했습니다. 며칠 전 이에 대한 후기를 들었는데, 고객에게 덤프 분석 결과를 설명하니 고객 측에서 실제로 가상 디렉터리가 연결된 곳은 네트워크 스토리지 장비였는데 이것이 매우 노후된 장비였다고 합니다. 아마도 지금 쯤은 장비 교체를 했거나 로컬 PC로 /jstatic 파일들을 배포하는 조치를 취했을 것이기 때문에 성능 장애를 더 이상 겪지 않고 있을 것입니다.
결국, 이번 사례는 제니퍼 닷넷 제품이 서비스 장애에 대한 원인을 찾진 못했지만, 제니퍼 닷넷을 쓰는 고객에 대한 부가 서비스(?)라고 할 수 있는 덤프 파일 분석으로 고객사의 장애 문제가 해결된 경우입니다. ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]