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

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

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

TT Labで続きを見る

一言でいうと

ヒープもGCも問題ないのにサービスが止まったなら、スレッドがどこかで待っています。スレッドダンプ(jcmd <pid> Thread.print)は、その瞬間にすべてのスレッドがどの行で何を待っているかを示し、ロックを保持しているスレッドと、その手前に並んでいるスレッドを対応づけてくれます。

なぜ必要なのか

このコースのタイトルが指す事件です。監視画面ではヒープ40%、GC停止5ms、CPU3%。それなのにヘルスチェックがタイムアウトし、ユーザーは「無限ローディング」を目にします。サーバーは生きています。ポートも開いていて、プロセスもあります。再起動すれば元に戻ります。そして数日後にまた止まります。原因は、リクエスト処理スレッド200個がすべて1つのロックの前に並んでいて、そのロックを保持するスレッドは、応答のない外部呼び出しを無期限に待ち続けていたことでした。ヒープには何の痕跡もありません。スレッドダンプにはすべて書かれています。

どう動くのか

jcmdのドキュメントは、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のドキュメントのtryLock(timeout, unit)は、決められた時間内にロックを取得できなければfalseを返すため、synchronizedと違って待ちに上限を設けられます。無期限に待つリクエストを「少し後でもう一度お試しください(503)」に変える、これがこのモジュールでの復旧です。

デッドロックは特別扱いされます。2つのスレッドが互いのロックを待つと、JVMがダンプの末尾にFound one Java-level deadlock:と関連するスレッド・ロックを整理して出力し、Found 1 deadlock.で締めくくります。デッドロックは自然には解消しないため、この文が見えたら再起動以外に手はなく、根本的な解決はロックの順序を統一することです。

ダンプは複数枚取ります。1枚は一瞬です。数秒間隔で3枚取り、同じスレッドが同じ位置にとどまっていれば本当に止まっていて、毎回違う位置なら単に忙しいだけです。jcmdの出力は1行目がpid、2行目が時刻なので、3枚の時刻の行が異なっている必要があります。

現場での姿

最もよくあるミスは、先に再起動してしまうことです。再起動すると証拠が消えます。サービスが止まっているその瞬間にダンプを3枚取るのは10秒で済みます。再起動はその後でも遅くありません。2つ目はjcmdを別のユーザーで実行することです。ドキュメントが明記しているとおり、JVMを起動したユーザーと同じユーザーでないと接続できません。3つ目は、ロックを保持するスレッドを探さずにBLOCKEDの数だけ数えることです。並んでいるスレッドは被害者であり、原因ではありません。原因はlockedを保持している1つのスレッドのスタックの最上部にあります。

次のラボですること

/opt/lab/fixtures/jvm/Stuck.java(処理スレッド4つの小さなHTTPサービス)を起動し、正常時のダンプを取っておき、/poisonでDBロックを永遠に保持させたうえで、残りのリクエストがBLOCKEDで溜まるダンプを取ります。ロックを保持するスレッドと待機スレッド数をダンプから読み取って記録し、Deadlock.javaでデッドロックのダンプを確認し、-Ddb.lock.timeout.ms=でtryLockを有効にして再起動し、無期限の待機が503に変わることを確認して、最後に2秒間隔のダンプを3枚残します。