JVM ハング - スレッドダンプも出力できないケース
何を持ってハングアップしたかと判断するのかが曖昧ですが、一般的に "JVM がハングした?" と言う事象については kill -QUIT でスレッドダンプも出力しないケースか、もしくは、スレッドダンプは出力されるがリクエストに対しての応答が、いつまで待っても返ってこないという事象に別れると思います。
この投稿はスレッドダンプも出力しないパターンについての説明です。
スレッドダンプが出力される場合には Java ハングアップ? も参考にご覧ください。
safepoint
Java VM がスレッドダンプを出力する場合や、Full GC を行う際は、現在動作中の全ての Java Thread を safepoint と呼ばれる場所まで処理を進め、その後、目的の動作を行います。
Java VM がスレッドダンプも出力できずハングアップしたという事象については、この safepoint まで到達できない状態になってしまっているケースが多く、個々のスレッドのステータスを確認することが原因の特定に役立ちます。
Java スレッド毎の SafepointStatus を確認
手前味噌で恐縮ですが、JavaThread 毎のSafepointStatus を表示する gdb python スクリプトを作成してみました。
https://github.com/takimai39/gdb-java
ハングアップした JVM の core を見る
https://bugs.openjdk.java.net/browse/JDK-8064749 にあるコードを実行して、実際にハングアップする状況を作ってみます。
$ java -XX:-UseCompilerSafepoints Stuck
^Z
[1]+ 停止 java -XX:-UseCompilerSafepoints Stuck
$ kill -QUIT %1
[1]+ 停止 java -XX:-UseCompilerSafepoints Stuck
$ fg
java -XX:-UseCompilerSafepoints Stuck
CTRL+Z でサスペンドして、kill -QUIT を送って、また fg で戻ってますが、スレッドダンプは吐かれません。
core を取得して、safepoint のステータスを確認して見ます。
$ jps
29617 Stuck
29657 Jps
$ gcore 29617
...
Saved corefile core.29617
$ gdb /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/bin/java ./core.29617
...
(gdb) source sp.py
(gdb) safepoint
--------------------------------------------------------------------
Status: SafepointSynchronize::_synchronizing
waiting to block: 1
LWP Java Thread Name Status
--------------------------------------------------------------------
LWP 29618 DestroyJavaVM ThreadSafepointState::_at_safepoint
LWP 29630 Timer ThreadSafepointState::_at_safepoint
LWP 29629 Worker ThreadSafepointState::_running
LWP 29627 Service Thread ThreadSafepointState::_at_safepoint
LWP 29626 C1 CompilerThread1 ThreadSafepointState::_at_safepoint
LWP 29625 C2 CompilerThread0 ThreadSafepointState::_at_safepoint
LWP 29624 Signal Dispatcher ThreadSafepointState::_at_safepoint
LWP 29623 ? ThreadSafepointState::_at_safepoint
LWP 29622 Reference Handler ThreadSafepointState::_at_safepoint
(gdb)
SafepointSynchronize::_state が _synchronizing となっていますので、JVM は、全ての JavaThread を safepoint にいる状態にしようとしています。
しかし、waiting to block が 1 ですので、まだ1つのスレッドが safepoint に到達していません。
スレッドダンプなど、同様に safepoint まで処理を進める必要のある JVM の機能は当然この状況では動作できません。
このケースでは LWP 29629 のスレッドがハングアップした原因になっています。
OpenJDK unwinder でスタックを確認してみる
https://qiita.com/takimai39/items/a78b7a64a501d77efed8
この OpenJDK unwinder で、対象のスレッド(LWP 29629)のスタックを確認してみます。
(gdb) source dbg8.py
Installing openjdk unwinder
(gdb) source sp.py
(gdb) info thread
Id Target Id Frame
14 Thread 0x7f373cd10700 (LWP 29630) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
13 Thread 0x7f373ce11700 (LWP 29629) 0x00007f3741109660 in ?? ()
12 Thread 0x7f373cf12700 (LWP 29628) 0x00007f3756e55cf2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
11 Thread 0x7f373d013700 (LWP 29627) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
10 Thread 0x7f373d114700 (LWP 29626) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
9 Thread 0x7f373d215700 (LWP 29625) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
8 Thread 0x7f373d316700 (LWP 29624) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
7 Thread 0x7f373d417700 (LWP 29623) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
6 Thread 0x7f373d518700 (LWP 29622) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
5 Thread 0x7f373d619700 (LWP 29621) 0x00007f375653ae47 in sched_yield () from /lib64/libc.so.6
4 Thread 0x7f3740a02700 (LWP 29620) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
3 Thread 0x7f3740b03700 (LWP 29619) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
2 Thread 0x7f375726d700 (LWP 29618) 0x00007f3756e55945 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1 Thread 0x7f375726e740 (LWP 29617) 0x00007f3756e52f57 in pthread_join () from /lib64/libpthread.so.0
(gdb) thread 13
[Switching to thread 13 (Thread 0x7f373ce11700 (LWP 29629))]
#0 0x00007f3741109660 in ?? ()
(gdb) bt
#0 0x00007f3741109660 in [compiled offset=0x40] Stuck$Worker.run() () at Stuck.java:35
#1 0x00007f37410004e7 in StubRoutines (1) ()
#2 0x00007f3755b12b4a in JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*) (result=0x7f373ce10dc0, m=<optimized out>, args=<optimized out>, __the_thread__=0x7f37500ea800) at /usr/src/debug/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/openjdk/hotspot/src/share/vm/runtime/javaCalls.cpp:406
#3 0x00007f3755b0ffe4 in JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*) (__the_thread__=0x7f37500ea800, args=0x7f373ce10d30, method=<error reading variable: access outside bounds of object referenced via synthetic pointer>, result=0x7f373ce10dc0)
at /usr/src/debug/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/openjdk/hotspot/src/share/vm/runtime/javaCalls.cpp:307
#4 0x00007f3755b0ffe4 in JavaCalls::call_virtual(JavaValue*, KlassHandle, Symbol*, Symbol*, JavaCallArguments*, Thread*) (result=result@entry=0x7f373ce10dc0, spec_klass=..., name=<optimized out>, signature=<optimized out>, args=args@entry=0x7f373ce10d30, __the_thread__=__the_thread__@entry=0x7f37500ea800)
at /usr/src/debug/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/openjdk/hotspot/src/share/vm/runtime/javaCalls.cpp:204
#5 0x00007f3755b105f9 in JavaCalls::call_virtual(JavaValue*, Handle, KlassHandle, Symbol*, Symbol*, Thread*) (result=result@entry=0x7f373ce10dc0, receiver=..., spec_klass=..., name=<optimized out>, signature=<optimized out>, __the_thread__=__the_thread__@entry=0x7f37500ea800)
at /usr/src/debug/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/openjdk/hotspot/src/share/vm/runtime/javaCalls.cpp:210
#6 0x00007f3755b55301 in thread_entry(JavaThread*, Thread*) (thread=<optimized out>, __the_thread__=0x7f37500ea800)
at /usr/src/debug/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/openjdk/hotspot/src/share/vm/prims/jvm.cpp:2974
#7 0x00007f3755ef4c72 in JavaThread::thread_main_inner() (this=0x7f37500ea800)
at /usr/src/debug/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/openjdk/hotspot/src/share/vm/runtime/thread.cpp:1710
#8 0x00007f3755d4be12 in java_start(Thread*) (thread=0x7f37500ea800)
at /usr/src/debug/java-1.8.0-openjdk-1.8.0.131-11.b12.el7.x86_64/openjdk/hotspot/src/os/linux/vm/os_linux.cpp:790
#9 0x00007f3756e51e25 in start_thread () at /lib64/libpthread.so.0
#10 0x00007f375655634d in clone () at /lib64/libc.so.6
(gdb)
frame #0 は Stuck.java の35行目で、以下のように while () でのタイトループです。
compiled と表示があることから HotSpot によってネイティブコードにコンパイル済みです。
つまり "-XX:-UseCompilerSafepoints" の指定が効く対象の動作です。
(デフォルトでは +UseCompilerSafepoints ですので、通常この問題に遭遇することは無いでしょう。)
33 @Override
34 public void run() {
35 while (!isDone) { // <-- ここだ!
36 // burn
37 }
38 }
スレッドダンプも出力できない JVM ハングアップの場合には、このように JavaThread 毎の safepoint のステータスを確認することで原因となるスレッドや処理の内容を見つけることが可能です。