用线程转储找出停顿原因

한국어 원문으로 표시합니다.

목표

"힙은 남았는데 서비스가 멈췄다" 를 직접 만들고 스레드 덤프로 원인을 짚는다 — 잠금을 쥔 스레드, 줄 선 스레드, 교착, 그리고 tryLock 타임아웃으로 하는 복구.

왜 중요한가

프로세스도 포트도 살아 있는데 응답이 없을 때, 힙 그래프는 아무것도 말해 주지 않는다. 스레드 덤프만이 "누가 무엇을 기다리는가" 를 보여 준다. 재시작하면 증거가 사라지므로, 멈춘 순간에 덤프를 찍는 손이 먼저다. 재료 Stuck.java 는 127.0.0.1:8085 에서 처리 스레드 4개(worker-N)로 동작하는 HTTP 서비스다 — /health 는 DB 를 건드리지 않고, / 는 DB 잠금을 잡고 5ms 일하며, /poison 은 잠금을 잡은 채 영원히 잠든다. -Ddb.lock.timeout.ms=<ms> 를 주면 synchronized 대신 ReentrantLock.tryLock 을 써서 그 시간 안에 못 잡으면 503 을 돌려준다.

단계

/root/jvm/threads 에 Stuck.java 를 컴파일하고 nohup java -cp /root/jvm/threads Stuck > /root/jvm/threads/server.log 2>&1 & 로 띄운 뒤 pid 를 /root/jvm/threads/server.pid 에 적는다. curl -s http://127.0.0.1:8085/health 가 ok 를 돌려줘야 한다.
jcmd -l > /root/jvm/threads/jcmd.txt 로 JVM 목록을 남긴다. Stuck 이 server.pid 의 pid 로 보여야 한다.
정상 상태의 덤프를 jcmd <pid> Thread.print > /root/jvm/threads/dump-idle.txt 로 남긴다. Full thread dump 와 "worker-1" 이 있어야 한다.
사건을 만든다: curl -s -m 20 http://127.0.0.1:8085/poison & 로 잠금을 영원히 쥐게 한 뒤 curl -s -m 20 http://127.0.0.1:8085/ & 를 세 번 더 보낸다(전부 백그라운드). 2초 뒤 jcmd <pid> Thread.print > /root/jvm/threads/dump-stuck.txt. 덤프에 waiting to lock 이 3줄 이상, BLOCKED 이 있어야 하고 /health 도 응답하지 않게 된다.
dump-stuck.txt 에서 - locked <주소> (a Stuck$Db) 를 쥔 스레드 이름과 같은 주소를 waiting to lock 하는 스레드 수를 읽어 /root/jvm/threads/diagnosis.txt 에 holder=<스레드이름> 과 blocked=<n> 두 줄로 적는다. 채점기는 살아 있는 프로세스의 덤프와 대조한다.
Deadlock.java 를 컴파일해 java -cp /root/jvm/threads Deadlock > /root/jvm/threads/deadlock.log 2>&1 & 로 띄우고(그대로 둔다) 1초 뒤 jcmd <pid> Thread.print > /root/jvm/threads/dump-deadlock.txt. Found 1 deadlock. 이 있어야 한다.
복구: server.pid 의 프로세스를 kill 하고 -Ddb.lock.timeout.ms=500 을 붙여 다시 띄워 server.pid 를 갱신한다. 다시 /poison 을 백그라운드로 보낸 뒤 curl -s -m 5 -o /dev/null -w '%{http_code}' http://127.0.0.1:8085/ 의 결과를 /root/jvm/threads/after.txt 에 저장한다 — 이제 503 이 5초 안에 돌아와야 한다.
서비스가 떠 있는 채로 /root/jvm/threads/dumps/dump-1.txt, dump-2.txt, dump-3.txt 를 2초 간격으로 남긴다. 세 파일의 시각 줄(pid 줄 다음의 둘째 줄)이 서로 달라야 한다.

참고

잠금 주소 찾기: grep -n 'locked <.*Stuck\$Db' dump-stuck.txt 와 grep -c 'waiting to lock <주소>' dump-stuck.txt. 스레드 이름은 그 줄보다 위에서 가장 가까운 "..." 로 시작하는 줄이다.
같은 포트에 두 번 띄우면 두 번째는 바인딩 실패로 죽습니다. 7단계에서 먼저 kill 하세요.
흔한 실수: 덤프를 한 장만 찍는 것, 줄 선 스레드 수만 세고 잠금을 쥔 스레드를 안 찾는 것.

