힙은 남았는데 서비스가 멈췄다

한 줄 요약

힙도 GC 도 멀쩡한데 서비스가 멈췄다면 스레드가 어딘가에서 기다리고 있는 것이다. 스레드 덤프(jcmd <pid> Thread.print)는 그 순간 모든 스레드가 어느 줄에서 무엇을 기다리는지 보여 주고, 잠금을 쥔 스레드와 그 앞에 줄 선 스레드를 짝지어 준다.

왜 이게 필요했나

이 코스 제목의 사건이다. 모니터링 화면에서 힙 40%, GC 정지 5ms, CPU 3%. 그런데 헬스체크가 타임아웃되고 사용자는 "무한 로딩" 을 본다. 서버는 살아 있다 — 포트도 열려 있고 프로세스도 있다. 재시작하면 돌아온다. 그리고 며칠 뒤 또 멈춘다. 원인은 요청 처리 스레드 200개가 전부 한 잠금 앞에 서 있었고, 그 잠금을 쥔 스레드는 응답 없는 외부 호출을 무한정 기다리고 있었다는 것이었다. 힙에는 아무 흔적이 없다. 스레드 덤프에는 전부 적혀 있다.

어떻게 동작하나

[jcmd 문서](https://docs.oracle.com/en/java/javase/21/docs/specs/man/jcmd.html)는 Thread.print 를 "모든 스레드를 스택 트레이스와 함께 찍는다(영향: 중간, 스레드 수에 비례)" 고 적고, -l 옵션이 java.util.concurrent 잠금 정보를 더한다고 적는다. jstack <pid> 도 같은 덤프를 준다. 덤프는 JVM 을 멈추지 않는다 — 스레드가 안전 지점에 도달할 때까지 잠깐 기다릴 뿐이다. 그래서 운영 중에도 찍을 수 있고, 찍어야 한다.

덤프 한 조각은 이렇게 생겼다(JDK 21, 실측).

"worker-2" #23 [213] prio=5 os_prio=0 cpu=11.78ms elapsed=1.45s tid=0x... nid=213 waiting for monitor entry   java.lang.Thread.State: BLOCKED (on object monitor)        at Stuck$Db.work(Stuck.java:41)        - waiting to lock <0x000000008bb16390> (a Stuck$Db)        at Stuck.lambda$main$3(Stuck.java:83)"worker-1" #22 [212] ... waiting on condition   java.lang.Thread.State: TIMED_WAITING (sleeping)        at java.lang.Thread.sleep(java.base@21/Native Method)        at Stuck$Db.hold(Stuck.java:56)        - locked <0x000000008bb16390> (a Stuck$Db)

읽는 순서는 정해져 있다. (1) 상태별로 센다 — RUNNABLE 은 일하는 중, BLOCKED 은 synchronized 모니터를 기다리는 중, WAITING/TIMED_WAITING 은 wait()·park()·sleep() 으로 기다리는 중. 요청 스레드 대부분이 BLOCKED 이면 잠금 경합이고, 대부분이 WAITING 이고 스택에 소켓 읽기가 있으면 외부 호출 대기다. (2) waiting to lock <주소> 의 주소를 모은다. 같은 주소가 수십 번 나오면 그것이 병목이다. (3) 그 주소를 - locked <주소> 로 검색하면 잠금을 쥔 스레드가 나온다. 그 스레드의 스택 맨 위가 원인이다 — 위 예시에서는 Thread.sleep, 현실에서는 대개 SocketInputStream.read 같은 외부 응답 대기다.

synchronized 가 아니라 java.util.concurrent 의 ReentrantLock·Semaphore 를 쓰면 상태는 BLOCKED 이 아니라 WAITING (parking) 이고 줄은 - parking to wait for <주소> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) 로 바뀐다. 잠금 종류에 따라 낱말이 다를 뿐 읽는 법은 같다. [ReentrantLock 문서](https://docs.oracle.com/en/java/javase/21/docs/api/java.base/java/util/concurrent/locks/ReentrantLock.html)의 tryLock(timeout, unit) 은 정해진 시간 안에 잠금을 못 잡으면 false 를 돌려주므로, synchronized 와 달리 기다림에 상한을 둘 수 있다. 무한정 기다리는 요청을 "잠시 뒤 다시 시도하세요(503)" 로 바꾸는 것이 이 모듈의 복구다.

교착(deadlock)은 특별 취급된다. 두 스레드가 서로의 잠금을 기다리면 JVM 이 덤프 끝에 Found one Java-level deadlock: 과 관련 스레드·잠금을 정리해 찍고 Found 1 deadlock. 으로 끝맺는다. 교착은 저절로 풀리지 않으므로 이 문장이 보이면 재시작 외에 답이 없고, 근본 해결은 잠금 순서를 통일하는 것이다.

덤프는 여러 장을 찍는다. 한 장은 순간이다. 몇 초 간격으로 세 장을 찍어 같은 스레드가 같은 자리에 계속 있으면 그것이 정말 멈춘 것이고, 매번 다른 자리면 그냥 바쁜 것이다. jcmd 출력은 첫 줄이 pid, 둘째 줄이 시각이므로 세 장의 시각 줄이 달라야 한다.

현장에서 만나는 모습

가장 흔한 실수는 재시작을 먼저 하는 것이다. 재시작하면 증거가 사라진다. 서비스가 멈춰 있는 그 순간에 덤프를 세 장 찍는 데 10초면 된다 — 그 뒤에 재시작해도 늦지 않다. 두 번째는 jcmd 를 다른 사용자로 돌리는 것이다. 문서가 못 박듯 JVM 을 띄운 사용자와 같은 사용자여야 붙는다. 세 번째는 잠금을 쥔 스레드를 안 찾고 BLOCKED 수만 세는 것이다. 줄 선 스레드는 피해자이지 원인이 아니다. 원인은 locked 를 쥔 한 스레드의 스택 맨 위에 있다.

다음 실습에서 할 것

/opt/lab/fixtures/jvm/Stuck.java — 처리 스레드 4개짜리 작은 HTTP 서비스 — 를 띄우고, 정상 덤프를 찍어 두고, /poison 으로 DB 잠금을 영원히 쥐게 한 뒤 나머지 요청이 BLOCKED 으로 쌓이는 덤프를 찍는다. 잠금을 쥔 스레드와 줄 선 스레드 수를 덤프에서 읽어 적고, Deadlock.java 로 교착 덤프를 보고, -Ddb.lock.timeout.ms= 로 tryLock 을 켜 다시 띄워 무한 대기가 503 으로 바뀌는 것을 확인하고, 마지막으로 2초 간격 덤프 세 장을 남긴다.