Im Changsu
JVM 모니터링
이게 왜 죽지..?

모니터링과 타임아웃의 중요성은 아무리 강조해도 지나치지 않는다. 최근 회사에서 아주 느린 API(약 15초)를 발견했는데 분명 매일 트래픽이 발생하는데도 2년동안 방치되고 있었다. 이런 레거시는 유지 보수할 일이 없다면 개발팀에서도 확인하기 어렵다. 사용자가 리포팅해주길 기대하는 것보다 모니터링 도구를 통해 파악하는 것이 좋다. 심지어 굉장히 간단한 문제여서 파악하고 수정하는 데에 1시간도 안걸렸지만 약 15초 걸리던 API를 100ms까지 줄였다.

먼저 알아두면 좋은 명령어가 있다. jps는 JVM Process Status를 출력하는 명령어로 현재 머신에서 실행중인 JVM의 PID나 실행 옵션을 확인할 때 유용하다.

> jps -v
${PID} Bootstrap -Djava...

Thread Dump

A thread dump is a snapshot of the state of all threads that are part of the process. (Oracle Docs)

쓰레드 덤프(Thread Dump)란 모든 쓰레드 상태의 스냅샷이다.

java-thread-state-machine

Java Thread States and Life Cycle

쓰레드 덤프에 메서드 콜 스택 정보를 가진 스택 프레임(Stack Frame)은 없다.

Debugging in IntelliJ

IntelliJ에서 디버깅하면 볼 수 있는 스택 프레임

Thread1   Thread2   Thread3
+-------+ +-------+ +-------+
|       | |       | |       |
|       | |       | | frame |
|       | |       | | frame |
| frame | |       | | frame |
| frame | | frame | | frame |
+-------+ +-------+ +-------+

Daemon Thread

  • Daemon Thread
    • thread.setDaemon(true)
    • Daemon Thread는 JVM 종료 시 자동으로 강제 종료한다.
    • 언제든지 죽어도 상관없는 작업에 사용한다.
    • Garbage Collector, JMX
  • Non-Daemon Thread
    • thread.setDaemon(false)
    • Non-Daemon Thread가 실행 중인 경우 JVM은 종료되지 않는다.
    • 기본적으로 개발자가 새로 생성하는 쓰레드는 Non-Daemon Thread이다.
    • 메인 쓰레드(Main Thread)도 Non-Daemon Thread다.
// java.lang.Thread
/* Whether or not the thread is a daemon thread. */
private boolean daemon = false;

Tool

나는 주로 쓰레드 간 교착 현상(deadlock)이나 단일 쓰레드의 병목 현상이 의심될 때 사용한다. 하지만 NAVER D2에 올라온 글 ‘스레드 덤프 분석하기‘를 보면 이 외의 다양한 상황에서도 쓰레드 덤프를 확인해 볼 수 있다. 쓰레드 덤프 분석이 처음이라면 해당 글을 정독해보자.

jstack

쓰레드 스택(Java Thread Stack)을 확인할 수 있는 CLI 도구다.

> jstack -l ${PID} > thread_dump.txt

VisualVM

VisualVM을 사용하면 실시간으로 쓰레드 스택의 상태를 확인할 수 있다.

visualvm-tomcat-threads

VisualVM에서 확인한 Thread Stack

Heap Dump

A heap dump is a snapshot of all the objects in the Java Virtual Machine (JVM) heap at a certain point in time. (Oracle Docs)

힙 덤프(Heap Dump)란 JVM 힙의 모든 Object를 담은 스냅샷이다.

OutOfMemoryError

JVM 실행 시 아래 옵션을 추가하면 OutOfMemoryError 발생으로 JVM이 종료될 때 힙 덤프를 생성한다.

  • -XX:HeapDumpPath를 생략하면 Java Process를 실행시킨 곳에 java_pid<pid>.hprof 형태로 파일이 생성된다.

    By default the heap dump is created in a file called java_pid.hprof in the working directory of the VM. - Oracle Docs

  • -XX:+PrintClassHistogramAfterFullGC-XX:+PrintClassHistogramBeforeFullGC 등의 옵션으로 Full GC 전후의 메모리 상태를 간략히 덤프할 수 있다.
-XX:+HeapDumpOnOutOfMemoryError \
-XX:HeapDumpPath=jvm.hprof

Tool

OutOfMemoryError가 발생한 게 아니라면 jmap을 사용해서 힙 덤프를 확인할 수 있다.

# jmap -dump:format=b,file=/path/app.hprof ${PID}
jmap -dump:file=/path/app.hprof ${PID}
Dumping heap to /path/app.hprof ...
Heap dump file created

> file /path/app.hprof
app.hprof: Java HPROF dump, created Tue May 17 01:15:39 2022

Eclipse Memory Analyzer (MAT)

MAT는 힙 덤프를 분석할 수 있게 도와주는 프로그램이다.

  • JDK를 찾지 못하는 경우 아래와 같이 옵션을 추가한다.
# ${MAT_HOME}/MemoryAnalyzer.ini
-vm
${JAVA_HOME}/bin

# -vmargs 보다 위에 추가해야 한다.
-vmargs
...

기본 Heap Size가 1024m이다. Heap Dump 파일이 이보다 큰 경우 Parsing할 때 아래와 같은 에러가 발생한다.

An internal error occurred during:
    "Parsing heap dump from '/path/java_pid1234.hprof'".
Java heap space

