성태의 닷넷 이야기
홈 주인
모아 놓은 자료
프로그래밍
질문/답변
사용자 관리
사용자
메뉴
아티클
외부 아티클
유용한 코드
온라인 기능
MathJax 입력기
최근 덧글
[정성태] Working with Rust Libraries from C#...
[정성태] Detecting blocking calls using asyn...
[정성태] 아쉽게도, 커뮤니티는 아니고 개인 블로그입니다. ^^
[정성태] 질문이 잘 이해가 안 됩니다. 우선, 해당 소스코드에서 ILis...
[양승조
] var대신 dinamic으로 선언해서 해결은 했습니다. 맞는 해...
[양승조
] 또 막혔습니다. ㅠㅠ var list = props[i].Ge...
[양승조
] 아. 감사합니다. 어제는 안됐던것 같은데....정신을 차려야겠네...
[정성태] "props[i].GetValue(props[i])" 코드에서 ...
[정성태] 저렇게 조각 코드 말고, 실제로 재현이 되는 예제 프로젝트를 압...
[정성태] Modules 창(Ctrl+Shift+U)을 띄워서, 해당 Op...
글쓰기
제목
이름
암호
전자우편
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 분석 사례 - 메모리 부족</h1> <p> 테스트 중의 한 웹 애플리케이션이 정상 동작하지 않고 있음을 발견했습니다. 이벤트 로그를 보니 다음과 같이 희귀한 메모리 부족 현상으로 웹 애플리케이션 동작에 문제가 발생한 것인데요.<br /> <br /> <div style='BACKGROUND-COLOR: #ccffcc; padding: 10px 10px 5px 10px; MARGIN: 0px 10px 10px 10px; FONT-FAMILY: Malgun Gothic, Consolas, Verdana; COLOR: #005555'> Name: Application<br /> Source: System.ServiceModel 3.0.0.0<br /> Date: 2014-12-19 오후 10:29:17<br /> Event ID: 3<br /> Task Category: WebHost<br /> Level: Error<br /> Keywords: Classic<br /> User: SYSTEM<br /> Computer: win2008r2.testad.com<br /> Description:<br /> WebHost failed to process a request.<br /> Sender Information: System.ServiceModel.ServiceHostingEnvironment+HostingManager/7699499<br /> 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.<br /> at System.ServiceModel.Activation.ServiceMemoryGates.Check(Int32 minFreeMemoryPercentage)<br /> at System.ServiceModel.ServiceHostingEnvironment.HostingManager.EnsureServiceAvailable(String normalizedVirtualPath)<br /> --- End of inner exception stack trace ---<br /> at System.ServiceModel.ServiceHostingEnvironment.HostingManager.EnsureServiceAvailable(String normalizedVirtualPath)<br /> at System.ServiceModel.ServiceHostingEnvironment.EnsureServiceAvailableFast(String relativeVirtualPath)<br /> Process Name: w3wp<br /> Process ID: 68448<br /> </div><br /> <br /> 문제의 원인은 다른 닷넷 프로세스가 시스템의 전체 메모리를 가져간 것입니다. 그나마 다행인 점은, 가상 머신이어서 메모리 부족 현상이 빨리 발견되었습니다. 메모리 6GB, pagefile.sys 메모리 11GB 정도가 할당되었는데... 그 프로세스 하나만 16GB 가까운 용량을 쓰고 있었던 것입니다. 도저히 해당 머신에서 분석할 수 있는 상황이 아니어서 덤프를 떠서 제 컴퓨터로 가져와 분석을 해보았습니다. (여기서 한가지 재미있는 점! 작업 관리자를 통해 풀 덤프를 뜨면 그 주체는 (ID가 4번인) SYSTEM 프로세스가 됩니다. 또한 도중에 취소도 안됩니다.)<br /> <br /> 닷넷 프로세스였기 때문에, 당연히 코드 상의 잘못으로 메모리 leak이 발생했다고 여겼고, Managed 객체가 많이 생성된 것을 알아내면 문제를 해결할 수 있을 거라 생각했습니다. 하지만, !dumpheap의 결과는 의외였습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:021> <span style='color: blue; font-weight: bold'>!dumpheap -stat</span> 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 <span style='color: blue; font-weight: bold'>000007ff0086cf48 399576 22376256 System.Diagnostics.ProcessThread 000007ff0056fdf8 1134356 54449088 System.Diagnostics.ThreadInfo</span> 000000000036b9f0 12011 83246488 Free 000007ff0019c308 74791 91600328 System.Object[] <span style='color: blue; font-weight: bold'>000007ff0024c0c0 30736 170218072 System.Byte[]</span> 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 </pre> <br /> 보시는 바와 같이 System.Byte[] 용량이 170MB에 불과했고 나머지 용량을 합친다고 해도 도저히 16GB에 육박하는 메모리 사용은 설명이 안됩니다.<br /> <br /> 그런데, 위의 결과에서 약간 이상한 점이 눈에 띕니다. ProcessThread와 ThreadInfo 객체가 유달리 많다는 점인데, !threads 명령으로 문제가 확인됩니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:000> <span style='color: blue; font-weight: bold'>!threads</span> <span style='color: blue; font-weight: bold'>ThreadCount: 14796</span> 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) </pre> <br /> 무려 14,000개가 넘는 스레드가 생성된 것입니다. 그렇다면 각각의 스레드 스택만으로 그렇게 메모리 소비가 되었다는 것인데, 이를 확인하려면 !address 명령을 사용해야 합니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:000> <span style='color: blue; font-weight: bold'>!address -summary</span> Mapping file section regions... ...[생략]... Mapping activation context regions... --- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal Free 12259 7fc`0a3e3000 ( 7.985 Tb) 99.81% <span style='color: blue; font-weight: bold'>Stack 73981 3`9cf00000 ( 14.452 Gb) 91.24% 0.18%</span> <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% ...[생략]... </pre> <br /> 위에서 "Stack" 영역이란 "<a target='tab' href='https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/-address'>Memory used for thread stacks.</a>"를 의미하는 것으로 말 그대로 스레드 스택으로 할당된 용량입니다. 1만 4천 개의 스레드가 스택 용량만으로 14GB가 넘는 용량을 잡아먹고 있는 것입니다. 그럼, !threadpool 명령을 내려 볼까요?<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:14770> <span style='color: blue; font-weight: bold'>!threadpool</span> CPU utilization: 81% Worker Thread: <span style='color: blue; font-weight: bold'>Total: 13779 Running: 13778</span> Idle: 1 <span style='color: blue; font-weight: bold'>MaxLimit: 32767</span> 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 </pre> <br /> 오호~~~ ThreadPool의 Max 값은 32767인데, 그 중에 현재 13779까지 스레드가 생성되었고 그중에서 13778개가 사용 중입니다. 그런데, 특이하게도 CPU 사용률이 81%군요. !runaway 명령어를 내려봐야겠습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:14770> <span style='color: blue; font-weight: bold'>!runaway</span> User Mode Time Thread Time <span style='color: blue; font-weight: bold'>21:1120 1 days 18:23:27.203</span> 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 </pre> <br /> 다행히 1개의 스레드가 독점하고 있군요. 해당 스레드로 문맥 전환을 하고 스레드 콜 스택을 확인해 봅니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:14770> <span style='color: blue; font-weight: bold'>~21s</span> ntdll!NtWaitForSingleObject+0xa: 00000000`76fb05fa c3 ret 0:021> <span style='color: blue; font-weight: bold'>!clrstack</span> 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] </pre> <br /> 이후의 문제 해결은 예전에 썼던 글로 이어집니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > windbg 분석 사례 - cpu 100% 현상 ; <a target='tab' href='http://www.sysnet.pe.kr/2/0/1831'>http://www.sysnet.pe.kr/2/0/1831</a> </pre> <br /> 위에서 제공한 IntBoundSet.put 메서드에는 lock이 있습니다. 그 내부에서 무한 루프 현상이 발생했기 때문에 lock 점유가 풀리지 않았고 이후 들어오는 모든 요청들은 스레드 풀로부터 지속적으로 새로 생성된 스레드에 할당된 것입니다.<br /> <br /> 정리해 보면, 메모리 leak 문제가 아니라 lock 동시성 문제로 인한 스레드 증가로 인해 메모리 부족현상이 발생한 것입니다.<br /> <br /> 한가지 더 재미있는 점이 있는데, 동일한 문제가 Web Application에서는 표면상으로 나타나지 않았다는 것입니다. 왜냐하면 IIS 는 우수한(!) Recycle 정책을 제공하기 때문에, w3wp.exe가 recycle 정책을 위반하는 상태로 진행되면 기존 프로세스를 종료하고 새로운 프로세스를 띄워 서비스를 한 것입니다. 다행히도, 제가 테스트를 IIS 뿐만 아니라 별도로 만든 NT 서비스에서도 수행했고 recycle 정책이 없는 NT 서비스는 문제를 지속적으로 안고 수행되는 바람에 제 눈에 띈 것입니다.<br /> </p><br /> <br /><hr /><span style='color: Maroon'>[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]</span> </div>
첨부파일
스팸 방지용 인증 번호
1035
(왼쪽의 숫자를 입력해야 합니다.)