5. JVM 모니터링
5.1 Thread
5.1.1 Thread Dump
JVM의 현재의 thread 상태를 파일로 기록하는 것이다.
어떤 스레드 그룹이 있는지, 각 스레드의 상태(running, wait), 각 스레드가 실행하고 있는 클래스 파일 등을 볼 수 있다.
갑자기 CPU 사용율이 치솟거나, 스레드 자원을 할당하지 못해서 프로그램이 병목이 될 때, 원인을 분석하기 위해서 사용한다.
thread dump를 남기는 방법은 여러가지 방법이 있다.
- JMX+VisualVM을 이용한 remote 조회 (JMX포트를 열어놓았다면, 원격으로)
jcmd <pid> <target>(호스트에 들어가서 자바 기본 커맨드 통해 파일로 남길 수 있음)- thread dump:
jcmd <pid> Thread.print> $your_file - 가능한 target 조회:
jcmd <pid> help
- thread dump:
JMX+jconsole을 이용하면 실시간 remote 조회가 가능하다.
visualVM에서 PID 확인하고, 19619
intelliJ 새로운 터미널 열어서 jcmd 19619 help 입력.
이친구한테 jcmd로 가져올 수 있는 정보들의 리스트가 쭉 있다. 내리다 보면 GC도 있고
Thread 관련된 건 print밖에 없었지만
jcmd 19619 Thread.print > ./thread_19619.dmp
이렇게 입력해서 Thread.print에 대한 Thread dump가 파일로 저장된 것을 확인할 수 있다.
Jconsole 통해서 실시간 조회도 가능하다.
이렇게 디버깅 된 상황이 있으면 dump부터 우선 남겨놓고 그 다음에 원인 파악을 하는 게 좋다.
5.1.2 Metrics
JMX 또는 prometheus로 노출된 metric에서 thread가 들어간 메트릭으로 상태를 확인할 수 있다.
(사용하는 도구, 라이브러리, 플러그인, agent, 설정 등에 따라서 종류나 이름이 달라질 수 있다.)
다음 내용들을 확인할 수 있다.
- thread count
- thread cpu time
- uptime (언제 떠서 지금까지 재기동 없이 잘 살아 있나 이런 거 확인할 때 쓰는 것)
5.2 Memory
5.2.1 Heap Dump
JVM의 현재의 heap 메모리 상태를 파일로 기록하는 것이다.
heap영역 별로 사용량이 얼마나 되는지, 클래스별 object의 수 등을 볼 수 있다.
메모리 사용율이 예상보다 높게 사용되거나, OOM으로 프로그램이 죽은 적이 있다면 원인을 분석하기 위해서 사용한다.
heap dump를 남기는 방법은 여러가지 방법이 있다.
- JMX+VisualVM을 이용한 remote 조회
jmap -dump:[live],format=b,file=<file-path> <pid>jcmd <pid> <target> <file-path>- GCheap dump:
jcmd <pid> GC.heap_dump <file-path> - 가능한 target 조회:
jcmd <pid> help
- GCheap dump:
JMX+jconsole을 이용하면 실시간 remote 조회가 가능하다.
5.2.2 Metrics
주로 다음 메트릭들을 확인 한다. (사용하는 도구, 라이브러리, 플러그인, agent, 설정 등에 따라서 종류나 이름이 달라질 수 있다.)
- heap usage/size
- off(non) heap usage/size
- heap의 영역별 usage/size
논힙은 자바가 VM인데 자기가 자기 메모리 말고 운영체제 메모리를 조금씩 쓰는 게 있다. 특히 네이티브 콜이 일어나면 이렇게 운영체제 메모리른 쓴다. 자바에서 사용하는 네이티브 메모리라고 보면 될 것 같고 그것도 기록을 할 수 있다.
그리고 힙의 영역별 (영젠, 올드젠 등) usage나 사이즈를 알 수도 있고
5.3 GC
5.3.1 GC Log
GC는 자바 성능에 큰 영향을 미친다.
따라서 GC가 일어날 때마다 로그를 기록해서 GC를 어떤 이유로 얼마나 수행했는지를 남길 수 있다.
기본 옵션
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:$your_logfile_name -XX:+UseGCLogFileRotation -XX:GCLogFileSize=1m -X
X:NumberOfGCLogFiles=10- -XX:+UseGCLogFileRotation, -XX:GCLogFileSize, -XX:NumberOfGCLogFiles 설정으로 자동으로 rotate 할 수 있다.
추가 옵션
-XX:+PrintClassHistogramAfterFullGC
-XX:+PrintClassHistogramBeforeFullGC
-XX:+PrintGC
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-XX:+PrintReferenceGC5.3.2 GC Log Analyzer
https://gceasy.io/ 사이트에서 하루 5건 무료로 분석하고 시각화 할 수 있다.
GC log 파일이 여러개라면 압축해서 올리면 된다.
5.3.3 GC Log 내용
이미지 출처 : https://dev.to/sematext/java-garbage-collection-logs-how-to-analyze-them-4hgb
5.3.4 Metrics
주로 다음 메트릭들을 확인 한다. (사용하는 도구, 라이브러리, 플러그인, agent, 설정 등에 따라서 종류나 이름이 달라질 수 있다.)
사용하는 GC 알고리즘에 따라서도 메트릭 이름이나 종류가 다르다.
- gc thread count
- memory usage before/after gc
- gc time/duration
- gc의 단계별 count or duration
5.3.5 GC Log 실습
1) 실습 코드
build.gradle
implementation 'org.apache.commons:commons-lang3:3.12.0'Oom.java
import java.util.ArrayList;
import java.util.List;
import org.apache.commons.lang3.RandomStringUtils;
public class Oom {
public static void main(String[] args) throws InterruptedException {
List<String> list = new ArrayList<>();
while(true) {
new Object();
String str = RandomStringUtils.random(10);
list.add(str);
if(str.contains("a")){
Thread.sleep(500);
}
}
}
}VM Option 에 다음 옵션으로 실행한다.
-Xms128m -Xmx128m -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:./gc_%p.log -XX:+UseGCLogFileRotation -XX:GCLogFileSize=1m -XX:NumberOfGCLogFiles=10실습 설명
Thread.sleep(500)은 객체 생성과 메모리 증가 속도를 늦춰, GC가 발생할 수 있는 타이밍을 확보하는 용도로 사용된다. JVM은 메모리 사용량이 일정 임계치를 넘었을 때 GC를 수행하므로, sleep을 넣으면 메모리 누적 속도를 조절할 수 있고, 그에 따라 GC 발생과 그 효과를 관찰하기 쉬운 환경이 된다. 실험 환경에서 GC 동작을 확인하려는 목적에서 사용되는 코드이다.
Thread.sleep(500)은 해당 코드를 실행 중인 현재 스레드(여기서는 main 스레드)만 멈추게 한다. GC는 JVM 내부에서 별도의 GC 스레드에 의해 작동하며, main 스레드가 sleep 중일 때도 필요하다면 GC는 독립적으로 수행된다. 따라서 sleep이 있다고 해서 전체 애플리케이션이 멈추는 것은 아니며, GC가 작동할 여유를 확보해준다는 의미로 해석하는 것이 옳다.
new Object()로 생성한 객체는 아무 곳에도 참조되지 않으므로 즉시 GC 대상이 된다. 반면, list.add(str)로 생성된 문자열은 리스트에 보관되므로 참조가 유지된다. 이처럼 참조가 끊기지 않은 객체들이 계속 리스트에 쌓이면 Young Generation의 Eden 영역과 Survivor 영역이 가득 차고, 결국 Old Generation도 차게 되어 Minor GC, 나아가 Full GC까지 발생하게 된다. GC는 이런 메모리 포화 상태가 되었을 때 자동으로 발생한다.
JVM이 사용하는 GC 알고리즘은 JVM 옵션으로 지정되며, 명시하지 않을 경우 JVM 버전에 따라 기본값이 다르다. 예를 들어, Java 8에서는 Parallel GC, Java 11 이상에서는 G1 GC가 기본이다. 현재 어떤 GC가 사용되고 있는지 확인하려면 실행 시 -XX:+PrintGCDetails 또는 -Xlog:gc* 옵션을 주거나, jinfo, jstat, 또는 GC 로그 출력을 통해 확인할 수 있다.
로그 분석
떨어진 로그를 https://gceasy.io/ 에서 분석해보자.
프로그램이 종료되고 나온 gc_pid21775.log.0.current 파일을 사이트에 업로드 해서 Analyze 누르면 분석이 진행된다.
(파일이 너무 커져서 일정 용량 이상이 되면 분석을 못 할 텐데 그 때는 압축해서 용량 줄여서 넣어도 된다.)
영역 별로 메모리 사이즈를 볼 수 있는데 Meta space(GC 못 함)가 너무 많아져서 OOM으로 실행시켰던 코드가 끝이 난 것을 알 수 있다.
그리고 GC가 여러 번 수행됐는데, 그 중에 어느 정도 시간대가 많이 걸렸는지 볼 수 있었다. GC는 50ms 미만으로 끝나야 좋은데 실제 50ms 미만으로 들어온 건 7%도 되지 않고 대부분 성능이 좋지 않다는 것을 알 수 있었다~
Heap Usage
minorGC/fullGC 의 총 걸린(누적) 시간, 반환된 byte, 평균 시간 어 어떤지 비교
각종 GC Statistics
오브젝트 스텟에서
새로 만든 게 얼마고,
(옮겨간 거)프로모션 된 게 얼마고
GC에 사용된 CPU.
5.4 Crash Dump
JVM이 예상치 못한 시스템 크래시로 강제종료될 때의 상태를 파일로 기록하게 할 수 있다. 주로 Native Library 를 사용할 때 나타난다. (잘못된 메모리 요소를 참조해서 나타나는 경우가 많다.)
Host machine이 강제종료되는 것은 JVM도 알 수 없으므로 상태를 남길 수 없다.
5.4.1 Crash Dump 파일 옵션
JVM 프로그램 실행시 -XX:ErrorFile=$PATH 로 파일 위치를 지정할 수 있다.
- Linux 기본 경로는
/var/log/java/
5.4.2 Crash Dump 가 남지 않는다면
/$path usage full: Crash Dump가 저장되는 파일시스템(/path)의 사용량이 100%인 경우, 로그가 기록되지 않는다.- 권한 문제 : Java 프로세스를 실행하는 계정이 대상 경로에 쓰기 권한이 없는 경우 로그가 남지 않는다. 이 경우 JVM 옵션(
-XX:ErrorFile,-XX:HeapDumpPath등)을 통해 로그 경로를 명시적으로 설정해야 한다. - JVM Bug : 매우 드물지만 JVM 자체의 버그로 인해 Crash 로그가 기록되지 않는 경우도 있다. 이 경우 원인 규명이 어렵다.
Crash Dump가 남지 않는 경우, 대부분은 권한 문제 때문이다. 예를 들어 /var/log/java/ 경로에 대해 실행 중인 프로세스 계정이 쓰기 권한이 없으면 로그가 남지 않는다. 또한 운영체제 파일시스템 자체가 가득 찼다면 로그가 기록되지 않는다. JVM Bug는 발생 가능성이 매우 낮다.
이렇게 해서 JVM이 어떤 시스템인지,
그 안에 메모리는 어떻게 구성됐는지,
그 메모리 영역을 정리하는 GC과정은 어떻게 일어나는지,
이런 동작들을 모니터링 하려면 JMX라는 표준 API랑 인터페이스가 있는데 그걸 어떻게 설정하는지,
어떤 툴로 모니터링 하는지,
이제 그 기록을 내가 파일로 남기고자 할 때 어떻게 남기는지,
나중에 추후 분석은 어떻게 하는지,
crash dump 에러의 종류들은 뭔지 알아보았다.