설정 파일에 JVM 옵션을 추가하면 확인할 수 있다.

# ${MAT_HOME}/MemoryAnalyzer.ini
-vmargs
#-Xmx1024m
-Xms6g
-Xmx6g

VisualVM

VisualVM은 애플리케이션을 실시간으로 분석하는 데 주로 사용한다.

# etc/visualvm.conf
visualvm_jdkhome="$JAVA_HOME"
> ./bin/visualvm

아래 기능으로 힙 덤프를 간략히 확인할 수도 있다. 하지만 기능이 다양한 MAT가 있기 때문에 VisualVM은 실시간으로 확인하는 용도로 사용한다.

  • File > Load > *.hprof

visualvm-heap-dump

VisuamVM에서 확인한 Heap Dump

Remote로 연결하기 위해서는 WAS에 JMX 설정이 필요하다.

# 버전에 맞춰서 다운로드
> ${CATALINA_HOME}/bin/catalina.sh version

> curl -LO https://archive.apache.org/dist/tomcat/tomcat-8/v8.5.41/bin/extras/catalina-jmx-remote.jar

> ${CATALINA_HOME}/bin/catalina.sh start \
-Dcom.sun.management.jmxremote \
-Dcom.sun.management.jmxremote.local.only=false \
-Dcom.sun.management.jmxremote.port=1099 \
-Dcom.sun.management.jmxremote.rmi.port=1099 \
-Dcom.sun.management.jmxremote.ssl=false \
-Dcom.sun.management.jmxremote.authenticate=false \
-Djava.rmi.server.hostname=127.0.0.1 \
-jar

GC Monitoring

GC 모니터링이란 JVM이 어떻게 GC를 수행하고 있는지 알아내는 과정을 말한다.

Tool

처음이라면 NAVER D2에 올라온 글 ‘Garbage Collection 모니터링 방법‘이 굉장히 도움된다.

jstat

# 1초마다 gc 확인
> jstat -gc <PID> 1000
> jstat -options
옵션 기능
gc 각 힙(heap) 영역의 현재 크기와 현재 사용량(Eden 영역, Survivor 영역, Old 영역등), 총 GC 수행 횟수, 누적 GC 소요 시간을 보여 준다.
gccapactiy 각 힙 영역의 최소 크기(ms), 최대 크기(mx), 현재 크기, 각 영역별 GC 수행 횟수를 알 수 있는 정보를 보여 준다. 단, 현재 사용량과 누적 GC 소요 시간은 알 수 없다.
gccause -gcutil 옵션이 제공하는 정보와 함께 마지막 GC 원인과 현재 발생하고 있는 GC의 원인을 알 수 있는 정보를 보여 준다.
gcnew New 영역에 대한 GC 수행 정보를 보여 준다.
gcnewcapacity New 영역의 크기에 대한 통계 정보를 보여 준다.
gcold Old 영역에 대한 GC 수행 정보를 보여 준다.
gcoldcapacity Old 영역의 크기에 대한 통계 정보를 보여 준다.
gcpermcapacity Permanent 영역에 대한 통계 정보를 보여 준다.
gcutil 각 힙 영역에 대한 사용 정도를 백분율로 보여 준다. 아울러 총 GC 수행 횟수와 누적 GC 시간을 알 수 있다.

Visual GC

JVM이 어떻게 GC를 수행하고 있는지 확인할 수 있다.

VisualGC Plugin

VisualVM의 Tools > Plugins에서 다운로드 할 수 있다.

visualgc-with-visualvm

함께 사용하는 도구들

JDK Tools

Java Platform Standard Edition 8 Documentation

Java Platform Standard Edition 8 Documentation

  • jcmd: 성능 관련 카운터 조회
> jcmd ${PID} PerfCounter.print
java.threads.daemon=42
java.threads.live=49
java.threads.livePeak=52
java.threads.started=3951
...
  • jmap: JVM Heap 조회
> jmap -heap ${PID}
Attaching to process ID 3838860, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.292-b10

using thread-local object allocation.
Parallel GC with 10 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 8348762112 (7962.0MB)
   NewSize                  = 174063616 (166.0MB)
   MaxNewSize               = 2782920704 (2654.0MB)
   OldSize                  = 348127232 (332.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 2094006272 (1997.0MB)
   used     = 398200696 (379.75377655029297MB)
   free     = 1695805576 (1617.246223449707MB)
   19.0162131472355% used
From Space:
   capacity = 82837504 (79.0MB)
   used     = 0 (0.0MB)
   free     = 82837504 (79.0MB)
   0.0% used
To Space:
   capacity = 78643200 (75.0MB)
   used     = 0 (0.0MB)
   free     = 78643200 (75.0MB)
   0.0% used
PS Old Generation
   capacity = 467140608 (445.5MB)
   used     = 107232904 (102.26526641845703MB)
   free     = 359907704 (343.23473358154297MB)
   22.955166423896078% used

47952 interned Strings occupying 5230216 bytes.
  • jhat: Java Heap Analyzer Tool
    • JDK 9에서 제거되었다.
> jhat -J-Xmx6g -port 7000 /path/app.hprof

Datadog

-Ddd.profiling.enabled=true \
-XX:FlightRecorderOptions=stackdepth=256

이 외의 도구들

더 읽을 거리

다른 개발자들의 실제 사례를 보면 얻을 수 있는 인사이트가 많다.

Thread Stack

Heap Memory

Garbage Collection

기타