原文はこちら。
The original article was written by Joakim Nordström (Principal Member of Technical Staff, Oracle).
https://inside.java/2021/02/12/deciphering-the-stacktrace/
今回の記事では、Java仮想マシンがクラッシュしたときに生成されるクラッシュログ（hs_errファイル）を見てみましょう。何が問題なのか、どのコンポーネントに責任があるのかを見つけるためには、クラッシュログファイルの解釈方法を理解することが重要です。ここでは、スタックトレースを構成するフレームの理解に焦点を当てます。
Divide and crash
この記事では、以下のようなJavaプログラムの例を作成しました。
- ループの中で、デクリメントされる分母で定数を割っていく
- 分母は最終的にゼロになるため、ゼロ除算が発生する
このコードでは、より興味深いスタックトレースを得るためにシンプルかつストレートなロジックにはなっていません。このコードは2つのJavaクラス（DumpsterとDivider）で構成されており、前者はループで反復するたびにDivider.do_div()を呼び出します。Dividerは割り算を行うネイティブJNIライブラリlibdump.soを呼出します。
以下は省略したバージョンです。ビルドや実行方法を含む完全なコードは、原文著者のGitHubリポジトリにあります。
inside-java-dumpster
https://github.com/jaokim/inside-java-dumpster
Java クラス
class Dumpster {
void main(...) {
do_loops(no_of_loops);
}
void do_loops(int no_of_loops) {
for(int i = no_of_loops; i >= 0; i--) {
new Divider().do_div(i);
}
}
}
class Divider {
void do_div(int denominator) {
native_div_call(denominator);
}
native void native_div_call(int denominator);
}
ネイティブライブラリ（libdump）
// This is the native method native_div_call
JNIEXPORT void JNICALL Java_jaokim_dumpster_Dumpster_native_1div_1call
(jint denominator) {
int numerator = 9;
// call C standard library div
div(numerator, denominator);
}
このプログラムを数回ループさせると、クラッシュします。
duke@cafedead:/work# java Dumpster 10
#
# A fatal error has been detected by the Java Runtime Environment:
#
# SIGFPE (0x8) at pc=0x00007fc0b124a5a3, pid=6208, tid=6209
#
# JRE version: OpenJDK Runtime Environment (15.0.1+9)
# Java VM: OpenJDK 64-Bit Server VM (15.0.1+9-18, mixed mode, aot, sharing, tiered, …
-> # Problematic frame:
-> # C [libc.so.6+0x3a5a3] div+0x3
#
# If you would like to submit a bug report, please visit:
# https://bugreport.java.com/bugreport/crash.jsp
-> # The crash happened outside the Java Virtual Machine in native code.
-> # See problematic frame for where to report the bug.
問題のあるフレームの他に、何が起こったのか明確な文章での指示があります。
- “The crash happened outside the Java Virtual Machine in native code “
- “See problematic frame for where to report the bug”
The crash happened outside the Java Virtual Machine in native code.
（JVM外のネイティブコードでクラッシュが発生しました）
生成されたhs_errファイル、特にスタックトレースを詳しく調べてみると、各フレームの最初の文字で現在のステップのコードのタイプがわかります。hs_errファイルの中には、その意味を示すヒントが直接書かれています。
J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code
スタックトレースを最初からたどっていきましょう。問題のあるフレームで、有用なヒントの意味を探っていきます。
Stack: [0x00007f2b92572000,0x00007f2b92673000], sp=0x00007f2b92671788, free space=1021k
Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)
-> C [libc.so.6+0x3a5a3] div+0x3
C [libdump.so+0x1162] Java_jaokim_dumpster_Divider_native_1div_1call+0x29
j jaokim.dumpster.Divider.native_div_call(I)V+0
j jaokim.dumpster.Divider.do_div(I)V+2
j jaokim.dumpster.Dumpster.do_loops(I)V+14
j jaokim.dumpster.Dumpster.doTestcase(Ljava/lang/Integer;)V+5
j jaokim.dumpster.Dumpster.main([Ljava/lang/String;)V+58
v ~StubRoutines::call_stub
V [libjvm.so+0x773a29] JavaCalls::call_helper(...)+0x299
V [libjvm.so+0x804747] jni_invoke_static(...) [clone .isra.0] [clone .constprop.1]+0x357
V [libjvm.so+0x80733f] jni_CallStaticVoidMethod+0x12f
C [libjli.so+0x4627] JavaMain+0xd17
C [libjli.so+0x7fc9] ThreadJavaMain+0x9
C=native code
先頭のフレームが問題のあるフレームなのですが、これにはCという接頭辞が付いています。このCはネイティブコードを意味しており、C標準ライブラリであるlib.soで関数div実行中にクラッシュしたことがわかります。次のフレームもネイティブコードで、libdump.soという独自のライブラリのJava_jaokim_dumpster_Dumpster_native_1div_1callという不格好な名前の関数を実行しています。
j=interpreted
その前に、DividerとDumpsterというJavaクラスが実行されています。両者ともインタプリタモードで実行しており、そのことを示す小文字のjが接頭辞としてついています。
Vv=VM code
作成したJavaクラスとメソッドは内部ネイティブコードの数個のフレームの後呼び出されています。~StubRoutines::call_stubには小文字vが接頭辞として付いており、libjvmフレームには大文字Vが接頭辞として付いています。小文字のvはVMが生成したコード、大文字のVはlibjvmライブラリ内部のコードを表しています（この区別は別途文章にする価値がありますが、現時点ではvとVがVM内部のネイティブコードであることを理解すれば十分です）。
プログラム実行は2個の最後のフレームで開始しています。Cでわかるように、これはJavaランチャーライブラリlibjli由来のネイティブコードです。その名の通り、このライブラリはJVMを起動するもので、javaコマンドがJavaプログラムを起動するために使います。Javaに特化していますが、JVM/HotSpotのメモリ空間では実行されないため、VM内部コードとしてはカウントされません。
J=compiled Java code
「コンパイル済みJavaコード」を示す大文字Jのフレームタイプを見ていきましょう。同じ例を使って、ループの数を1000回に増やしただけで、少し異なるスタックトレースが得られます。
duke@cafedead:/work# java Dumpster 1000
#
# A fatal error has been detected by the Java Runtime Environment:
#
クラッシュログはほとんど同じように見えますが、native_div_callとdo_div_callのJavaフレームの部分だけは異なり、大文字のJになっています。
C [libc.so.6+0x3a5a3] div+0x3
C [libdump.so+0x1162] Java_jaokim_dumpster_Divider_native_1div_1call+0x29
-> J 56 jaokim.dumpster.Divider.native_div_call(I)V (0 bytes) @ 0x00007f67a87e46db [0x00007f67a87e4620+0x00bb]
-> J 55 c1 jaokim.dumpster.Divider.do_div(I)V (6 bytes) @ 0x00007f67a12b33a4 [0x00007f67a12b3320+0x0084]
j jaokim.dumpster.Dumpster.do_loops(I)V+14
j jaokim.dumpster.Dumpster.doTestcase(Ljava/lang/Integer;)V+5
j jaokim.dumpster.Dumpster.main([Ljava/lang/String;)V+58
v ~StubRoutines::call_stub
V [libjvm.so+0x773a29] JavaCalls::call_helper(...)+0x299
V [libjvm.so+0x804747] jni_invoke_static(...) [clone .isra.0] [clone .constprop.1]+0x357
V [libjvm.so+0x80733f] jni_CallStaticVoidMethod+0x12f
C [libjli.so+0x4627] JavaMain+0xd17
C [libjli.so+0x7fc9] ThreadJavaMain+0x9
このように多数回ループを実行する場合、JVMはメソッドdo_divがhotspotであると理解し、毎回インタプリタモードを使わず、JITコンパイルして貴重なクロックサイクルを節約しようとします。56と55という数字がメソッドをコンパイルのタスクIDで、バイト数は生成されたコードのサイズ、アドレスはメモリ中のコンパイル済みコードを指しています。
A=aot compiled Java code
異なるフレームタイプを全てカバーするため、JEP 295のAOT機能を使うAOTコンパイルステップを追加する必要があります。
JEP 295: Ahead-of-Time Compilation
https://openjdk.java.net/jeps/295
この例では、事前コンパイル済みバージョンのDividerクラスの使い方を示しています。jaotcコマンドを使ってクラスをAOTライブラリdivider.soにコンパイルしています。experimentalモードを解除し、AOTLibrary引数を付けています。
duke@cafedead:/work# java -XX:+UnlockExperimentalVMOptions -XX:AOTLibrary="divider.so" Dumpster 1000
クラッシュの状況を見ると、Divider.do_div()フレームには大文字Aの接頭辞が付いています。これはAOTコンパイル済みメソッドを使っていることを示しています。
C [libc.so.6+0x3a5a3] div+0x3
C [libdump.so+0x1162] Java_jaokim_dumpster_Divider_native_1div_1call+0x29
J 55 jaokim.dumpster.Divider.native_div_call(I)V (0 bytes) @ 0x00007fc0987e465b [0x00007fc0987e45a0+0x00bb]
-> A 2 jaokim.dumpster.Divider.do_div(I)V (6 bytes) @ 0x00007fc0afb7d194 [0x00007fc0afb7d120+0x0074]
j jaokim.dumpster.Dumpster.do_loops(I)V+14
j jaokim.dumpster.Dumpster.doTestcase(Ljava/lang/Integer;)V+5
j jaokim.dumpster.Dumpster.main([Ljava/lang/String;)V+58
v ~StubRoutines::call_stub
V [libjvm.so+0x773a29] JavaCalls::call_helper(...)+0x299
V [libjvm.so+0x804747] jni_invoke_static(...) [clone .isra.0] [clone .constprop.1]+0x357
V [libjvm.so+0x80733f] jni_CallStaticVoidMethod+0x12f
C [libjli.so+0x4627] JavaMain+0xd17
C [libjli.so+0x7fc9] ThreadJavaMain+0x9
Who caused the crash?
この特定のケースでは、何が起こったのかわかっています。ゼロ除算を行ったのです。問題のあるフレームはC標準ライブラリにあり、hs_errファイルには
“See problematic frame for where to report the bug”（バグ報告先は問題のあるフレームを参照してください）
と明示されているにもかかわらず、よく使われているC標準ライブラリがこのように簡単にクラッシュするとは考えられません。ですから、単にlibc.soの責任というのではなく、他のフレームを見て、何が起こっているのかを確認すべきです。次に疑われるのは、独自のネイティブライブラリです。ここでは、divを呼び出す前に分母が0であるかどうかをチェックすることで、修正できます。
JNIEXPORT void JNICALL Java_jaokim_dumpster_Dumpster_native_1div_1call
(jint denominator) {
int numerator = 9;
// call C standard library div
if(denominator == 0) {
return;
}
div(numerator, denominator);
}
しかしながら、実際にネイティブコードを呼ぶのではなく、Javaのループ内でiがゼロにならないよう、”i>=0“から”i>0“に修正するのがよいでしょう。
class Dumpster {
void do_loops(int no_of_loops) {
for(int i = no_of_loops; i > 0; i--) {
new Divider().do_div(i);
}
}
}
Summary
hs_errファイルには、さまざまなスタックフレームのタイプが簡潔にまとめられており、バグやクラッシュをどこに報告すればよいかのヒントも記載されています。
J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code
しかしながら、上記内容を以下の表で少々わかりやすくしてみました。この記事により、スタックフレームの接頭辞の意味の背景にあるものへの理解が進むことを願っています。
| Char | Description | Description (Janapese) |
|---|---|---|
j | Java code interpreted by the JVM at runtime | 実行時にJVMが解釈するJavaコード （インタプリタモード） |
J | Java code compiled just in time by the JVM | JVMがJITコンパイルしたJavaコード |
A | Java code compiled ahead-of-time, by jaotc | jaotcでAOTコンパイルしたJavaコード |
C | Native code from external library, not residing in the JVM | JVMにない、外部ライブラリ由来のネイティブコード |
V | Native code from library part of the JVM | JVMを構成するライブラリ由来のネイティブコード |
v | Native code genereted by the JVM | JVMが生成したネイティブコード |
Further reading
Javaアプリケーションのクラッシュのトラブルシューティングにおいてさらなる支援が必要であれば、Java Troubleshooting Guideを読まれることをおすすめします。このガイドでは、何がクラッシュしたのかを判断する方法だけでなく、ヒントや可能な回避策についてもアドバイスしています。
システム・クラッシュのトラブルシューティング
https://docs.oracle.com/javase/jp/15/troubleshoot/troubleshoot-system-crashes.html
Troubleshoot System Crashes
https://docs.oracle.com/en/java/javase/15/troubleshoot/troubleshoot-system-crashes.html
Logico Inside 