![[WAS 이슈 해결 #1] java.lang.OutOfMemoryError: GC overhead limit exceeded 로 인한 Tomcat 서버 다운 / CPU 사용량 폭증](https://img1.daumcdn.net/thumb/R750x0/?scode=mtistory2&fname=https%3A%2F%2Fblog.kakaocdn.net%2Fdn%2Fzrznw%2Fbtq1KBMNxd6%2FakQCGCMTUVueFsFDKhEenK%2Fimg.png)
최근 운영중인 웹서비스가 비규칙적으로 다운되는 현상이 있었는데, 발생했던 문제와 그 문제를 해결하는 과정에 대해서 포스팅을 해보려고 한다. 서버 운영을 하는 실무자들에게 도움이 되었으면 좋겠다.
문제 발생
첫 발생이 3월 초쯤 이었던가?.. 운영중인 웹 서비스가 종종 다운되는 현상을 겪었다. 운영 서버에 요청을 보내면 처리되지 않다가 결국 몇 분 뒤 Tomcat 서버가 죽어 위처럼 Service Unavailable 메시지를 띄었다.
보통 부하 분산과 장애에 대비해 WAS를 이중화 해놓기 때문에 WAS하나가 죽어도 다른 WAS가 처리해 줄껀데, 브라우저가 응답대기 상태도 아니고 Service Unavailable 을 띄운걸로 봐서는 WAS두개가 모두 죽은 것 같았다.
어떤 문제가 있었던걸까? 여태까지 악성쿼리때문에 DB 락 걸이 걸려 부하가 걸리는 장애는 종종 겪어 보았지만, 이번 케이스는 달랐다.
단서 1. CPU 사용률에 최대 부하 발생
해당 상황이 접수되고나서 바로 확인해보니 이중화 된 WAS 두개가 아예 삭선처리되어 모두 뻗어있었다. 그냥 Tomcat 서비스가 다운된 상태...
문제가 최초 발생 했을 시간대의 CPU사용량을 보니 WAS 2번이 기존 5~10% 내외로 사용하던 사용량이 어느 시점에 80%까지 올라가며 최대 부하가 걸려있었다. 5분 뒤 WAS 1번도 따라서 같은 현상을 보이기 시작했다.
보통 지연이 길거나, 부하가 강한 요청 중 단순 조회작업이라면 Kill을 해서 일단 서비스 복구를 하고 분석을 할텐데.. 이건뭐 톰캣이 다 죽어있으니 뭘 할수도 없고 ㅋㅋ당장 서비스 복구를 위해 WAS 재부팅밖에 답이 없었다. 그리고 바로 WAS 로그를 확인해봤다.
단서 2. java.lang.OutOfMemoryError: GC overhead limit exceeded
톰캣 로그를 확인하니, 발생 했을 때로 추정되는 시간때에 모두 java.lang.OutOfMemoryError: GC overhead limit exceeded 오류가 찍혀있었다.
GC에 대해서 간단하게 알아보고 넘어가보자. JVM은 메모리 확보를 위해서 GC를 수행한다. 대학 Java 시간에 잠깐 배웠던 그 GC가 맞다 바로 가비지 컬렉션(Garbage collection)이다. 더 이상 사용되지 않는 객체에 대해서 메모리를 해체해주면서 메모리 풀을 관리해주는 친구다.
근데 저 GC overhead limit exceeded 메시지는 왜 띄었는가..?
* GC를 진행하는데 CPU 98% 이상 사용
* GC 진행 후 메모리 2%미만이 복구 되었을 때
일단은 메모리가 부족했던 걸까? 생각이 들었다. 찾아보니, 위 문제에 직면한 경우 보통 JVM 옵션으로 힙 리밋 제한을 없애거나 메모리 사용량을 늘리라고들 하더라. 사실. 나는 이런 셋팅쪽 문제가 아닐거라고 개인적으로 생각은 들었지만, 팀 내부적으론 일단 메모리 부족으로 방향을 잡고, 톰캣, 자바 셋팅쪽을 손봤다.
하지만, 내 예상처럼 이런 증상은 셋팅으로 해결되지 않았다. 몇 일간 원인모를 이유로 서버는 다운됐다..ㅠ
그리고 GC 로그를 확인하기 위해서 서버에 GC로그를 남기는 설정도 추가하여 해당 문제가 발생했을 때 GC로그를 확인했으나, "GC 할껀데 메모리 없어~~~" 사실상 이런 내용만 도배되어있었다. 그런데 GC 시도 엄청 많이 했긴 했더라......암튼 이문제를 해결하는데 GC로그는 도움되지 않았다..
단서 3. 특정 요청에 문제가 생기는 것은 아니었다.
이게 어떤 특정요청에만 생기는 현상일까 생각이 들었다. 머 배치가 돌때 먼가 잘못 도는게 있는걸까? 아니면 사용자가 이상한 파라미터를 던져서 처리를 못하나...? 신기하게도 새벽에는 이런일이 발생하질 않네?.. 해서 의심이 갔었다.
문제가 발생했었을 때의 로그를 확인했으나, 공통점은 없었다. 심지어 GC error 가 발생한 해당 요청을 같은 파라미터를 넣고 다시 요청해도 같은 현상은 발생하지 않았다.
결론부터 말하자면, 특정한 요청이 문제가 됐었다. 다만, 내가 바로 찾지 못한 이유는, 이미 문제가 발생한 이후에 로그에 찍힌 GC error 로그에만 집착했기 때문이었다. 일단은 GC error 로그가 어떤 요청에 찍혔다 하더라도, 그 요청이 문제가 아니라는 거다. 이미 문제는 발생했고, 우연히 그 요청을 처리중일 때 GC 가 동작하여 error 을 띄운거란거다.
만약 이방법으로 간단하게 볼려면, GC Limit 이 발생하기 전 로그들을 뒤져봐야 한다.
이런 현상이 지속되고, 팀원들이 이 문제를 해결하기 위해 이미 붙어있었기 때문에, 내 업무를 좀 쳐내고 나중에 시간이 남으면 보려고 생각했다. 뭐 그때쯤 가서 이미 해결이 되면, 좋은거긴 한데, 나는 셋팅쪽 문제가 아닐꺼란 생각이 계속 들었다.
단서 4. 힙메모리 사용량 증가
시간적 여유가 생겨 다시 문제를 분석해봤다. 보니까 해당 문제가 발생 했을 때 CPU사용량도 돌라갔었지만, 힙 메모리 사용량도 폭발적으로 증가하는 현상이 확인되었다.
왜 처음부터 힙메모리 관제에 신경쓰지 않았을까, 평소에 악성쿼리처럼 CPU를 많이 점유하던 장애를 주로 만났었기 때문에 메모리보다는 CPU 사용량이나 어떤 요청이 왔는지 이런거 위주로 봤던게 좀 방심했던 것 같다.
원래 힙메모리 사용량의 이상적인 그래프는 맨 아래 그래프처럼 어느정도 메모리가 올라가다 GC가 작동하여 떨어지고, 계속 반복하여 적정한 수준을 유지하는게 이상적이다.
하지만 위 사진을 보다시피 3월 16일동안 3회나 01번 02번 WAS 힙메모리 점유율이 급격하게 올라가는 것을 볼 수 있다.
문제 해결을 위한 방향성 잡기
자 여기까지 정리를 해보자.
1. 새벽이 아닌 주야간 워크 타임때, 그리고 불특정, 비규칙적인 시간에 서버가 다운이 된다.
2. CPU 사용량과 힙 메모리 점유율이 급격히 상승한다.
3. 서버 에러 로그에는 GC overhead limit exceeded 이 발생한다.
자 일단 에러로그에 GC 할 메모리가 부족하다고 되어있어서 GC에만 문제가 있었던건가 여기에만 집중했지만, 내 생각에는 이건 메모리가 부족해지고 나서, 즉 어떤 문제가 발생하고 그 이후에 파생된 현상이지 주 원인은 갑작스럽게 메모리를 차지한 어떤게 있을거라고 생각했다.
즉, 어떤 원인에 의해 메모리가 급격하게 사용되었고, 그 이후에 평소처럼 GC를 하려니 GC 리밋 로그를 띄운 것 이다. 나도 그랬지만, 보통 다른 사람들도 이 GC 리밋 에러 로그를 보고, 왜 GC 리밋 로그를 띄었을까..? 검색해보면 "서버 힙메모리가 부족하네요 ㅎㅎ" 이럴텐데 이렇게 접근해서는 해결 할 수 없는 문제였다. (내 케이스의 경우)
자. 정리하자면 GC 관련된 문제가 아닐꺼다, 무언가가 힙메모리를 엄청나게 차지하니까, 당연히 GC도 못하니 저 오류를 띄운거고, 우리는 앞으로 어떤 녀석이 힙메모리를 그 순간에 차지하고 있었는지를 찾아야한다.
앞으로 해야할게 바로 힙메모리 분석이다. 다음 포스팅을 통해서 힙메모리 분석을 어떻게 했고, 어떤게 원인이었으며, 어떻게 조치했는지에 대해서 알아보자
#톰캣 #WAS #오류 #다운 #종료 #꺼짐 #GC #overhead #limit #Exceeded #메모리릭 #메모리누수 #힙 #힙메모리 #메모리 #사용량 #점유률 #급등 #증가 #서버 #장애 #트러블 슈팅