서비스를 띄우고 pid 를 남긴다

/root/jvm/threads 에 Stuck.java 를 컴파일하고 nohup 으로 띄운 뒤 pid 를 /root/jvm/threads/server.pid 에 적는다. /health 가 ok 를 돌려준다.

nohup java -cp /root/jvm/threads Stuck > server.log 2>&1 & 뒤에 echo $! > server.pid 입니다. cd … && nohup … & 처럼 && 로 묶으면 $! 가 서브셸의 pid 가 되니 cd 는 따로 하세요. 기동에 1초쯤 걸리니 curl 전에 잠깐 기다리세요.

JVM 목록

jcmd -l > /root/jvm/threads/jcmd.txt 를 남긴다. Stuck 이 server.pid 의 pid 로 보여야 한다.

jcmd -l 은 같은 사용자로 띄운 JVM 만 보여 줍니다. pid 와 메인 클래스가 한 줄씩입니다.

정상 상태의 덤프

jcmd Thread.print > /root/jvm/threads/dump-idle.txt 를 남긴다. Full thread dump 와 "worker-1" 이 있어야 한다.

pid 는 $(cat /root/jvm/threads/server.pid) 로 꺼내 쓰면 됩니다. 정상 덤프를 먼저 남겨야 사건 덤프와 비교할 수 있습니다.

사건을 만들고 덤프를 찍는다

/poison 을 백그라운드로 보내고 / 를 세 번 더 백그라운드로 보낸 뒤 2초 뒤 jcmd Thread.print > /root/jvm/threads/dump-stuck.txt. waiting to lock 이 3줄 이상, BLOCKED 이 있어야 한다.

curl -s -m 20 http://127.0.0.1:8085/poison & 다음 curl -s -m 20 http://127.0.0.1:8085/ & 를 세 번. 처리 스레드 4개가 전부 잠금 앞에 서면 /health 도 응답하지 않습니다 — 그것이 사건입니다.

잠금을 쥔 스레드와 줄 선 스레드

dump-stuck.txt 에서 locked <주소> (a Stuck$Db) 를 쥔 스레드 이름과 같은 주소를 waiting to lock 하는 스레드 수를 /root/jvm/threads/diagnosis.txt 에 holder=<이름> 과 blocked= 으로 적는다.

locked 줄의 주소(<0x...>)를 잡고, 그 줄보다 위에서 가장 가까운 큰따옴표로 시작하는 줄이 스레드 이름입니다. blocked 는 같은 주소의 waiting to lock 줄 수입니다.

교착은 JVM 이 이름을 불러 준다

Deadlock.java 를 컴파일해 백그라운드로 띄운 채(그대로 둔다) jcmd Thread.print > /root/jvm/threads/dump-deadlock.txt. Found 1 deadlock. 이 있어야 한다.

java -cp /root/jvm/threads Deadlock > deadlock.log 2>&1 & 뒤 pid 는 $! 입니다. 두 스레드가 서로의 잠금을 기다리므로 프로그램은 끝나지 않습니다 — 채점이 끝날 때까지 두세요.

무한 대기를 503 으로 바꾼다

server.pid 의 프로세스를 kill 하고 -Ddb.lock.timeout.ms=500 을 붙여 다시 띄워 server.pid 를 갱신한다. /poison 을 백그라운드로 보낸 뒤 curl -s -m 5 -o /dev/null -w '%{http_code}' http://127.0.0.1:8085/ 의 결과를 /root/jvm/threads/after.txt 에 저장한다(503).

시스템 프로퍼티는 클래스 이름 앞에 옵니다: java -Ddb.lock.timeout.ms=500 -cp ... Stuck. tryLock 이 500ms 안에 못 잡으면 503 을 돌려주므로 서비스는 느려질 뿐 멈추지 않습니다.

덤프는 세 장

서비스가 떠 있는 채로 /root/jvm/threads/dumps/dump-1.txt, dump-2.txt, dump-3.txt 를 2초 간격으로 남긴다. 세 파일의 시각 줄(pid 줄 다음의 둘째 줄)이 서로 달라야 한다.

for i in 1 2 3; do jcmd $PID Thread.print > dumps/dump-$i.txt; sleep 2; done. 같은 스레드가 세 장에서 같은 자리면 정말 멈춘 것입니다.