windbg 분석 사례 - 메모리 부족
테스트 중의 한 웹 애플리케이션이 정상 동작하지 않고 있음을 발견했습니다. 이벤트 로그를 보니 다음과 같이 희귀한 메모리 부족 현상으로 웹 애플리케이션 동작에 문제가 발생한 것인데요.
Name: Application
Source: System.ServiceModel 3.0.0.0
Date: 2014-12-19 오후 10:29:17
Event ID: 3
Task Category: WebHost
Level: Error
Keywords: Classic
User: SYSTEM
Computer: win2008r2.testad.com
Description:
WebHost failed to process a request.
Sender Information: System.ServiceModel.ServiceHostingEnvironment+HostingManager/7699499
Exception: System.ServiceModel.ServiceActivationException: The service '/WCFs/CHelloWorld.svc' cannot be activated due to an exception during compilation. The exception message is: Memory gates checking failed because the free memory (126545920 bytes) is less than 5% of total memory. As a result, the service will not be available for incoming requests. To resolve this, either reduce the load on the machine or adjust the value of minFreeMemoryPercentageToActivateService on the serviceHostingEnvironment config element.. ---> System.InsufficientMemoryException: Memory gates checking failed because the free memory (126545920 bytes) is less than 5% of total memory. As a result, the service will not be available for incoming requests. To resolve this, either reduce the load on the machine or adjust the value of minFreeMemoryPercentageToActivateService on the serviceHostingEnvironment config element.
at System.ServiceModel.Activation.ServiceMemoryGates.Check(Int32 minFreeMemoryPercentage)
at System.ServiceModel.ServiceHostingEnvironment.HostingManager.EnsureServiceAvailable(String normalizedVirtualPath)
--- End of inner exception stack trace ---
at System.ServiceModel.ServiceHostingEnvironment.HostingManager.EnsureServiceAvailable(String normalizedVirtualPath)
at System.ServiceModel.ServiceHostingEnvironment.EnsureServiceAvailableFast(String relativeVirtualPath)
Process Name: w3wp
Process ID: 68448
문제의 원인은 다른 닷넷 프로세스가 시스템의 전체 메모리를 가져간 것입니다. 그나마 다행인 점은, 가상 머신이어서 메모리 부족 현상이 빨리 발견되었습니다. 메모리 6GB, pagefile.sys 메모리 11GB 정도가 할당되었는데... 그 프로세스 하나만 16GB 가까운 용량을 쓰고 있었던 것입니다. 도저히 해당 머신에서 분석할 수 있는 상황이 아니어서 덤프를 떠서 제 컴퓨터로 가져와 분석을 해보았습니다. (여기서 한가지 재미있는 점! 작업 관리자를 통해 풀 덤프를 뜨면 그 주체는 (ID가 4번인) SYSTEM 프로세스가 됩니다. 또한 도중에 취소도 안됩니다.)
닷넷 프로세스였기 때문에, 당연히 코드 상의 잘못으로 메모리 leak이 발생했다고 여겼고, Managed 객체가 많이 생성된 것을 알아내면 문제를 해결할 수 있을 거라 생각했습니다. 하지만, !dumpheap의 결과는 의외였습니다.
0:021> !dumpheap -stat
total 0 objects
Statistics:
MT Count TotalSize Class Name
000007ff00b16a38 1 24 System.Collections.Generic.ObjectEqualityComparer`1[[System.Data.ProviderBase.DbConnectionPoolGroup, System.Data]]
...[생략]...
000007ff0019d478 63398 4177336 System.String
000007ff0086cf48 399576 22376256 System.Diagnostics.ProcessThread
000007ff0056fdf8 1134356 54449088 System.Diagnostics.ThreadInfo
000000000036b9f0 12011 83246488 Free
000007ff0019c308 74791 91600328 System.Object[]
000007ff0024c0c0 30736 170218072 System.Byte[]
Total 2317105 objects
Fragmented blocks larger than 0.5 MB:
Addr Size Followed by
000000000ef50938 0.6MB 000000000efe1f88 System.Net.IPEndPoint
000000000f585200 0.6MB 000000000f617348 System.Net.IPEndPoint
000000000f61bcb0 0.6MB 000000000f6b3a50 System.Net.Sockets.Socket
000000000f94d780 0.8MB 000000000fa0f338 System.Runtime.Remoting.Channels.SocketStream
보시는 바와 같이 System.Byte[] 용량이 170MB에 불과했고 나머지 용량을 합친다고 해도 도저히 16GB에 육박하는 메모리 사용은 설명이 안됩니다.
그런데, 위의 결과에서 약간 이상한 점이 눈에 띕니다. ProcessThread와 ThreadInfo 객체가 유달리 많다는 점인데, !threads 명령으로 문제가 확인됩니다.
0:000> !threads
ThreadCount: 14796
UnstartedThread: 0
BackgroundThread: 14791
PendingThread: 0
DeadThread: 4
Hosted Runtime: no
PreEmptive Lock
ID OSID ThreadOBJ State GC GC Alloc Context Domain Count APT Exception
0 1 8dc8 0000000000f9c910 a020 Enabled 0000000000000000:0000000000000000 0000000000340500 0 MTA
4 2 a1c4 0000000000fa1470 b220 Enabled 0000000000000000:0000000000000000 0000000000340500 0 MTA (Finalizer)
...[생략]...
14795 39c8 e934 00000004d9866e90 3009220 Enabled 0000000000000000:0000000000000000 0000000000340500 0 MTA (Threadpool Worker)
XXXX 39c1 00000004d974b620 1019820 Enabled 0000000000000000:0000000000000000 0000000000340500 0 Ukn (Threadpool Worker)
XXXX 39c9 00000004d98675a0 1019820 Enabled 0000000000000000:0000000000000000 0000000000340500 0 Ukn (Threadpool Worker)
XXXX 39ca 00000004d9867cb0 1019820 Enabled 0000000000000000:0000000000000000 0000000000340500 0 Ukn (Threadpool Worker)
XXXX 39cb 00000004d98683c0 1019820 Enabled 0000000000000000:0000000000000000 0000000000340500 0 Ukn (Threadpool Worker)
14797 39cc edfc 00000004d9868ad0 1009220 Enabled 0000000000000000:0000000000000000 0000000000340500 0 MTA (Threadpool Worker)
무려 14,000개가 넘는 스레드가 생성된 것입니다. 그렇다면 각각의 스레드 스택만으로 그렇게 메모리 소비가 되었다는 것인데, 이를 확인하려면 !address 명령을 사용해야 합니다.
0:000> !address -summary
Mapping file section regions...
...[생략]...
Mapping activation context regions...
--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free 12259 7fc`0a3e3000 ( 7.985 Tb) 99.81%
Stack 73981 3`9cf00000 ( 14.452 Gb) 91.24% 0.18%
<unknown> 318 0`3c0e7000 ( 960.902 Mb) 5.92% 0.01%
Heap 85 0`10b68000 ( 267.406 Mb) 1.65% 0.00%
TEB 14799 0`0739e000 ( 115.617 Mb) 0.71% 0.00%
Image 506 0`04b5c000 ( 75.359 Mb) 0.46% 0.00%
Other 10 0`001c3000 ( 1.762 Mb) 0.01% 0.00%
PEB 1 0`00001000 ( 4.000 kb) 0.00% 0.00%
...[생략]...
위에서 "Stack" 영역이란 "
Memory used for thread stacks."를 의미하는 것으로 말 그대로 스레드 스택으로 할당된 용량입니다. 1만 4천 개의 스레드가 스택 용량만으로 14GB가 넘는 용량을 잡아먹고 있는 것입니다. 그럼, !threadpool 명령을 내려 볼까요?
0:14770> !threadpool
CPU utilization: 81%
Worker Thread: Total: 13779 Running: 13778 Idle: 1 MaxLimit: 32767 MinLimit: 2
Work Request in Queue: 0
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 997 Free: 1 MaxFree: 4 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 2
오호~~~ ThreadPool의 Max 값은 32767인데, 그 중에 현재 13779까지 스레드가 생성되었고 그중에서 13778개가 사용 중입니다. 그런데, 특이하게도 CPU 사용률이 81%군요. !runaway 명령어를 내려봐야겠습니다.
0:14770> !runaway
User Mode Time
Thread Time
21:1120 1 days 18:23:27.203
17:96b0 0 days 2:26:34.046
4:a1c4 0 days 0:01:40.484
10:5aa8 0 days 0:01:30.031
..[생략]...
1:ac28 0 days 0:00:00.000
다행히 1개의 스레드가 독점하고 있군요. 해당 스레드로 문맥 전환을 하고 스레드 콜 스택을 확인해 봅니다.
0:14770> ~21s
ntdll!NtWaitForSingleObject+0xa:
00000000`76fb05fa c3 ret
0:021> !clrstack
OS Thread Id: 0x1120 (21)
Child SP IP Call Site
00000000204fe0f8 0000000076fb05fa [RedirectedThreadFrame: 00000000204fe0f8]
00000000204fe190 000007ff007e8882 MyApp.util.IntBoundSet.put(Int32) [d:\...\IntBoundSet.cs @ 74]
...[생략]...
00000000204fe840 000007ff006bbf93 System.Runtime.Remoting.Channels.SocketHandler.ProcessRequestNow()
00000000204fe880 000007ff006bb66e System.Runtime.Remoting.Channels.SocketHandler.BeginReadMessageCallback(System.IAsyncResult)
00000000204fe8e0 000007ff006b7226 System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
00000000204feb80 000007fef8d9c9e4 [GCFrame: 00000000204feb80]
00000000204fed50 000007fef8d9c9e4 [DebuggerU2MCatchHandlerFrame: 00000000204fed50]
이후의 문제 해결은 예전에 썼던 글로 이어집니다.
windbg 분석 사례 - cpu 100% 현상
; https://www.sysnet.pe.kr/2/0/1831
위에서 제공한 IntBoundSet.put 메서드에는 lock이 있습니다. 그 내부에서 무한 루프 현상이 발생했기 때문에 lock 점유가 풀리지 않았고 이후 들어오는 모든 요청들은 스레드 풀로부터 지속적으로 새로 생성된 스레드에 할당된 것입니다.
정리해 보면, 메모리 leak 문제가 아니라 lock 동시성 문제로 인한 스레드 증가로 인해 메모리 부족현상이 발생한 것입니다.
한가지 더 재미있는 점이 있는데, 동일한 문제가 Web Application에서는 표면상으로 나타나지 않았다는 것입니다. 왜냐하면 IIS 는 우수한(!) Recycle 정책을 제공하기 때문에, w3wp.exe가 recycle 정책을 위반하는 상태로 진행되면 기존 프로세스를 종료하고 새로운 프로세스를 띄워 서비스를 한 것입니다. 다행히도, 제가 테스트를 IIS 뿐만 아니라 별도로 만든 NT 서비스에서도 수행했고 recycle 정책이 없는 NT 서비스는 문제를 지속적으로 안고 수행되는 바람에 제 눈에 띈 것입니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]