모니터링과 타임아웃의 중요성은 아무리 강조해도 지나치지 않는다. 최근 회사에서 아주 느린 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. OkHttp ConnectionPool이 여러 개 생긴 것으로 문제가 발생했었다.

공식 홈페이지에서 다운로드한 후 bin 디렉토리의 실행 파일을 실행하면 된다. 실행하면 로컬 환경의 모든 JVM 프로세스를 확인할 수 있다.

bin/visualvm

IntelliJ 플러그인 VisualVM Launcher도 있긴 하지만, 기본적으로 실행했을 때 모든 JVM 프로세스를 확인할 수 있어서 VisualVM을 사용하는 데에 큰 불편함이 없었다.

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은 애플리케이션을 실시간으로 분석하는 데 주로 사용한다.

# $VISUALVM_HOME/etc/visualvm.conf
# Default location of JDK:
#
# It can be overridden on command line by using --jdkhome <dir>
# Be careful when changing jdkhome.
# There are two VisualVM launchers for Windows (32-bit and 64-bit) and
# installer points to one of those in the VisualVM application shortcut 
# based on the Java version selected at installation time.
#
#visualvm_jdkhome="/path/to/jdk"
visualvm_jdkhome="$JAVA_HOME"

# 실행
./bin/visualvm

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

File > Load > *.hprof

visualvm-heap-dump

VisuamVM에서 확인한 Heap Dump

Remote에서 모니터링하기 위해서는 JVM 애플리케이션에 JMX 옵션을 추가해야 한다. Apache Tomcat을 사용한다면 아래와 같이 추가한다.

# Tomcat 다운로드
curl -LO https://archive.apache.org/dist/tomcat/tomcat-8/v8.5.41/bin/extras/catalina-jmx-remote.jar

${CATALINA_HOME}/bin/catalina.sh version

${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 \
  # -Dcom.sun.management.jmxremote.authenticate=true \
  # -Dcom.sun.management.jmxremote.password.file=$CATALINA_BASE/conf/jmxremote.password \
  # -Dcom.sun.management.jmxremote.access.file=$CATALINA_BASE/conf/jmxremote.access \

  # -Djava.rmi.server.hostname=${REAL_HOST} \
  -Djava.rmi.server.hostname=255.255.255.255 \

  -jar

이후 VisualVM에서 다음과 같이 설정한다.

File > Add JMX Connection

File > Add JMX Connection

JVM 옵션으로 추가한 RMI(Remote Method Invocation) HOST와 PORT를 입력한다.

Setting JMX Connection

추가하면 다음과 같이 스레드를 실시간으로 모니터링 할 수 있다. 스레드와 힙 메모리의 스냅샷을 저장할 수도 있다.

Setting JMX Connection

설정만 한다면 여러 호스트를 모니터링 할 수 있다.

Setting JMX Connection

GC Monitoring

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

Tool

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

jstat

JVM Statistics Monitoring
공식 문서

# 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

JDK Tools and Utilities

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

Enabling the Java Profiler

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

이 외의 도구들

JDK Mission Control - Oracle
Pinpoint - NAVER에서 만든 오픈소스 APM
Java Profiler Features - YourKit
JProfiler (유료)

더 읽을 거리

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

Thread Stack

스레드 덤프 분석하기 - NAVER D2
How to Read a Thread Dump - DZone
JVM stack과 frame - 기계인간 John Grib

Heap Memory

하나의 메모리 누수를 잡기까지 - NAVER D2
도움이 될수도 있는 JVM memory leak 이야기 - 우아한 형제들
자바 애플리케이션 성능 튜닝의 도(道) - NAVER D2
Java 애플리케이션 트러블 슈팅 - NAVER D2
Java Memory Analysis - 권남
JVM Crash 문제 해결하기 - 와탭
자바 메모리누수(with 힙덤프) 분석하기 - 김지헌
Java Heap Dump 를 이용한 문제 해결 - 탁구치는 개발자
JVM의 default Heap Size가 궁금하세요? - 삵(sarc)
생애 첫 Heap 메모리 분석기 - 양권성
Eclipse Memory Analyzer 소개 - spoqa
Eclipse MAT — Incoming, Outgoing References - DZone
Remote Monitoring with VisualVM and JMX
아파치 톰캣(Apache Tomcat)을 JMX로 Remote Monitoring 하기
전문가를 위한 스프링 5 (15장 애플리케이션 모니터링)

Garbage Collection

<자바 성능을 결정짓는 코딩 습관과 튜닝 이야기>라는 책의 저자가 쓰신 글들은 모두 재밌고 유용하다.
- Garbage Collection 모니터링 방법 - NAVER D2
- Garbage Collection과 Statement Pool - NAVER D2
  - DBCP 사용시 poolPreparedStatements 속성이 성능에 미치는 영향

기타

Java 프로파일링 도구 - 메이커 꾸러기
OpenJDK 9: Life Without HPROF and jhat - InfoQ
Everything I Ever Learned About JVM Performance Tuning at Twitter - Attila Szegedi

최종 수정: 2022-05-23