TT Lab
はじめる
学ぶ 学習パス コース

ヒープは余っていたのにサービスが止まった

スレッドダンプで止まった理由を探す

TT Labで続きを見る

目標

「ヒープは余っているのにサービスが止まった」状況を自分で再現し、スレッドダンプで原因を特定します。ロックを保持するスレッド、待機しているスレッド、デッドロック、そして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を返します。

ステップ

  1. /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を返す必要があります。
  2. jcmd -l > /root/jvm/threads/jcmd.txtでJVMの一覧を残してください。Stuckがserver.pidのpidで表示される必要があります。
  3. 正常状態のダンプをjcmd <pid> Thread.print > /root/jvm/threads/dump-idle.txtで残してください。Full thread dumpと"worker-1"が含まれている必要があります。
  4. 事件を起こします。curl -s -m 20 http://127.0.0.1:8085/poison &でロックを永遠に保持させたあと、curl -s -m 20 http://127.0.0.1:8085/ &をさらに3回送ってください(すべてバックグラウンド)。2秒後にjcmd <pid> Thread.print > /root/jvm/threads/dump-stuck.txtを実行してください。ダンプにwaiting to lockが3行以上とBLOCKEDが含まれている必要があり、/healthも応答しなくなります。
  5. dump-stuck.txtで- locked <주소> (a Stuck$Db)を保持しているスレッドの名前と、同じアドレスをwaiting to lockしているスレッドの数を読み取り、/root/jvm/threads/diagnosis.txtにholder=<스레드이름>とblocked=<n>の2行で書いてください(プレースホルダーはアドレスとスレッド名です)。採点ツールは、稼働中のプロセスのダンプと照合します。
  6. 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.が含まれている必要があります。
  7. 復旧です。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秒以内に返ってくる必要があります。
  8. サービスが起動したまま、/root/jvm/threads/dumps/dump-1.txt、dump-2.txt、dump-3.txtを2秒間隔で残してください。3つのファイルの時刻の行(pidの行の次の2行目)が、それぞれ異なっている必要があります。

参考

サービスを起動して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とメインクラスが1行ずつ並びます。

正常状態のダンプ

jcmd Thread.print > /root/jvm/threads/dump-idle.txtを残してください。Full thread dumpと"worker-1"が含まれている必要があります。

pidは$(cat /root/jvm/threads/server.pid)で取り出して使えます。正常時のダンプを先に残しておくと、事件のダンプと比較できます。

事件を起こしてダンプを取る

/poisonをバックグラウンドで送り、/をさらに3回バックグラウンドで送ってから、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/ &を3回です。処理スレッド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は$!です。2つのスレッドが互いのロックを待つので、プログラムは終了しません。採点が終わるまでそのままにしてください。

無期限の待機を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を返すので、サービスは遅くなるだけで止まりません。

ダンプは3枚

サービスが起動したまま、/root/jvm/threads/dumps/dump-1.txt、dump-2.txt、dump-3.txtを2秒間隔で残してください。3つのファイルの時刻の行(pidの行の次の2行目)が、それぞれ異なっている必要があります。

for i in 1 2 3; do jcmd $PID Thread.print > dumps/dump-$i.txt; sleep 2; done。同じスレッドが3枚とも同じ位置にいれば、本当に止まっています。