톰캣 CPU 점유 장애 (Feat. GC)

배경

어느 날, 아무 문제 없이 동작하던 웹 서비스에서, 페이지가 조회되지 않는다고 한다.
서버는 어떤 에러도 뱉어내지 않았지만 응답이 매우 느린 상황이었다.
시스템 정보를 보니 CPU를 100%가량 사용하고 있었고, Load Average또한 거의 8까지 올라가 있는 상황이다.

문제의 원인을 찾아보자.

Step1. CPU를 많이 사용하고 있는 프로세스 찾기

=> 톰캣 프로세스에서 CPU를 엄청 사용하고 있었다.

Step2. 이 프로세스에서도 CPU를 많이 사용하고 있는 쓰레드 찾기

ps -mo pcpu,lwp -p ${PID}

=> 4개 쓰레드가 CPU를 엄청 사용하고 있었다.

Step3. 그 쓰레드가 어떤 일을 하고 있었는지 덤프하기

jstack ${PID}

=> 어라..? GC를 하는 쓰레드였다.

Step4. 실제로 GC가 어떻게 일어나고 있는지 확인하기

jstat -gc ${PID} ${SEC}

=> Full GC가 계속 발생하고 있었다.

Step5. 어떤 메모리가 메모리영역에서 남아 있는지 확인하기

jmap -histo ${PID}

=> 대시보드를 조회할 때 사용하는 객체들이 GC되지 않고 남아 있었음

수정한 내용은 무엇인가?

로직 수정

List dashboard = new ArrayList();
List addDashboard = new ArrayList();
...중략...
dashboard.clear();
dashboard.addAll(addDashboard);

결과가 같은 두 리스트 dashboard와 addDashboard를 만들어 둔 다음, dashboard를 지우고 addDashboard를 dashboard에 추가하는 어처구니 없는 로직이 있었다.
물론 이 로직이 원인이 된 것은 아니지만, 영향이 없었다고 말하진 못한다.

GC 관련 설정 수정

• .bashrc 파일 수정

export CATALINA_OPTS="-Xms4G -Xmx4G -XX:NewRatio=2 -Xloggc:$CATALINA_HOME/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps"

 

• 전체 Heap Size 증설 : 현재 2G -> 4G
  • 서버에서 사용할 수 있는 메모리는 8G였지만 2G밖에 사용하고 있지 않아서 2G -> 4G로 증설했다.
  • 그리고, Xms와 Xmx의 크기 설정은 동일하게 하는 것을 권장한다고 한다.
  • Xms:4G ( JVM이 할당하는 최소 Heap Size )
  • Xmx:4G ( JVM이 할당하는 최대 Heap Size )
• YG, OG 영역 비율
  • YG영역의 비율을 높임으로써, OG영역으로 넘어가는 객체의 수를 줄이고 Major GC의 횟수를 줄이려고 함
  • 일반적으로 Minor GC가 Major GC보다 빠르고, Major GC를 할 때 stop-the-world가 발생할 수 있음 ( 다른 thread들이 일을 하지 못함 => 응답 지연 )
  • XX:NewRatio=2 ( YG영역이 10G라면 -> OG영역은 20G가 됨 )
• GC 로그 남기기
  • Xloggc:$CATALINA_BASE/logs/gc.log
  • XX:+PrintGCDetails
  • XX:+PrintGCDateStamps

결론

1. 사실 GC과정에서의 문제는 단순히 톰캣을 재시작하면 그 순간 만큼은 해결된다.
2. 다만 원인파악을 위해서, 현재 상태를 유지한채로 분석이 필요하다.
3. 이번 상황에는 메모리 점유가 많이 없었고, CPU 점유만 높아진 상황이어서, 불필요 로직을 걷어내고, 톰캣에 Java 메모리 관련 설정을 추가했다.

참고

• https://d2.naver.com/helloworld/184615
• https://d2.naver.com/helloworld/1329
• 2020/07/29 - [개발/개발 상식] - GC란 무엇일까?

GC란 무엇일까?