Deciphering the stack trace

原文はこちら。
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クラス(DumpsterDivider)で構成されており、前者はループで反復するたびに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

その前に、DividerDumpsterという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_calldo_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

しかしながら、上記内容を以下の表で少々わかりやすくしてみました。この記事により、スタックフレームの接頭辞の意味の背景にあるものへの理解が進むことを願っています。

CharDescriptionDescription (Janapese)
jJava code interpreted by the JVM at runtime実行時にJVMが解釈するJavaコード
(インタプリタモード)
JJava code compiled just in time by the JVMJVMがJITコンパイルしたJavaコード
AJava code compiled ahead-of-time, by jaotcjaotcでAOTコンパイルしたJavaコード
CNative code from external library, not residing in the JVMJVMにない、外部ライブラリ由来のネイティブコード
VNative code from library part of the JVMJVMを構成するライブラリ由来のネイティブコード
vNative code genereted by the JVMJVMが生成したネイティブコード

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

コメントを残す

以下に詳細を記入するか、アイコンをクリックしてログインしてください。

WordPress.com ロゴ

WordPress.com アカウントを使ってコメントしています。 ログアウト /  変更 )

Google フォト

Google アカウントを使ってコメントしています。 ログアウト /  変更 )

Twitter 画像

Twitter アカウントを使ってコメントしています。 ログアウト /  変更 )

Facebook の写真

Facebook アカウントを使ってコメントしています。 ログアウト /  変更 )

%s と連携中