Tomcat, Netty의 쓰레드 덤프 분석을 통해 병목 지점을 분석해보자 - Prometheus,Grafana를 통한 시각화 모니터링
자바 쓰레드의 상태(Thread State)
상태 전이에 대해 간략하게 설명하기 전에 종류나 알고 가자
- NEW : 쓰레드가 생성되었으나 아직 시작되지 않은 상태 (아직 OS 쓰레드는 존재하지 않는 상태)
- Thread.start()를 호출해야 OS에서 실제로 쓰레드를 생성
- RUNNABLE : 쓰레드가 실행 가능하여 OS의 리소스를 기다리거나 JVM 안에서 실행중인 상태
- OS 스케줄러의 실행 대기열에 포함되었다가 차례로 CPU에서 실행된다.
- BLOCKED : 쓰레드가 동기화 락을 기다리며 Block된 상태
- WAITING : 무한정 대기중인 쓰레드 (CPU 입장에서 Waiting과 Blocked는 동일)
- TIMED_WAITING : 쓰레드가 지정된 시간동안 대기
- TERMINATED : 실행 완료되었거나 예외가 발생하여 종료된 쓰레드의 상태
- 한번 종료된 쓰레드는 다시 시작할 수 없음
쓰레드 상태의 전이
- 생성(NEW) → Thread.start() 호출 → OS가 실제 쓰레드 생성(Runnable)
- 실제 요청을 처리하기 위한 상태(Runnable)는 OS 스케줄러에서 CPU를 할당받아 실행중이거나 기다리는 상태
- Java에서는 이 둘을 구분할 수 없기에 합쳐서 Runnable로 표현
- 그러다 쓰레드가 현재 코어를 사용할 수 없다면 Blocked, Waiting, Timed Waiting 상태를 오가며 변하는데, 모두 OS에 의해 즉시 코어에서 쓰레드가 분리된 상태이다.Waiting : OS에서 조건이 충족됐다는 신호(Object.notify() 등)가 올 때까지 무한정 대기
- Timed Waiting : 일정 시간 절전모드를 요청하는 셈
- Blocked : 다른 쓰레드가 보유한 모니터 락을 획득하기 위한 상태
쓰레드 덤프(Thread Dump)를 통한 상태 분석
실행중인 프로그램의 모든 쓰레드 상태와 관련 정보를 캡처한 스냅샷으로, 애플리케이션 디버깅이나 성능 분석시 유용하다. (쓰레드 이름, 상태, 스택 트레이스, 모니터와 잠금 정보)
jstack -l $(lsof -t -iTCP:8080 -sTCP:LISTEN) > thread_dump.txt
// lsof -t -iTCP:8080 -sTCP:LISTEN : 8080 포트를 사용하는 pid 찾기
// jstack -l <PID> > thread_dump.txt : pid에 해당하는 프로세스의 쓰레드 덤프 뜨기
// -l : Lock에 관련된 추가 정보를 제공
-sTCP:LISTEN : 요청을 기다리는(Listen) 프로세스로 제한하지 않으면 요청을 처리하는 다른 클라이언트가 존재하는 경우 여러 PID가 전달되어 오류가 발생할 수 있다.
Error: More than one non-option argument
Cannot connect to core dump or remote debug server. Use jhsdb jstack instead
JPS 명령어나 TDA 도구를 통해 자바 프로세스 목록을 확인하고 쓰레드 덤프를 분석할 수 있다.
Heap 덤프도 분석할 생각이면 VIsualVM이 유용할 거 같다. (난 MAT 쓰고 있긴함)
Docker 컨테이너에서 실행한 애플리케이션의 쓰레드 덤프 수집
현재 실행중인 Java 프로세스를 보여주며 PID도 확인할 수 있다.
# jps
1 /app.jar
162 Jps
app.jar의 PID는 1이다.
# jstack -l 1 > /tmp/thread_dump.txt
// 쓰레드 덤프 뜬다.
# docker cp 0832f4deec8f:/tmp/thread_dump.txt "<Directory>\thread_dump.txt"
// 호스트 머신의 해당 경로로 복사해서 직접 읽어본다.
jstack -l <PID> : 해당 프로세스의 쓰레드 덤프를 수집한다.
docker cp : 호스트 머신의 원하는 경로로 thread_dump.txt를 복사해올 수 있다.
0832f4deec8f는 실행중인 애플리케이션의 컨테이너 Id이다. (docker ps로 확인 가능)
Tomcat의 Thread Dump 분석
스프링 애플리케이션에서는 쓰레드 풀에서 꺼내쓰면서 재사용한다. (쓰레드의 생성 비용 문제)
- server.tomcat.threads.min-spare : 최소 작업 쓰레드의 수(default=10)
- server.tomcat.threads.max : 최대 작업 쓰레드의 수(default=200)
Tomcat은 min-spare만큼 쓰레드 풀을 생성하되, 요청이 많아지면 max 수만큼 쓰레드 수를 늘린다.
이에 관해서는 글쓰는데 참고한 해당 블로그에 자세히 나와있다.
[Java] 스프링 톰캣의 스레드 덤프를 통한 스레드 상태에 대한 이해(Thread State with Spring Application Tom
1. 자바 스레드의 여러 가지 상태들[ 여러 종류의 스레드 상태들(Thread State) ]자바 공식 문서(자바 23 기준)에 따르면 다음과 같은 자바 스레드 상태가 존재한다.NEW스레드가 생성되었으나 아직 시
mangkyu.tistory.com
Netty의 Thread Dump 분석
사실 문제가 발생해서 블로킹을 확인하려는 프로젝트가 Spring Webflux 환경이라 WAS로 Netty를 사용한다.
스냅샷 형태의 덤프 파일은 순간적인 상태만 보여주기 때문에 쓰레드 상태 변화를 확인하기 어렵다.
thread dump 뜰때는 10초 간격으로 3번 덤프 뜨는게 유용하다고 하니 나도 그렇게 진행하겠다.
Webflux 환경에서는 특히 블로킹이 발생하면 작업 쓰레드(이벤트 루프)가 멈추고 성능 저하를 발생킨다.
Netty는 Nio나 Epoll에 기반한 이벤트루프를 작업 쓰레드로 생성한다.
- reactor-http-nio-* : Java NIO 기반
- reactor-http-epoll-* : Linux Epoll 기반
"grpc-default-worker-ELG-1-1" #30 daemon prio=5 os_prio=0 cpu=3.85ms elapsed=977.10s tid=0x00007f4659d55700 nid=0x4f runnable [0x00007f462c97d000]
java.lang.Thread.State: RUNNABLE
at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait0(Native Method)
at io.grpc.netty.shaded.io.netty.channel.epoll.Native.epollWait(Native.java:182)
at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:312)
at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:376)
at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(java.base@17.0.2/Thread.java:833)
Locked ownable synchronizers:
- None
쓰레드 상태에 따른 예상 원인 분석
- RUNNABLE 상태인 경우 실행중인 작업이 많아 CPU Bound일 가능성 농후
- 어디에서 대기하는지 확인하기
- WAITING, TIMED_WAITING이면 문제
- BLOCKED : 락 경합이 발생할 가능성
실제 프로젝트의 문제 상황을 해결하기 위한 쓰레드 덤프 수집 및 분석
마이크로서비스간의 통신을 통해 원하는 데이터를 요청해서 받아오는 비즈니스에 대해서 메시지 수신을 담당하는 로직이 지연되는 현상이 발생했었다.
사실 비동기 방식으로 구성된 프로젝트가 마냥 좋기만 한게 아닌게..
로그 출력같은 블로킹 함수나 로직상 블로킹 구조를 띄게 되면 오히려 MVC 방식으로 하는 것보다도 성능적으로 더 구려질 수 있다.
그래서 비동기로 개발을 하겠다고 하면 당연히 블로킹에 발작하고 경계해야한다.
메시지 수신이 지연되는 오류에 대해서 디버깅해봐도 실행이 안되었고 Netty의 쓰레드 덤프를 따서 분석해보았다.
"reactor-tcp-epoll-4" #34 daemon prio=5 os_prio=0 cpu=100.0ms elapsed=500.50s tid=0x00007f45700cd8d0 nid=0x45 runnable [0x00007f459a1f4000]
java.lang.Thread.State: RUNNABLE
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2073)
at my.package.KafkaConsumerService.processMessage(KafkaConsumerService.java:45)
at reactor.core.publisher.Mono.lambda$subscribe$0(Mono.java:4003)
at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:280)
at reactor.netty.channel.FluxReceive.lambda$subscribe$1(FluxReceive.java:170)
at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscriber.run(FluxSubscribeOnCallable.java:227)
at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
at java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.lang.Thread.run(Thread.java:834)
Locked ownable synchronizers:
- None
찾았다.
기존 로직에서 오류가 나는 부분도 아마 다른 마이크로 서비스로 요청을 보낸 뒤, 결과를 받아오는 동안 대기하는 부분이 블로킹 작업이라 그런 것으로 추측했었다.
예측했던 대로 블로킹 함수에 의해서 이벤트 루프가 쓰레드를 차단했던 것이었다.
요청을 전송한 후, 결과를 받기 위해 대기하는 과정(blocking)이 끝나고 나서야 이벤트 루프에 있던 receive() 가 동작하면서 지연된 것이다.
주 쓰레드. 여기서는 이벤트 루프(default reactive scheduler)에서 실행되면 쓰레드를 차단하면서 스트림의 성능에 영향을 주게 된다.
이제 원인을 분석했으니 해결하는 방법을 찾아야했다.
IO 작업에 특화된 Scheduler.boundedElastic()를 통해서 처리하려는데, Kafka 컨슈머 동작을 쓰레드풀에 넣어야할지 고민했다.
하지만 이 메시지 수신 과정은 ReactiveKafka에서 비동기적으로 동작하기에 블로킹 IO 작업이 없으므로 결국 이 대기하는 과정을 boundedElastic() 쓰레드풀에 넣어서 블로킹 IO를 먹어버리고 해결할 수 있었다.
트러블슈팅으로서 만족스러운 분석에 만족스러운 결과라고 소회한다.
운영 환경에서 메트릭 정보를 모니터링 및 덤프 분석 자동화 구축
사실 매번 쓰레드 덤프 뜨고 있는게 여간 불편한 일이 아니다. 그래서 계속 쓰레드 상태를 감시하면서 특정 조건을 만족하면 덤프를 수집하도록 자동화하면 어떨까? 해서 만들어봤다.
스프링 애플리케이션에서 메트릭 정보를 Prometheus에서 수집하기 위해 micrometer 라이브러리를 추가해야한다.
implementation 'io.micrometer:micrometer-registry-prometheus'
멀티모듈 혹은 MSA 환경이라면 공통 모듈에만 의존성을 넣어도 좋다.
다만 actuator 엔드포인트 설정은 서비스 단위로 해야한다. Prometheus에서 actuator의 엔드포인트를 노출해야 수집한다.
management:
endpoints:
web:
exposure:
include: "threaddump"
metrics:
export:
prometheus:
enabled: true
heapdump, prometheus, health, info 등 원하는 엔드포인트를 기입
Grafana에서 시각화할 메트릭 정보
그럼 어떤 메트릭 정보를 통해서 어떻게 블로킹 상태를 판단할 수 있을까?
이벤트 루프의 메트릭 지표와 응답 시간을 수집해서 블로킹 여부를 판단하려고 했다.
왜냐하면 비즈니스 상에서 블로킹이 발생했다고 생각했을때, 당연히 처리속도도 느려질거고 큐잉에 요청들이 대기하는 양이 증가할게 뻔하다.
당연히 Netty의 이벤트 루프에 있는 작업 대기 큐 지표나 Connection 처리량부터 아래에서 Alerts로 설정한 쓰레드 상태 지표(비율이나 유지 시간별)을 표시하고자 했다.
Reactor Netty의 이벤트 루프에서 대기중인 작업의 수 (Prometheus Query)
sum(rate(reactor_netty_eventloop_pendingTasks[1m]))
1min 동안 처리되지 않고 대기중인 작업의 초당 평균수(sum-rate)
JVM에서 WAITING 상태인 쓰레드의 초당 평균 수 (Prometheus Query)
sum by (state) (rate(jvm_threads_state{state=~"WAITING"}[1m]))
1min 동안 측정해서 쓰레드들이 얼마나 대기 상태에 자주 놓이는지 표시해서 병목을 진단할 수 있당
적은건 이 정도고, 현재 다른 JVM이나 Spring 애플리케이션 대시보드들 까보면서 이쁘게 표시하는 방법에 대해 연구하고 있다.
MSA 환경이라 마이크로 서비스들이 많아서~~~ 한번에 모든 서비스들의 지표를 흐름으로 봐야하는 메트릭에 어떤게 있고 각 서비스별로 봐야하는건 뭐가 있는지 구분하는 작업중이다
Prometheus의 AlertManager를 통한 덤프 수집 자동화
AlertManager
Prometheus의 별도 컴포넌트로 내장 기능이 아니라 독립적인 서비스로 동작한다.
Prometheus는 기본적으로 메트릭 수집과 쿼리하는 역할만 하기 때문에, 경고(Alerts)를 생성하고 알람을 전송하는 기능을 처리하는 목적이다.
알람(Notification) 전송 기능을 통해서 webhook 서버로 POST 요청을 전달할 수 있다.
여러 개의 Prometheus 서버가 하나의 AlertManager를 공유하도록 설계했기에 별도로 분리된 서비스로 동작한다.
prometheus나 alertManager에 대한 YAML 코드는 구태 적지 않겠다.
중요한건 어떤 메트릭 데이터를 집중적으로 감시하고, 덤프 수집을 위한 조건으로 임계치를 얼마나 설정할것인가? 이다.
alerts.yml
groups:
- name: ThreadBlockingAlerts
rules:
- alert: ThreadBlockingRatio
expr: (jvm_threads_state{state="blocked"} / jvm_threads_count) * 100 > 10
for: 30s
labels:
severity: warning
annotations:
summary: "Blocking Thread:entire ratio 10%"
description: "쓰레드중 10% 이상 블로킹 상태를 유지하고 있습니다."
- alert: ThreadBlockingLongDuration
expr: jvm_threads_state{state="blocked"} > 0
for: 1m
labels:
severity: critical
annotations:
summary: "Blocking Thread:duration 1min"
description: "쓰레드가 1분 이상 블로킹 상태를 유지하고 있습니다."
직접 구현한 Webhook API
private final String pid = ManagementFactory.getRuntimeMXBean().getName().split("@")[0];
public String generateHeapDump() {
try {
String dumpFile = "/tmp/heapdump_" + System.currentTimeMillis() + ".hprof";
ProcessBuilder pb = new ProcessBuilder("jcmd", pid, "GC.heap_dump", dumpFile);
pb.redirectErrorStream(true);
Process process = pb.start();
int exitCode = process.waitFor();
if (exitCode == 0) {
return dumpFile;
} else {
log.error("generateHeapDump error - exit code: " + exitCode);
return null;
}
} catch (Exception e) {
log.error("generateHeapDump error - " + e);
return null;
}
}
Spring Actuator에서 제공하는 엔드포인트
근데 사실 Spring Actuator에서 제공하는 여러 엔드포인트중에서 덤프 정보를 제공하는 경우가 있다.
특히 /actuator/heapdump나 /actuator/threaddump는 직접 설정해서 HTTP를 통해 접근할 수 있다.
AlertManager의 Webhook을 통해서 직접 덤프를 뜨는 API를 구현할 필요 없이 해당 actuator의 엔드포인트를 통해서 쓰레드덤프나 힙덤프를 딸수 있다.
global:
resolve_timeout: 5m
route:
receiver: "actuator-dump"
receivers:
- name: "actuator-dump"
webhook_configs:
- url: "http://feed:8080/actuator/threaddump"
send_resolved: false
- url: ...
5min 안에 해결안되면 터지는 시한폭탄이다.
직접 API로 구현하는 방식을 채택하면 덤프 파일 수집만 하는게 아니라 개발 환경으로 전송하는거까지 자동화될거 같은데 actuator가 편하긴 해서 고민이다.
어차피 모니터링하면 Grafana 통해서 Alerts 간거 알람 뜰거고, 해당 문제 상황이 벌어진 순간의 덤프는 이미 떴으니 나중에 직접 까도 되지 않을까라는 안일한 생각이다.
출처 및 인용
https://docs.oracle.com/en/java/javase/23/docs/api/java.base/java/lang/Thread.State.html