[WAS 이슈 해결 #2] MAT 힙 덤프 분석으로 JAVA 메모리 누수(Memory Leak) 잡기 - 톰캣 힙메모리 증가 문제 / Out of Memory

  저번 포스팅에서 CPU사용량, 힙메모리 사용량이 순간적으로 치솟아 서버가 다운되는 현상에 대해서 포스팅 했다. 이번에는 이 문제의 원인을 어떻게 밝혀냈고 해결했는지에 대해서 알아보자.

https://extsdd.tistory.com/257

[WAS 이슈 해결 #1] java.lang.OutOfMemoryError: GC overhead limit exceeded 로 인한 Tomcat 서버 다운 / CPU 사용량

1. 힙메모리(Heap Memory) 덤프

-XX:+HeapDumpOnOutOfMemoryError

  JVM 실행 옵션에 위 옵션을 추가하면 OutOfMemoryError가 발생했을 때 힙메모리 덤프를 떠준다. 위 설정을 적용시켜주고 안타깝지만 문제가 발생할 때 까지 기다리자.

  다시 OOM 문제가 발생했고, 힙 메모리 덤프 파일이 서버에 정상적으로 생성됐다. 위 사진은 분석을 위해 서버에서 생성된 덤프 파일을 내 로컬 PC로 가져온 모습니다.

​

  충격적이게도..덤프 메모리가 10GB나 한다...VDI에서 로컬로 가져오는데 다운 속도도 느리고 중간에 계속 끊어지고 그래서 tar로 압축해 1.5기가로 줄인상태로 가져왔다.

​

  위 사진에 나온 다른 파일들은 MAT를 돌리고 생성된 파일이니 무시하면된다. 우린 java_pidxxxxx.hprof 파일만 있으면 된다.

2. Memory Analyzer (MAT) 설치

  이 힙메모리를 덤프한 hprof 파일을 분석하기 위해선 MAT를 많이들 쓴다. 그래서.. 그냥 검색해서 다운받아 쓰면 되나 했는데.. 여기서도 난관에 봉착했다. ㅋㅋ

​

  이클립스에서 MAT 플러그인을 본거같기도해서 구글에 MAT를 검색하니 진짜로 이클립스 플러그인으로 내장된 Eclipse Memory Analyzer (MAT) 을 많이 사용하더라 ㅋㅋㅋ그래서 개꿀~ 하고 이클립스 마켓플레이스들어가서 플러그인 설치하려고하니.. 회사 네트워크에서 마켓플레이스가 차단되어 있더라.......ㅠ..

​

  어떻게 시간박치기 차력으로 검색하니 프록시로 접속할 수 있게되어 MAT를 설치했다. 그래서 야호! 소리를 지른후 10GB 짜리 덤프파일을 임포트하니 이클립스가 멈췄다. ㅋㅋ.. 아 그래..10GB짜리니까 머..오래 걸리는건가? 하고 마냥 기달렸지만 계속 무응답 상태였다. 그걸또 참지 못하고 그냥 강종해버렸다. 어차피 퇴근시간도 가까워서 걍 임포트 눌러놓고 내일 출근해서 보기로 맘을 먹었다.

MAT 메모리 부족..

  다음날 보니까 MAT의 가용 메모리가 부족해.. 열수 없단다.. 그렇다.. 메모리에 적재해야하는게 10GB가 넘는데... 아마 무리였을꺼야 이해하기로 했다. 후.. OOM 문제로 메모리 누수 분석하려니 분석툴에서 OOM 발생이라니.. ㅋㅋ 또 검색해보니 이클립스 메모리 설정하듯이. MAT도 최대 메모리 설정을 바꾸란다. 아니 근데.. 아무리 찾아봐도.. 이 플러그인으로 딸려온 MAT만 단독으로 설정 바꿀수 있는게 없다..

​

  검색해서 찾은 결과를 보니 사람들은 다 이클립스 플러그인이 아니고 걍 Stand Alone으로 실행하고 있네..? 후.. 결론은 이렇다. 걍 Stand Alone 버전으로 따로 받아서 하는게 젤 맘편하다..

MAT Stand Alone 버전 설치

https://www.eclipse.org/mat/downloads.php

Eclipse Memory Analyzer Open Source Project | The Eclipse Foundation

  후...위 사이트 들어가서 저기 스텐드얼론 버전을 받고 압축을 풀자.

3. Heap Dump 파일 MAT에 Import

  그럼 위 같은 파일들이 나올꺼다. 저기 보라색 행성모양 아이콘이 MAT이다. 일단 메모리 설정부터 하자.

MAT 메모리 설정

저기 보이는 MemoryAnalyzer.ini 를 열어보자.

-vmargs-Xmx10g

  끝에 위 옵션을 추가해주자. 이 MAT 프로세스가 최대 10GB의 메모리를 점유하겠다는거다. 그리고 MAT 실행

  오우...실행 완료. 화면 하단에 보이는 Open a Heap Dump 버튼을 눌러서 아까 빼내온 java_pidxxxxx.hprof 파일을 열자.

  그럼 위 처럼 어떤 레포트 볼꺼냐? 물어보는데 디폴트로 선택된 누수 리포트(Leak Suspects Report)를 선택하고 Finish 해주자.

4. 메모리 누수(Memory Leak) 분석

System Overview

  자 1번 박스를 보자.. 어떤 어떤 한 부분이 거의 모든 부분을 차지하고 있는것으로 보인다. 딱 여기까지만 봐도. 아...이거 메모리 누수 맞구나 직감했다.

​

  노란색 배경의 2번 박스를 보면 이 메모리 누수의 유력한 용의자를 추천해준다 ..ㅋㅋ 음.. 어떤 한 쓰레드가 메모리를 98% 점유 했구만...... 보니까 java.lang.Object[]를 처리하는 중에 문제가 발생한 것으로 보인다.

​

  스프링에선 요청 하나당 쓰레드 하나가 처리하니까, 저기 찍혀있는 쓰레드ID를 카탈리나 로그에서 뒤져보면, 어떤 요청에, 어떤 파라미터로 요청이 왔는지 일단 메모해두면 문제해결하는데 도움이 된다.

​

  나의 경우에는 특정 모든 요청이 문제가 있던건 아니고, 어떤 요청에 특정 파라미터로 요청이 왔을때만 증상이 발생했다. 머 ㅋㅋ.. 지금 중요한건 아니고.. 저기서도 단서를 찾을 수 있다는 것을 알려주고 싶었다. 캡쳐해서 같이 보고싶긴 하나, 회사 소스, 운영계 파라미터를 공개할 수는 없기 때문에 이정도만 하겠다.

​

  다시 돌아와서 3번 박스를 보자. 여기 아주 확실하게 2번에서 문제가된 java.lang.Object[] 이게 소스중 어느파일, 몇 번째 줄인지까지 알려준다. 검은색으로 가린건 소스노출이 있어 가렸고 맨 하단 xxxController.java:266 이라고 써져있듯이, 저부분을 처리하다 메모리 누수가 발생했다고 보면 된다.

메모리에 적재된 객체 분석

  실제로 메모리에 어떤 객체들이 적재되었는지 보기위해서 See stacktrace with involved local variables. 를 클릭하자.

  그럼 이런 화면이 나온다. 당시에 메모리에 적제되어있는 객체들을 뽑아준다. 우리가 봐야할껀 파랗게 표시된 부분이다. 자동으로 MAT가 의심가는 객체를 저렇게 파랗게 하이라이트 해준다.

 

  1번 박스를 보면 딱봐도 저 0x66b6121c0 주소에 할당된 객체가 6.5기가나 잡아먹고 있다는것이 보인다. 그 객체를 눌러서2번 박스처럼 List Object를 눌러주자, 오른쪽 마우스누르는게 아니다. 저 주소값 적혀있는 객체 이름을 눌러주자. 그뒤 3번에 있는 with outgoing references 버튼을 눌러주자.

  자 대충 <class> 객체는 크기가 얼마 안크니 무시하고 6.5GB나 차지하고 있는 elementData를 까보자. 위처럼 나올꺼다. 보니까 Element 하나가 EgovMap 자료형인 ArrayList인가 보네? 1번 박스에 있는 메모리주소를 한번 봐보자, Element 끼리의 메모리 주소 간격이 모두 1BO (Hex) 로 동일하다, 연속적으로 쭉 할당된 것이다.

​

  2번 계산기에서 1BO를 10진수로 바꾸면 432이고 역시 EgovMap 객체 하나당 Retained Heap 을 보면 동일하게 432를 차지하고 있다. 근데 이런게 14,937,421 개나 생성됐다는것..(3번 박스)

​

  이걸 보고 메모리주소들만 보고 바로 직감했다. 아..먼가...반복문에서 new 로 객체생성하는 과정에서 무한루프 걸린거같은데...

  무작위로 객체하나를 까보니까 time, text가 들어가있다. 멀까? 사실 여기까지 볼 필요는 없었다. 그냥 호기심에 여기까지 뜯어본거고. System OverView에서 알려준 문제된 소스 위치로 바로 가도 된다 ㅋㅋ..한번 가보자.

5. 문제 원인

  사실 문제가 된 부분은 System Overview에서 찝어줬었다.. 사실 난 이걸 못봤고 다 끝나고 보니까 어??ㅋㅋ 머야 소스 위치까지 알려줘..? 하고 나중에 알았다. 아무튼 저기 컨트롤러 266번째 줄에서 문제가 발생한 것 같다네? 아마, Call Stack을 추적해서 저 객체들이 갑자기 불어난 지점을 찾아주는 것 같다.

  문제의 원인은 크게 3단계였나, 일단 1번 박스를 보면 Start 시간이 Last 시간보다 커질 경우 루프가 종료된다. 아마 루프 안에서 언젠가 Last 시간이 커지도록 증분이 되겠지? 라고 생각했지만 이상한 부분이 있었다.

​

  2번 박스를 보자, ㅋㅋㅋ 시간을 get해서 만약 null 이면 0이고, 즉 start 시간에 0을 더하니 start 시간은 그대로잖아? 그럼 start가 last보다 커지는 순간이 안오니 무한루프에 걸린거다.ㅋㅋㅋㅋㅋㅋㅋㅋㅋ

​

  3번 박스를 보면 무한 루프안에서 계속 EgovMap 객체를 생성해서 List에 넣어주고 있어다. 그럼 우리가 위에서 분석한거랑 똑같아진다 ㅋㅋㅋㅋ List에 객체를 무한히 생성하고, 이 무한히 생성된 객체가 메모리를 다잡아먹어서 메모리 누수가 발생한 것..실제로 우리가 그 outgoing references에서 본 EgovMap 객체 무더기가 다 이때 생성된 것이다.

​

  그럼 왜 이런현상을 지금 발견한걸까? ㅋㅋㅋ 사실 여태까지 저 컬럼이 null이 오는 경우가 없었다.... 그래서 다 정상적으로 처리되었지만, 아주 특수한 케이스로 .. 진짜 아주아주 극히 드문, 아니 처음이었지 이때가 ㅋㅋㅋ 아주 드문 케이스로 저 값이 null로 들어올 때가 있었던거다.

​

  사실 이문제 발생초기에 특정 파라미터가 문제가 일으키는게 아닐까 생각했어서 카탈리나 로그에서 OOM 발생 직전의 로그들을 다 보았지만, 이게, 딱 저 파라미터로 요청들어왔을 때 바로 로그에 남는게 아니고, 저 요청 후 객체를 생성하고 OOM이 걸릴때까지 몇초의 간격이 있었다. 그런데, 그 몇초 사이에 시스템에선 다른 요청처리한 것에 대한 로그가 그사이에 들어갔기 때문에 난 바로 알아차리지 못했다.. 보니까,, OOM 발생 직전에 항상 저 요청에 저 null이 오는 파라미터가 들어오더라 ㅋㅋ..

6. 후기

  흠..루프문 안에서 객체 생성은 굉장히 위험하다. 물론 내가짠 코드는 아니었지만, 나중에 이런 부분은 한번더 생각하보고 넘어갈 정도로 임팩트가 컸다 ㅋㅋ.. 실제로 운영에 영향을 줬으니까..

​

  아 사실 카탈리나 로그에서 코인 채굴하듯이 로그 뒤지고 하는거보다 그냥 MAT 돌렸으면 바로 잡을 수 있던건데, 실제로 메모리 누수에 대한 트러블 슈팅은 처음이어서 우왕좌왕 해맸던 것 같다. 처음에 이 메모리 관련 이슈로 문제가 발생했을 때 어디서부터 봐야하나 감을 잡을 수 없었는데 이번 경험을 통해서 앞으로 메모리 관련이슈가 발생했을때 음..이거랑 저거 한번체크해봐야겠구만! 하는 약간의 시야는 생긴 것 같다 ㅋㅋ

​

 

#WAS #이슈 #해결 #MAT #MemoryAnalyzer #힙 #힙메모리 #힙덤프 #JAVA #메모리누수 #memoryLeak #OOM #OutOfMemory #메모리분석 #톰캣 #WAS #오류 #다운 #종료 #꺼짐 #GC #overhead #limit #Exceeded #메모리릭 #메모리누수 #힙 #힙메모리 #메모리 #사용량 #점유률 #급등 #증가 #서버 #장애 #트러블슈팅