Fight the Future

Java言語とJVM、そしてJavaエコシステム全般にまつわること

Java 11でPrintStringTableStatisticsするとクラッシュする

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つあります。

どちらも「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を検索して、興味を持ったチケットを、同様に再現して学んでいきます!いつか、再現ではなく、自分がバグレポートをしたり、チケットを解決できるようになろうっ。