스레드 덤프와 프로파일러로 장애 원인 찾기
예외의 원인을 잃지 않게 감싸는 법부터 스레드 상태, CPU 시간, 프로파일러까지, 증상에 맞는 도구로 가설을 확인하며 장애 원인을 좁히는 방법을 배웁니다.
장애가 나면 손에 잡히는 도구부터 켜고 싶어집니다. 하지만 프로파일러나 JFR이 쏟아 내는 데이터에는 언제나 눈에 띄는 항목이 있고, 무엇을 확인하려는지 정하지 않은 채 보면 그 항목을 원인으로 착각하기 쉽습니다. 그래서 먼저 증상을 구체적으로 적습니다. 언제부터, 어떤 요청이, 얼마나 느려졌는지, 원래는 어떻게 동작해야 하는지를 적고, 그 증상을 설명할 수 있는 가설을 세웁니다. 가설은 "CPU를 많이 쓰는 메서드가 있다", "락을 기다린다", "할당이 많아 GC가 잦다", "외부 I/O가 느리다"처럼 어떤 결과가 나오면 틀렸다고 말할 수 있는 형태여야 합니다.
도구마다 보여 주는 것이 다릅니다. 디버거는 한 번의 실행에서 특정 순간의 변수와 호출 상태를 보여 주고, 스레드 덤프는 어느 한 순간 스레드마다 무엇을 하고 누구를 기다리는지를 보여 줍니다. 프로파일러와 JFR은 일정 시간 동안 CPU와 할당이 어디에 쓰였는지의 분포를 보여 줍니다. 이 글에서는 진단의 출발점인 예외 정보부터 시작해 가설을 적는 방법, 스레드 상태 읽기, CPU 시간과 경과 시간의 차이를 차례로 보고, 마지막에 증상별로 도구를 고르는 기준을 정리합니다. GC 로그 글과 JFR 글의 도구도 함께 씁니다.
예외를 바꿔 던질 때 원인을 잃지 않기
진단에서 가장 먼저 보는 것은 대개 로그에 남은 예외입니다. 그런데 예외를 다른 예외로 바꿔 던지는 코드가 원래 예외를 버리면, 가장 중요한 정보가 로그에 남지 않습니다. 다음 코드는 조회 수 문자열을 정수로 바꾸다 실패하면 IllegalArgumentException을 새로 던지는데, 원래의 NumberFormatException은 넘기지 않습니다.
public final class DiscardedExceptionCauseBug {
static int parseViewCount(String value) {
try {
return Integer.parseInt(value);
} catch (NumberFormatException exception) {
throw new IllegalArgumentException("invalid view count: " + value);
}
}
public static void main(String[] args) {
try {
parseViewCount("forty");
} catch (IllegalArgumentException exception) {
System.out.println("message=" + exception.getMessage());
System.out.println("wrong-cause-null=" + (exception.getCause() == null));
}
}
}message=invalid view count: forty
wrong-cause-null=true메시지에 입력값을 넣었으니 충분해 보이지만, getCause()가 null이라는 것은 원래 예외가 통째로 사라졌다는 뜻입니다. Integer.parseInt가 어떤 메시지를 남기며 어느 위치에서 실패했는지가 어디에도 남지 않습니다. 이렇게 짧은 코드라면 짐작할 수 있지만, 실제 서비스에서 데이터베이스 드라이버나 라이브러리 깊숙한 곳에서 난 예외를 이렇게 버리면 로그만 보고는 원인을 찾을 길이 없어집니다.
고치는 방법은 바꿔 던질 때 원래 예외를 원인(cause)으로 넘기는 것입니다. 예외 클래스 계층 설계와 예외 변환에서 본 것처럼 대부분의 예외 클래스에는 메시지와 원인을 함께 받는 생성자가 있습니다. 다음 코드는 정수 변환과 양수 검사를 한 메서드에서 하고, 실패하면 어떤 작업이 실패했는지 알려 주는 메시지와 함께 원래 예외를 넘깁니다. main은 두 입력을 넣어 봅니다. "forty"는 정수 변환에서 실패하고, "0"은 변환에는 성공하지만 양수 검사에서 실패합니다.
public final class DiagnosticExceptionBoundary {
static int parseViewCount(String value) {
try {
int viewCount = Integer.parseInt(value);
if (viewCount <= 0) {
throw new IllegalArgumentException("not positive");
}
return viewCount;
} catch (RuntimeException exception) {
throw new IllegalArgumentException("parse board view count failed", exception);
}
}
public static void main(String[] args) {
try {
parseViewCount("forty");
} catch (IllegalArgumentException exception) {
exception.printStackTrace(System.out);
}
try {
parseViewCount("0");
} catch (IllegalArgumentException exception) {
System.out.println("0 -> " + exception.getMessage() + ", cause=" + exception.getCause());
}
}
}java.lang.IllegalArgumentException: parse board view count failed
at DiagnosticExceptionBoundary.parseViewCount(DiagnosticExceptionBoundary.java:10)
at DiagnosticExceptionBoundary.main(DiagnosticExceptionBoundary.java:16)
Caused by: java.lang.NumberFormatException: For input string: "forty"
at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
at java.base/java.lang.Integer.parseInt(Integer.java:662)
at java.base/java.lang.Integer.parseInt(Integer.java:778)
at DiagnosticExceptionBoundary.parseViewCount(DiagnosticExceptionBoundary.java:4)
... 1 more
0 -> parse board view count failed, cause=java.lang.IllegalArgumentException: not positiveprintStackTrace는 바깥 예외의 스택을 먼저 출력하고, Caused by: 줄부터 원래 예외의 메시지와 스택을 이어서 출력합니다. 이제 로그만 봐도 "forty"라는 입력이 Integer.parseInt 안에서 실패했고, 그 호출이 소스의 4번째 줄이라는 것까지 알 수 있습니다. 마지막의 ... 1 more는 원인 예외의 스택에서 나머지 한 프레임이 바깥 예외의 스택과 같아서 생략했다는 뜻입니다. 여기서는 main의 16번째 줄입니다. java.base/로 시작하는 JDK 내부 프레임의 줄 번호는 JDK 버전마다 다릅니다.
두 번째 입력에서는 바깥 메시지가 첫 번째와 똑같습니다. 어느 단계에서 실패했는지는 원인을 봐야 구별되며, "0"은 원인이 not positive이므로 양수 검사에서 걸렸다는 것을 알 수 있습니다. 양수 검사의 예외를 try 안에서 던졌기 때문에 같은 catch에 잡혀 한 번 더 감싸진 것입니다. 두 실패를 메시지만으로 구별하고 싶다면 검사를 try 밖으로 빼서 다른 메시지로 던지는 방법도 있습니다.
원인을 넘기는 것과 함께 로그에 무엇을 더 남길지도 정해 둡니다. 요청을 구별하는 식별자, 배포된 버전, 어떤 작업 중이었는지가 있으면 재현 경로를 훨씬 빨리 좁힐 수 있습니다. 반대로 예외 메시지에 입력값을 넣을 때는 비밀번호나 개인정보가 아닌지 확인하고, 그런 값이라면 가려서 남깁니다.
가설을 적어 두기
장애를 분석하는 메모에 "느리다"라고만 적으면 무엇을 확인해야 끝나는지가 정해지지 않습니다. 다음 코드는 가설 하나를 레코드로 표현해, 무엇을 적어야 하는지를 필드로 보여 줍니다.
import java.time.Instant;
import java.util.List;
public final class DiagnosticHypothesisModel {
private enum Status {
OPEN,
CONFIRMED,
REJECTED
}
private record Hypothesis(
String symptom,
String claim,
List<String> evidenceNeeded,
String falsifier,
Instant startedAt,
Status status) {}
public static void main(String[] args) {
Hypothesis lock =
new Hypothesis(
"save p99 > 2s",
"threads wait on PostRepository monitor",
List.of("three thread dumps", "JFR JavaMonitorEnter", "request timestamps"),
"no blocked threads and monitor wait below 10ms",
Instant.parse("2026-07-14T10:00:00Z"),
Status.OPEN);
System.out.println(lock);
}
}Hypothesis[symptom=save p99 > 2s, claim=threads wait on PostRepository monitor, evidenceNeeded=[three thread dumps, JFR JavaMonitorEnter, request timestamps], falsifier=no blocked threads and monitor wait below 10ms, startedAt=2026-07-14T10:00:00Z, status=OPEN]증상(symptom)은 측정한 숫자로 적습니다. save p99 > 2s는 저장 요청의 99번째 백분위 응답 시간, 즉 가장 느린 1%를 뺀 나머지가 모두 그 안에 들어오는 시간이 2초를 넘었다는 뜻입니다. 주장(claim)은 저장소 객체의 모니터를 기다린다는 것이고, 이를 확인할 자료(evidenceNeeded)로 스레드 덤프 세 번, JFR의 JavaMonitorEnter 이벤트, 요청 시각을 적었습니다. 가장 중요한 필드는 반증 조건(falsifier)입니다. BLOCKED 스레드가 없고 모니터 대기가 10밀리초 아래라면 이 가설은 틀렸다고, 자료를 보기 전에 미리 정해 두는 것입니다.
반증 조건을 먼저 적어 두면 자료를 보고 나서 해석을 끼워 맞추는 일을 막을 수 있습니다. 상태를 CONFIRMED로 바꾸기 전에는 같은 증상을 설명할 수 있는 다른 가설이 없는지, 빠뜨린 자료는 없는지도 확인합니다. 두 현상이 함께 나타났다고 해서 한쪽이 다른 쪽의 원인이라는 보장은 없으므로, 의심하는 원인만 바꾼 실험이나 재현으로 확인해야 결론을 낼 수 있습니다.
스레드의 상태를 코드로 읽기
락 대기 가설을 확인하려면 스레드가 지금 무엇을 하는지 봐야 합니다. ThreadMXBean을 쓰면 프로그램 안에서 다른 스레드의 상태와 스택을 읽을 수 있습니다. 다음 프로그램은 작업자 스레드 하나를 띄우고, 작업자가 시작했다는 신호를 받은 뒤 그 스레드의 정보를 읽습니다. 래치(CountDownLatch)를 두 개 씁니다. waiting은 작업자가 시작했다고 알리는 신호이고, release는 main이 정보를 다 읽은 뒤 작업자를 놓아 주는 신호입니다.
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.util.concurrent.CountDownLatch;
public final class ThreadStateEvidence {
public static void main(String[] args) throws Exception {
CountDownLatch waiting = new CountDownLatch(1);
CountDownLatch release = new CountDownLatch(1);
Thread worker =
Thread.ofPlatform()
.name("board-waiter")
.start(
() -> {
waiting.countDown();
try {
release.await();
} catch (InterruptedException exception) {
Thread.currentThread().interrupt();
}
});
waiting.await();
try {
ThreadMXBean threads = ManagementFactory.getThreadMXBean();
ThreadInfo info = threads.getThreadInfo(worker.threadId(), 8);
if (info == null) {
System.out.println("no thread info");
} else {
StackTraceElement[] stack = info.getStackTrace();
System.out.println("name=" + info.getThreadName());
System.out.println("state=" + info.getThreadState());
System.out.println("top=" + (stack.length > 0 ? stack[0] : "(empty stack)"));
}
} finally {
release.countDown();
}
worker.join();
}
}name=board-waiter
state=WAITING
[email protected]/jdk.internal.misc.Unsafe.park(Native Method)getThreadInfo(id, 8)은 그 스레드의 상태와 함께 스택을 위에서부터 최대 8프레임까지 담아 돌려줍니다. 작업자는 release.await()에서 기다리는 중이었고, 래치는 내부에서 스레드를 파킹(park)해 재우므로 스택의 맨 위가 Unsafe.park입니다. 상태가 BLOCKED가 아니라 WAITING인 것도 그 때문입니다. BLOCKED는 synchronized 모니터에 들어가려고 기다릴 때만 쓰이는 상태입니다. 두 상태의 차이와 덤프에서 기다리는 대상을 찾는 방법은 BLOCKED·WAITING 상태로 스레드 덤프 읽기에서 자세히 다뤘습니다.
이 예제는 정보를 읽는 부분을 try로 감싸고 release.countDown()을 finally에 두었습니다. 정보를 처리하다 예외가 나도 작업자를 놓아 주기 위해서입니다. 작업자는 데몬이 아닌 스레드라서, 놓아 주지 않으면 main이 끝나도 JVM이 종료되지 않습니다. getThreadInfo는 스레드가 이미 끝났거나 가상 스레드이면 null을 돌려주고, JVM에 스택 정보가 없으면 빈 배열을 담아 줍니다. 그래서 null을 확인하고 stack[0]을 읽기 전에 길이도 확인했습니다.
진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다
countDown 신호 뒤 release.await에 진입하기 전과 실제 대기 중의 두 가능한 snapshot을 구분합니다. 스케줄을 확정하지 않고 신호 수신이 WAITING을 보장하지 않는 이유를 단계로 드러낼 수 있습니다.
ThreadStateEvidence의 waiting 신호와 release.await 진입 사이의 가능한 실행 순서를 비교합니다.
진입 신호의 보장 범위와 별도의 대기 진입
진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다
waiting.countDown()은 release.await()보다 앞에 있습니다. main이 신호를 받아도 작업자가 실제 대기에 들어갔는지는 보장되지 않아, 상태를 한 번 읽고 WAITING으로 단정할 수 없습니다.
신호 전달과 뒤의 대기 진입 사이에는 순서 보장이 없다
작업자의 waiting.countDown은 release.await 앞이다. main의 waiting.await는 신호만 받으므로 main 조회와 작업자의 대기 진입 사이 순서는 정해지지 않는다. RUNNABLE과 WAITING은 가능한 순간 상태다.
상태별 상세 해설
가능한 스냅샷
countDown 뒤, release.await 진입 전
- 가능한 상태
- RUNNABLE 등을 관측할 수 있음
- waiting.await()가 알려 주는 것
- 진입 신호를 보낸 지점까지 진행
가능한 스냅샷
release.await에서 실제 대기 중
- 가능한 상태
- WAITING을 관측할 수 있음
- waiting.await()가 알려 주는 것
- release 대기 진입을 확인한 신호는 아님
두 행은 코드가 허용하는 상황이며 새 실행 관측이 아닙니다. getThreadInfo의 상태·스택은 그 호출 시점의 스냅샷입니다.
이 예의 조건
- 가능한 스냅샷이며 새 관측이 아닙니다. getThreadInfo는 호출 순간의 상태·스택을 제공합니다.
관계도의 보충 설명
| 구분 | 내용 |
|---|---|
| 설명 | |
| 전체 읽기 정보 | 진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다 진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다 ThreadStateEvidence의 waiting 신호와 release.await 진입 사이의 가능한 실행 순서를 비교합니다. 진입 신호의 보장 범위와 별도의 대기 진입 진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다 waiting.countDown()은 release.await()보다 앞에 있습니다. main이 신호를 받아도 작업자가 실제 대기에 들어갔는지는 보장되지 않아, 상태를 한 번 읽고 WAITING으로 단정할 수 없습니다. 가능한 스냅샷 countDown 뒤, release.await 진입 전 가능한 상태 RUNNABLE 등을 관측할 수 있음 waiting.await()가 알려 주는 것 진입 신호를 보낸 지점까지 진행 가능한 스냅샷 release.await에서 실제 대기 중 가능한 상태 WAITING을 관측할 수 있음 waiting.await()가 알려 주는 것 release 대기 진입을 확인한 신호는 아님 두 행은 코드가 허용하는 상황이며 새 실행 관측이 아닙니다. getThreadInfo의 상태·스택은 그 호출 시점의 스냅샷입니다. |
| 관찰·상황 | 값·보충 정보 | 변화·이유 |
|---|---|---|
| 진입 신호 waiting.countDown이 release.await보다 먼저입니다. |
|
|
| 대기 전 조회 countDown 뒤 await 전 스냅샷일 수 있습니다. |
|
|
| 실제 대기 조회 release.await에 진입한 순간은 WAITING일 수 있습니다. |
|
|
진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다
countDown 신호 뒤 release.await에 진입하기 전과 실제 대기 중의 두 가능한 snapshot을 구분합니다. 스케줄을 확정하지 않고 신호 수신이 WAITING을 보장하지 않는 이유를 단계로 드러낼 수 있습니다.
ThreadStateEvidence의 waiting 신호와 release.await 진입 사이의 가능한 실행 순서를 비교합니다.
진입 신호의 보장 범위와 별도의 대기 진입
진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다
waiting.countDown()은 release.await()보다 앞에 있습니다. main이 신호를 받아도 작업자가 실제 대기에 들어갔는지는 보장되지 않아, 상태를 한 번 읽고 WAITING으로 단정할 수 없습니다.
신호 전달과 뒤의 대기 진입 사이에는 순서 보장이 없다
작업자의 waiting.countDown은 release.await 앞이다. main의 waiting.await는 신호만 받으므로 main 조회와 작업자의 대기 진입 사이 순서는 정해지지 않는다. RUNNABLE과 WAITING은 가능한 순간 상태다.
상태별 상세 해설
가능한 스냅샷
countDown 뒤, release.await 진입 전
- 가능한 상태
- RUNNABLE 등을 관측할 수 있음
- waiting.await()가 알려 주는 것
- 진입 신호를 보낸 지점까지 진행
가능한 스냅샷
release.await에서 실제 대기 중
- 가능한 상태
- WAITING을 관측할 수 있음
- waiting.await()가 알려 주는 것
- release 대기 진입을 확인한 신호는 아님
두 행은 코드가 허용하는 상황이며 새 실행 관측이 아닙니다. getThreadInfo의 상태·스택은 그 호출 시점의 스냅샷입니다.
이 예의 조건
- 가능한 스냅샷이며 새 관측이 아닙니다. getThreadInfo는 호출 순간의 상태·스택을 제공합니다.
관계도의 보충 설명
| 구분 | 내용 |
|---|---|
| 설명 | |
| 전체 읽기 정보 | 진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다 진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다 ThreadStateEvidence의 waiting 신호와 release.await 진입 사이의 가능한 실행 순서를 비교합니다. 진입 신호의 보장 범위와 별도의 대기 진입 진입 신호를 받았어도 작업자가 이미 대기 중이라고 확정할 수 없다 waiting.countDown()은 release.await()보다 앞에 있습니다. main이 신호를 받아도 작업자가 실제 대기에 들어갔는지는 보장되지 않아, 상태를 한 번 읽고 WAITING으로 단정할 수 없습니다. 가능한 스냅샷 countDown 뒤, release.await 진입 전 가능한 상태 RUNNABLE 등을 관측할 수 있음 waiting.await()가 알려 주는 것 진입 신호를 보낸 지점까지 진행 가능한 스냅샷 release.await에서 실제 대기 중 가능한 상태 WAITING을 관측할 수 있음 waiting.await()가 알려 주는 것 release 대기 진입을 확인한 신호는 아님 두 행은 코드가 허용하는 상황이며 새 실행 관측이 아닙니다. getThreadInfo의 상태·스택은 그 호출 시점의 스냅샷입니다. |
| 관찰·상황 | 값·보충 정보 | 변화·이유 |
|---|---|---|
| 진입 신호 waiting.countDown이 release.await보다 먼저입니다. |
|
|
| 대기 전 조회 countDown 뒤 await 전 스냅샷일 수 있습니다. |
|
|
| 실제 대기 조회 release.await에 진입한 순간은 WAITING일 수 있습니다. |
|
|
열 번 모두 WAITING이 나왔지만, 이것이 정해진 답은 아닙니다. 단계 그림처럼 작업자의 waiting.countDown()은 release.await()보다 앞에 있습니다. main의 waiting.await()가 돌아왔다는 것은 작업자가 countDown()을 지났다는 뜻일 뿐, 이미 await()에 들어가 멈췄다는 뜻은 아닙니다. main이 정보를 읽은 순간 작업자가 아직 두 줄 사이를 지나는 중이었다면 RUNNABLE이 나올 수도 있습니다. 이 실행에서 매번 WAITING이 나온 것은 main이 ThreadMXBean을 얻는 동안 작업자가 충분히 앞서 나갔기 때문이고, 그런 타이밍은 어떤 규칙도 약속하지 않습니다. 스레드 상태는 읽은 순간의 사진일 뿐입니다.
ThreadMXBean이 다루는 것은 플랫폼 스레드뿐입니다. API 문서는 가상 스레드를 모니터링하지 않는다고 밝히고 있으며, 가상 스레드까지 포함한 덤프가 필요하면 jcmd <pid> Thread.dump_to_file -format=json <파일 경로>를 씁니다.
스레드 덤프는 여러 번 떠서 비교한다
운영 중인 서비스에서는 이 예제처럼 코드를 넣는 대신 jcmd <pid> Thread.print -l로 모든 스레드의 상태와 스택, 락 소유 정보를 한 번에 뜹니다. 그런데 한 번 뜬 덤프에 WAITING 스레드가 보인다고 문제가 있는 것은 아닙니다. 스레드 풀의 작업자는 할 일이 없으면 늘 WAITING 상태로 다음 작업을 기다리기 때문입니다. BLOCKED 스레드가 하나 보이는 것도 마침 그 순간 짧게 락을 기다렸을 수 있습니다.
그래서 덤프는 몇 초 간격으로 여러 번, 예를 들어 세 번 떠서 비교합니다. 같은 요청 스레드들이 매번 같은 락 주소를 기다리며 BLOCKED이고, 그 락을 쥔 스레드의 스택도 매번 같은 자리에 머물러 있다면 락 대기 가설이 힘을 얻습니다. 반대로 덤프마다 기다리는 스레드와 위치가 바뀐다면 락은 오가고 있는 것이므로 다른 가설을 봐야 합니다. JFR의 jdk.JavaMonitorEnter 이벤트는 임계값보다 오래 기다린 경우를 시간축 위에 모아 주므로, 덤프 사이의 빈 시간을 채우는 데 함께 씁니다.
CPU 시간과 경과 시간 나눠 보기
요청이 느릴 때 그 시간이 계산에 쓰였는지 기다리는 데 쓰였는지를 가르는 간단한 방법이 있습니다. 같은 구간에서 벽시계로 잰 경과 시간과 스레드가 실제로 CPU를 쓴 시간을 비교하는 것입니다. 다음 프로그램은 20밀리초를 잔 뒤 작은 계산을 하고, 두 시간을 함께 출력합니다.
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;
import java.time.Duration;
public final class CpuAndWallTimeEvidence {
public static void main(String[] args) throws Exception {
ThreadMXBean threads = ManagementFactory.getThreadMXBean();
if (!threads.isCurrentThreadCpuTimeSupported()) {
System.out.println("cpu-time-unsupported");
return;
}
if (!threads.isThreadCpuTimeEnabled()) {
threads.setThreadCpuTimeEnabled(true);
}
long wallStart = System.nanoTime();
long cpuStart = threads.getCurrentThreadCpuTime();
Thread.sleep(Duration.ofMillis(20));
long checksum = 0;
for (int value = 0; value < 100_000; value++) {
checksum += (long) value * value;
}
long cpu = threads.getCurrentThreadCpuTime() - cpuStart;
long wall = System.nanoTime() - wallStart;
System.out.println("wall-ns=" + wall);
System.out.println("cpu-ns=" + cpu);
System.out.println("checksum=" + checksum);
}
}wall-ns=22462200
cpu-ns=2282093
checksum=333328333350000경과 시간은 약 22.5밀리초인데 CPU 시간은 약 2.3밀리초입니다. 차이인 20밀리초는 Thread.sleep으로 잠든 시간입니다. 자는 동안 스레드는 CPU를 쓰지 않으므로 CPU 시간에는 계산한 부분만 잡혔습니다. 처음의 두 if는 이 JVM이 현재 스레드의 CPU 시간 측정을 지원하는지, 측정이 켜져 있는지를 확인하고 꺼져 있으면 켭니다. 시간 값은 머신과 실행마다 다르고, API 문서도 이 값이 나노초 단위로 표시될 뿐 나노초까지 정확하지는 않다고 밝힙니다.
실제 요청에서도 같은 스레드, 같은 구간에서 경과 시간이 CPU 시간보다 훨씬 길다면 I/O, sleep, 락, 운영체제의 스케줄링처럼 기다리는 쪽을 먼저 의심합니다. 두 시간이 비슷하다면 계산 자체가 오래 걸린 것입니다. 다만 차이만으로 원인을 특정할 수는 없으므로, 기다리는 쪽이라면 스레드 덤프와 JFR의 대기 이벤트로, 계산 쪽이라면 JFR의 실행 표본으로 어디인지 확인합니다.
증상에 맞는 도구 고르기
지금까지의 내용을 증상별로 묶으면 다음과 같습니다. 디버거에서 쓰는 조건부 중단점은 조건이 참일 때만 멈추는 중단점이고, 감시점(watchpoint)은 특정 필드를 읽거나 바꿀 때 멈추는 중단점입니다.
| 증상 | 먼저 확인할 것 | 쓸 도구 |
|---|---|---|
| 특정 입력에서 결과가 틀림 | 그 실행의 변수와 호출 흐름 | 디버거의 중단점, 조건부 중단점, 감시점 |
| 응답이 멈추거나 락을 기다림 | 누가 누구를 기다리는지 | 여러 번 뜬 스레드 덤프, JFR의 jdk.JavaMonitorEnter와 jdk.ThreadPark |
| CPU 사용률이 높음 | CPU가 어느 메서드에 쓰이는지 | JFR 실행 표본(jfr view hot-methods), async-profiler 같은 샘플링 프로파일러, JIT 컴파일 로그 |
| GC가 잦거나 메모리가 계속 늘어남 | 할당률 문제인지 생존 객체 집합 문제인지 | GC 로그, JFR 할당 표본, 클래스 히스토그램, 힙 덤프 |
| 느린데 CPU는 한가함 | 어디에서 기다리는지 | JFR의 소켓·파일 이벤트, 하위 서비스의 응답 시간, 연결 풀 대기열 |
NoSuchMethodError 같은 클래스 연결 오류 | 어떤 클래스가 어디서 로딩됐는지 | -Xlog:class+load, 모듈 구성, javap로 본 메서드 시그니처 |
마지막 줄의 클래스 로딩 로그는 클래스 로딩과 초기화에서, javap는 javap로 바이트코드 읽기에서 다뤘습니다. 실행 중인 서비스에서 자주 쓰는 명령을 모으면 다음과 같습니다.
jcmd -l
jcmd <pid> Thread.print -l
jcmd <pid> JFR.start name=incident settings=profile duration=60s filename=/tmp/incident.jfr
jfr summary /tmp/incident.jfr명령을 실행할 때는 실행한 명령 자체, 대상 pid와 그 프로세스의 시작 시각, 배포 버전, 기록의 시간대를 장애 분석 기록에 함께 적습니다. 나중에 다른 사람이 같은 결론에 이르는 과정을 다시 따라갈 수 있어야 하기 때문입니다. 진단 명령도 부하가 있고 민감한 데이터를 담을 수 있으므로, 운영 서버에서는 팀의 운영 절차에 따라 실행합니다.
플레임 그래프에서 가장 넓은 프레임이 원인인가요?
플레임 그래프(flame graph)는 실행 표본의 스택을 쌓아 그린 그림으로, 프레임의 폭이 그 메서드가 표본에 나온 비율입니다. 가장 넓은 프레임은 표본 시간을 가장 많이 차지했다는 뜻일 뿐, 그 자체로 문제라는 뜻은 아닙니다. 원래 가장 많은 일을 하도록 만들어진 메서드라면 넓은 것이 정상입니다.
원인으로 보려면 먼저 그래프를 그린 시간 범위가 요청이 느렸던 시간과 맞는지 확인합니다. 그다음 평소의 그래프와 비교해 그 프레임이 늘어났는지, 입력 크기나 호출 횟수가 바뀌었는지, 락이나 할당이 함께 늘었는지를 보며 가설을 확인합니다.
정리
- 예외를 바꿔 던질 때는 원래 예외를 원인으로 넘깁니다. 그래야 로그의
Caused by:에 처음 실패한 위치가 남습니다. - 가설에는 확인할 자료와 반증 조건을 자료를 보기 전에 적어 둡니다. 함께 나타난 현상을 원인으로 확정하려면 바꿔 보는 실험이나 재현이 필요합니다.
- 스레드 상태는 읽은 순간의 사진입니다. 한 번 본 WAITING이나 BLOCKED로 결론 내리지 말고, 덤프를 여러 번 떠서 같은 대기가 이어지는지 확인합니다.
- 경과 시간이 CPU 시간보다 훨씬 길면 기다리는 쪽을, 비슷하면 계산 쪽을 먼저 의심하고 각각 맞는 도구로 확인합니다.
- 증상에 맞는 도구를 고릅니다. 디버거는 한 실행의 상태를, 스레드 덤프는 대기 관계를, 프로파일러와 JFR은 시간에 따른 분포를 보여 줍니다.
연습 문제
CPU, LOCK, MEMORY, IO 네 가지 증상을 enum으로 만들고, 증상을 받아 처음 할 진단 작업을 문자열로 돌려주는 메서드를 작성하세요. 모든 증상을 빠짐없이 처리하는 switch 식을 써야 합니다.
코드를 쓰기 전에 증상마다 처음 확인할 자료를 먼저 적어 보세요. 그리고 다음 질문에도 답해 보세요. 요청이 느려서 스레드 덤프를 한 번 떴더니 요청 스레드가 WAITING이었습니다. 이것만으로 교착 상태라고 확정할 수 있을까요? 확정하려면 무엇을 더 봐야 할까요?
해설 보기
public final class DiagnosticFirstActionSolution {
private enum Symptom {
CPU,
LOCK,
MEMORY,
IO
}
static String firstAction(Symptom symptom) {
return switch (symptom) {
case CPU -> "JFR execution samples";
case LOCK -> "three thread dumps";
case MEMORY -> "GC log and class histogram";
case IO -> "socket events and downstream latency";
};
}
public static void main(String[] args) {
for (Symptom symptom : Symptom.values()) {
System.out.println(symptom + " -> " + firstAction(symptom));
}
}
}CPU -> JFR execution samples
LOCK -> three thread dumps
MEMORY -> GC log and class histogram
IO -> socket events and downstream latencyswitch 식에 default를 두지 않은 것이 핵심입니다. enum의 모든 상수를 case로 다루면 컴파일러가 빠진 것이 없는지 확인해 주므로, 나중에 Symptom에 새 증상을 추가하고 case를 빠뜨리면 컴파일 오류로 바로 알 수 있습니다. default를 두었다면 새 증상이 아무 경고 없이 default로 흘러갔을 것입니다. 이 메서드가 돌려주는 값은 조사를 시작할 곳일 뿐, 원인을 확정한 진단 결과가 아니라는 점도 기억해 둡니다.
질문의 답은 '확정할 수 없다'입니다. WAITING은 래치나 조건 변수, 스레드 풀의 작업 큐 등 무언가를 기다린다는 뜻일 뿐이고, 정상적인 대기도 늘 WAITING으로 보입니다. 교착 상태라고 말하려면 둘 이상의 스레드가 서로 상대가 쥔 락을 기다리는 관계가 원을 이뤄야 하고, 그 관계가 시간이 지나도 풀리지 않아야 합니다. 그래서 덤프를 몇 초 간격으로 여러 번 떠서 같은 스레드들이 같은 대상을 계속 기다리는지 확인하고, 기다리는 대상을 누가 쥐고 있는지 스택과 락 정보에서 찾습니다. ThreadMXBean.findDeadlockedThreads()는 락을 기다리는 관계가 원을 이루는 경우를 찾아 주지만, 이런 탐지에 잡히지 않는 멈춤도 있다는 것은 BLOCKED·WAITING 상태로 스레드 덤프 읽기에서 보았습니다.
이 장을 마치며
이 장에서는 이미 실행 중인 자바 프로그램의 안쪽을 JVM 도구로 들여다봤습니다. 클래스 로딩과 초기화에서 시작해 javap로 바이트코드 읽기, JIT와 벤치마크를 거쳐 GC 로그, JFR, 그리고 이 글의 스레드 덤프와 프로파일러까지 왔습니다. 도구는 저마다 다르지만 쓰는 순서는 같습니다. 증상을 숫자로 적고, 틀릴 수 있는 가설을 세우고, 그 가설을 확인하거나 버릴 자료를 맞는 도구로 모읍니다.