Java 11でのみ発生します。7、8、9、10では発生せず、現在開発中のJava 12では、fixされています。
$ java -version openjdk version "11.0.1" 2018-10-16 OpenJDK Runtime Environment 18.9 (build 11.0.1+13) OpenJDK 64-Bit Server VM 18.9 (build 11.0.1+13, mixed mode)
-XX:+PrintStringTableStatisticsを付けてjavaコマンドを実行するだけです。MacOSでもLinuxでも発生します。
MacOS
$ java -XX:+PrintStringTableStatistics -version openjdk version "11.0.1" 2018-10-16 OpenJDK Runtime Environment 18.9 (build 11.0.1+13) OpenJDK 64-Bit Server VM 18.9 (build 11.0.1+13, mixed mode) SymbolTable statistics: Number of buckets : 20011 = 160088 bytes, each 8 Number of entries : 14858 = 356592 bytes, each 24 Number of literals : 14858 = 548664 bytes, avg 36.927 Total footprint : = 1065344 bytes Average bucket size : 0.742 Variance of bucket size : 0.746 Std. dev. of bucket size: 0.863 Maximum bucket size : 8 # # A fatal error has been detected by the Java Runtime Environment: # # SIGSEGV (0xb) at pc=0x000000010b1da50e, pid=93059, tid=9731 # # JRE version: OpenJDK Runtime Environment (11.0.1+13) (build 11.0.1+13) # Java VM: OpenJDK 64-Bit Server VM (11.0.1+13, mixed mode, tiered, compressed oops, g1 gc, bsd-amd64) # Problematic frame: # V [libjvm.dylib+0x5da50e] _ZN7Monitor8try_lockEv+0x16 # # Core dump will be written. Default location: /cores/core.93059 # # An error report file with more information is saved as: # /Users/koichi.sakata/code/jdk11/hs_err_pid93059.log # # If you would like to submit a bug report, please visit: # http://bugreport.java.com/bugreport/crash.jsp # zsh: abort (core dumped) java -XX:+PrintStringTableStatistics -version
コアは/cores/にあります。コアが吐かれない場合は、ulimit -c unlimitedしましょう。
Linux (Ubuntu)
$ java -XX:+PrintStringTableStatistics -version openjdk version "11.0.1" 2018-10-16 OpenJDK Runtime Environment 18.9 (build 11.0.1+13) OpenJDK 64-Bit Server VM 18.9 (build 11.0.1+13, mixed mode) SymbolTable statistics: Number of buckets : 20011 = 160088 bytes, each 8 Number of entries : 14979 = 359496 bytes, each 24 Number of literals : 14979 = 551216 bytes, avg 36.799 Total footprint : = 1070800 bytes Average bucket size : 0.749 Variance of bucket size : 0.751 Std. dev. of bucket size: 0.867 Maximum bucket size : 8 # # A fatal error has been detected by the Java Runtime Environment: # # SIGSEGV (0xb) at pc=0x00007f0907052e2d, pid=2331, tid=2332 # # JRE version: OpenJDK Runtime Environment (11.0.1+13) (build 11.0.1+13) # Java VM: OpenJDK 64-Bit Server VM (11.0.1+13, mixed mode, tiered, compressed oops, g1 gc, linux-amd64) # Problematic frame: # V [libjvm.so+0xbe9e2d] Monitor::try_lock()+0x1d # # Core dump will be written. Default location: Core dumps may be processed with "/usr/share/apport/apport %p %s %c %P" (or dumping to /home/jyukutyo/core.2331) # # An error report file with more information is saved as: # /home/jyukutyo/hs_err_pid2331.log # # If you would like to submit a bug report, please visit: # http://bugreport.java.com/bugreport/crash.jsp
JBSのチケット
JDK Bug System (JBS) を検索したところ、すでにチケットがあり、12でfixするという記載があります。
[JDK-8211821] PrintStringTableStatistics crashes JVM - Java Bug System
自分の学びとして、修正について詳細に見てみます。修正は、このchangesetでした。
http://hg.openjdk.java.net/jdk/jdk/rev/8419d77e3635
内容はとんでもなくシンプルです。コメント修正やテストコードの追加を除くと、これだけです。
@@ -4291,6 +4291,9 @@ notify_vm_shutdown(); + // exit_globals() will delete tty + exit_globals(); + // We are after VM_Exit::set_vm_exited() so we can't call // thread->smr_delete() or we will block on the Threads_lock. // Deleting the shutdown thread here is safe because another @@ -4304,9 +4307,6 @@ } #endif - // exit_globals() will delete tty - exit_globals(); - LogConfiguration::finalize(); return true;
exit_globals()関数の呼び出しを動かしただけです。これは12に対する修正なので、自分でも、OpenJDK 11のソースに対して、同様の修正をして、ビルドし、実行してみます。タグjdk-11+13を使います。
まず、そのままビルドし、-XX:+PrintStringTableStatisticsを付けてjavaコマンドを実行すると、同様にクラッシュします。修正をしてビルドし、実行すると…
$ ./build/macosx-x86_64-normal-server-slowdebug/jdk/bin/java -XX:+PrintStringTableStatistics -version openjdk version "11-internal" 2018-09-25 OpenJDK Runtime Environment (slowdebug build 11-internal+0-adhoc.koichisakata.jdk11) OpenJDK 64-Bit Server VM (slowdebug build 11-internal+0-adhoc.koichisakata.jdk11, mixed mode) SymbolTable statistics: Number of buckets : 20011 = 320176 bytes, each 16 Number of entries : 22799 = 729568 bytes, each 32 Number of literals : 22799 = 909384 bytes, avg 39.887 Total footprint : = 1959128 bytes Average bucket size : 1.139 Variance of bucket size : 1.155 Std. dev. of bucket size: 1.075 Maximum bucket size : 8 StringTable statistics: Number of buckets : 65536 = 524288 bytes, each 8 Number of entries : 963 = 15408 bytes, each 16 Number of literals : 963 = 57584 bytes, avg 59.796 Total footprsize_t : = 597280 bytes Average bucket size : 0.015 Variance of bucket size : 0.015 Std. dev. of bucket size: 0.122 Maximum bucket size : 2
見事、クラッシュせずに、StringTableの統計情報が出ました！
なぜ直るのか
exit_globals()関数の呼び出しを動かすと、修正できるのでしょうか？JBSのチケットに、こういうコメントがありました。
In JDK-9, SymbolTable::dump() did not have a ResourceMark nor did it call Thread::current(). So the symbol table dump could be done after deleting the thread. The thread gets deleted by the "delete thread;" statement in Threads::destroy_vm(). This happens before the call to exit_globals(). Function exit_globals() calls SymbolTable::dump(), which now calls Thread::current(). This change was done in JDK-8195100. Perhaps destroy_vm() can call exit_globals() before deleting the thread.
exit_globals()関数内ではSymbolTable::dump()関数を呼び出している。JDK 9では、SymbolTable::dump()関数で、ResourceMarkもThread::current()も呼んでいなかった。11では、SymbolTable::dump()がThread::current()を呼び出している。しかし、exit_globals()を呼び出す前に、すでにスレッドは削除されているので、Thread::current()の呼び出しがクラッシュする。という流れのようです。
修正前のソースを見ます。
notify_vm_shutdown(); // We are after VM_Exit::set_vm_exited() so we can't call // thread->smr_delete() or we will block on the Threads_lock. // Deleting the shutdown thread here is safe because another // JavaThread cannot have an active ThreadsListHandle for // this JavaThread. delete thread; #if INCLUDE_JVMCI if (JVMCICounterSize > 0) { FREE_C_HEAP_ARRAY(jlong, JavaThread::_jvmci_old_thread_counters); } #endif // exit_globals() will delete tty exit_globals(); LogConfiguration::finalize(); return true;
たしかに、delete thread;が先にあって、その後exit_globals()関数を呼び出しています。前述のdiffでは、exit_globals()関数をdelete thread;より前に動かしました。コメント内容と合っています。
exit_globals()関数を見ます。
void exit_globals() { static bool destructorsCalled = false; if (!destructorsCalled) { destructorsCalled = true; perfMemory_exit(); if (PrintSafepointStatistics) { // Print the collected safepoint statistics. SafepointSynchronize::print_stat_on_exit(); } if (PrintStringTableStatistics) { SymbolTable::dump(tty); StringTable::dump(tty); } ostream_exit(); } }
たしかに、SymbolTable::dump(tty)があります。SymbolTable::dump関数を見ます。
void SymbolTable::dump(outputStream* st, bool verbose) { if (!verbose) { the_table()->print_table_statistics(st, "SymbolTable"); } else { st->print_cr("VERSION: 1.0"); for (int i = 0; i < the_table()->table_size(); ++i) { HashtableEntry<Symbol*, mtSymbol>* p = the_table()->bucket(i); for ( ; p != NULL; p = p->next()) { Symbol* s = (Symbol*)(p->literal()); const char* utf8_string = (const char*)s->bytes(); int utf8_length = s->utf8_length(); st->print("%d %d: ", utf8_length, s->refcount()); HashtableTextDump::put_utf8(st, utf8_string, utf8_length); st->cr(); } } } }
うーん、Thread::current()の呼び出しがありませんね。そもそも、javaコマンドの実行では、SymbolTable statisticsはきちんと出力されており、StringTable statisticsの出力でクラッシュしていました。なので、SymbolTable::dump呼び出しの次の行で呼び出している、StringTable::dump関数を見ます。
void StringTable::dump(outputStream* st, bool verbose) { if (!verbose) { the_table()->print_table_statistics(st, "StringTable"); } else { Thread* thr = Thread::current(); ResourceMark rm(thr); st->print_cr("VERSION: 1.1"); PrintString ps(thr, st); if (!the_table()->_local_table->try_scan(thr, ps)) { st->print_cr("dump unavailable at this moment"); } } }
Thread::current()の呼び出しがありました！ここが原因とわかりました。
hs_err
今回は学習のため、上記のような手順を踏みましたが、hs_err_pid のログファイルにもこうあります。
--------------- T H R E A D --------------- Current thread is native thread Stack: [0x000000010515a000,0x000000010525a000], sp=0x0000000105259650, free space=1021k Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code) V [libjvm.dylib+0x1169350] VMError::report_and_die(int, char const*, char const*, __va_list_tag*, Thread*, unsigned char*, void*, void*, char const*, int, unsigned long)+0x7b0 V [libjvm.dylib+0x1169c03] VMError::report_and_die(Thread*, void*, char const*, int, char const*, char const*, __va_list_tag*)+0x83 V [libjvm.dylib+0x6d02f0] report_vm_error(char const*, int, char const*, char const*, ...)+0x1d0 V [libjvm.dylib+0x39bd] Thread::current()+0x5d V [libjvm.dylib+0x1016d59] StringTable::print_table_statistics(outputStream*, char const*)+0x39 V [libjvm.dylib+0x10177d6] StringTable::dump(outputStream*, bool)+0x36 V [libjvm.dylib+0x982c34] exit_globals()+0x64 V [libjvm.dylib+0x10d7e37] Threads::destroy_vm()+0x1d7 V [libjvm.dylib+0xab33b9] jni_DestroyJavaVM_inner(JavaVM_*)+0x169 V [libjvm.dylib+0xab323c] jni_DestroyJavaVM+0x1c C [java+0x607d] JavaMain+0x52d C [libsystem_pthread.dylib+0x3661] _pthread_body+0x154 C [libsystem_pthread.dylib+0x350d] _pthread_body+0x0 C [libsystem_pthread.dylib+0x2bf9] thread_start+0xd
V [libjvm.dylib+0x39bd] Thread::current()+0x5dと出ており、ここで落ちているとわかります。
どの修正でこのバグが入ったのか
このクラッシュが発生しない、Java 10 (jdk-10+10) では、StringTable::dumpはこのような実装でした (47103:a993ec29ec75)。
void StringTable::dump(outputStream* st, bool verbose) { if (!verbose) { the_table()->dump_table(st, "StringTable"); } else { Thread* THREAD = Thread::current(); st->print_cr("VERSION: 1.1"); for (int i = 0; i < the_table()->table_size(); ++i) { HashtableEntry<oop, mtSymbol>* p = the_table()->bucket(i); for ( ; p != NULL; p = p->next()) { oop s = p->literal(); typeArrayOop value = java_lang_String::value(s); int length = java_lang_String::length(s); bool is_latin1 = java_lang_String::is_latin1(s); if (length <= 0) { st->print("%d: ", length); } else { ResourceMark rm(THREAD); int utf8_length = length; char* utf8_string; if (!is_latin1) { jchar* chars = value->char_at_addr(0); utf8_string = UNICODE::as_utf8(chars, utf8_length); } else { jbyte* bytes = value->byte_at_addr(0); utf8_string = UNICODE::as_utf8(bytes, utf8_length); } st->print("%d: ", utf8_length); HashtableTextDump::put_utf8(st, utf8_string, utf8_length); } st->cr(); } } } }
これが、changeset50445:bd6b78feb6a3で、現在の実装にがらっと変わっています。このリビジョンに戻して、ビルドし、同様に実行してみました。
$ ./build/macosx-x86_64-normal-server-slowdebug/jdk/bin/java -XX:+PrintStringTableStatistics -version openjdk version "11-internal" 2018-09-25 OpenJDK Runtime Environment (slowdebug build 11-internal+0-adhoc.koichisakata.jdk11) OpenJDK 64-Bit Server VM (slowdebug build 11-internal+0-adhoc.koichisakata.jdk11, mixed mode) SymbolTable statistics: Number of buckets : 20011 = 320176 bytes, each 16 Number of entries : 22698 = 726336 bytes, each 32 Number of literals : 22698 = 906064 bytes, avg 39.918 Total footprint : = 1952576 bytes Average bucket size : 1.134 Variance of bucket size : 1.147 Std. dev. of bucket size: 1.071 Maximum bucket size : 8 # To suppress the following error report, specify this argument # after -XX: or in .hotspotrc: SuppressErrorAt=/thread.hpp:737 # # A fatal error has been detected by the Java Runtime Environment: # # Internal Error (/Users/koichi.sakata/code/jdk11/src/hotspot/share/runtime/thread.hpp:737), pid=81690, tid=8707 # assert(current != __null) failed: Thread::current() called on detached thread # # JRE version: OpenJDK Runtime Environment (11.0) (slowdebug build 11-internal+0-adhoc.koichisakata.jdk11) # Java VM: OpenJDK 64-Bit Server VM (slowdebug 11-internal+0-adhoc.koichisakata.jdk11, mixed mode, tiered, compressed oops, g1 gc, bsd-amd64) # Core dump will be written. Default location: /cores/core.81690 # # An error report file with more information is saved as: # /Users/koichi.sakata/code/jdk11/hs_err_pid81690.log # # If you would like to submit a bug report, please visit: # http://bugreport.java.com/bugreport/crash.jsp # Current thread is 8707 Dumping core ...
クラッシュしました。この変更がクラッシュの原因であることは、間違いなさそうです。
変更内容
changeset50445:bd6b78feb6a3のサマリには、「8195097: Make it possible to process StringTable outside safepoint」とあります。8195097という番号が、JBSのチケット番号ですので、JBSを確認します。
[JDK-8195097] Make it possible to process StringTable outside safepoint - Java Bug System
「The StringTable should be able to unlink strings outside a safepoint. 」と書かれていました。セーフポイントの範疇外となるStringをunlinkできるようにする変更のようです。
このチケットには、サブタスクが2つあります。
- [JDK-8195098] Low latency hashtable for read-mostly scenarios - Java Bug System
- [JDK-8195099] Concurrent safe-memory-reclamation mechanism - Java Bug System
どちらも「low latency data-structure」にするための変更、と書かれています。src/hotspot/share/utilities/concurrentHashTable.hppが新規に作成されており、これがそのデータ構造のようです。src/hotspot/share/classfile/stringTable.hppで、このconcurrentHashTableを使うように変更しています。
+typedef ConcurrentHashTable<WeakHandle<vm_string_table_data>, + StringTableConfig, mtSymbol> StringTableHash; ... +class StringTableConfig : public StringTableHash::BaseConfig {
この辺りで、一段落のようです。
コア解析
さて、やり残していることがあります。コアを吐いたのに、見ていません。gdbで見てみます。Linux (Ubuntu) です。MacOSよりやりやすかったので。
$ gdb jdk-11.0.1/bin/java ./core GNU gdb (Ubuntu 7.7-0ubuntu3) 7.7 Copyright (C) 2014 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-linux-gnu". Type "show configuration" for configuration details. For bug reporting instructions, please see: <http://www.gnu.org/software/gdb/bugs/>. Find the GDB manual and other documentation resources online at: <http://www.gnu.org/software/gdb/documentation/>. For help, type "help". Type "apropos word" to search for commands related to "word"... Reading symbols from jdk-11.0.1/bin/java...(no debugging symbols found)...done. ... [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1". Core was generated by `java -XX:+PrintStringTableStatistics -version'. Program terminated with signal SIGABRT, Aborted. #0 0x00007fac31ed0f79 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 56 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory. (gdb)
バックトレースを見ます。
(gdb) bt #0 0x00007fac31ed0f79 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #1 0x00007fac31ed4388 in __GI_abort () at abort.c:89 #2 0x00007fac315eb219 in os::abort(bool, void*, void const*) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #3 0x00007fac318123aa in VMError::report_and_die(int, char const*, char const*, __va_list_tag*, Thread*, unsigned char*, void*, void*, char const*, int, unsigned long) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #4 0x00007fac31812c2b in VMError::report_and_die(Thread*, unsigned int, unsigned char*, void*, void*, char const*, ...) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #5 0x00007fac31812c5e in VMError::report_and_die(Thread*, unsigned int, unsigned char*, void*, void*) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #6 0x00007fac31813c6d in crash_handler(int, siginfo*, void*) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #7 <signal handler called> #8 0x00007fac317b35b7 in ThreadsListHandle::ThreadsListHandle(Thread*) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #9 0x00007fac315e343f in os::print_location(outputStream*, long, bool) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #10 0x00007fac315f669f in os::print_register_info(outputStream*, void const*) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #11 0x00007fac318115c8 in VMError::report(outputStream*, bool) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #12 0x00007fac31812157 in VMError::report_and_die(int, char const*, char const*, __va_list_tag*, Thread*, unsigned char*, void*, void*, char const*, int, unsigned long) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #13 0x00007fac31812c2b in VMError::report_and_die(Thread*, unsigned int, unsigned char*, void*, void*, char const*, ...) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #14 0x00007fac31812c5e in VMError::report_and_die(Thread*, unsigned int, unsigned char*, void*, void*) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #15 0x00007fac315f5ac0 in JVM_handle_linux_signal () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #16 0x00007fac315e9cb8 in signalHandler(int, siginfo*, void*) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #17 <signal handler called> #18 0x00007fac315a4e2d in Monitor::try_lock() () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #19 0x00007fac3170d90e in StringTable::dump(outputStream*, bool) () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #20 0x00007fac312399dc in exit_globals() () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #21 0x00007fac317aeb8d in Threads::destroy_vm() () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #22 0x00007fac312de318 in jni_DestroyJavaVM () from /home/jyukutyo/jdk-11.0.1/lib/server/libjvm.so #23 0x00007fac32468d24 in JavaMain () from /home/jyukutyo/jdk-11.0.1/bin/../lib/jli/libjli.so #24 0x00007fac3267d182 in start_thread (arg=0x7fac32cb2700) at pthread_create.c:312 #25 0x00007fac31f9530d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 (gdb)
今回はデバッグシンボルがないので、こんなくらいでしょうか。
まとめ
たまたまクラッシュに遭遇したことで、JBSの修正済みチケットを自分で再現して、OpenJDKを学ぶという新たな手法を自分的に発見でき、うれしく思います。今後は、バグに出会わなくても、JBSを検索して、興味を持ったチケットを、同様に再現して学んでいきます！いつか、再現ではなく、自分がバグレポートをしたり、チケットを解決できるようになろうっ。
