Go to Qiita Advent Calendar 2024 Top
LoginSignup
12
6

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

NTTコムウェアAdvent Calendar 2023

Day 10
@comware_osakamoto(Osamu SAKAMOTO)inNTTコムウェア株式会社

GraalVM Native Image トラブルシューティングことはじめ

Last updated at Posted at 2023-12-09

この記事は NTT コムウェア Advent Calendar 2023 10日目の記事です。

はじめに

こんにちは、 NTT コムウェア株式会社の坂本統です。

私は普段 Java システムの技術サポートをお仕事にしています。特に Java 実行・開発環境ソフトウェア（JRE/JDK）である OpenJDK を専門として Java 仮想マシン（JVM）のトラブルシューティングを得意としています。

この記事では近頃 Java 界隈で注目されている GraalVM Native Image トラブルシューティングことはじめとして、Native Image から JVM 関連情報を取得する方法とその情報を参照する方法についてご紹介いたします。

GraalVM Native Image とは

GraalVM は Oracle 社が主導して開発している OpenJDK ベースの Java 実行開発環境ソフトウェアで、Java 実行基盤として互換性を持つ他に以下の３つの強力な機能を持ち、次世代 Java 高速実行基盤として期待されています。

  • 高性能 Just-In-Time(JIT) コンパイラ
  • Ahead-Of-Time(AOT) コンパイラによる高速ネイティブ実行（Native Image）
  • 多言語プログラミング対応（Truffle）

このうち Native Image 機能 は Java アプリケーションを高速で軽量な実行ファイル（Native Image）に変換する機能です。ざっくり伝えると Java コードの解析によって同等の C++ コードに変換してコンパイルします。この機能により生成された実行ファイルは Native Image と呼ばれ、通常の Java アプリケーションと比較して高速起動かつ低メモリ消費のメリットを持ちます。またアプリケーションに必要な最小限の Java コードしか含めないためファイルサイズの縮小やセキュリティホールの極小化といったメリットもあります。

さて話が変わりますが OpenJDK や GraalVM といった多くの JRE/JDK は HotSpot と言う名前の JVM を使用します。JVM のトラブルシューティングでは HotSpot VM が備える機能を使用して解析に必要な情報、例えば GC ログやフライトレコードなどを取得します。一方 Native Image は軽量な Substrate VM を使用します。これは HotSpot VM で取得できた情報が Substrate VM からは取得不可であることや、取得可能であっても取得手順が異なることを意味します。

実際のところ、GraalVM の開発が進むことでほぼ同じ情報を取得できる様になりました。ただし取得方法や情報の内容にはいくつかの差異があります。前置きが長くなりましたがこの記事では HotSpot VM と比較した、 Substrate VM(Native Image)) から情報を取得する方法とその情報を参照する方法について紹介いたします。

JVM から取得可能な情報

本記事でまとめる JVM から取得可能な情報は以下の通りです。

情報 主な取得目的
バージョン 実行環境の確認
JVM オプション アプリケーション設定の確認
GC ログ（Serial GC） GC チューニング
スレッドダンプ ハングアップ解析
ヒープダンプ OutOfMemoryError 解析
フライトレコード アプリケーションプロファイリング
エラーレポート クラッシュ解析
コアダンプ デバッグ

調査環境

調査環境は以下の通りです。

項目 詳細 備考
OS Ubuntu 22.04
Java 実行環境 GraalVM for JDK 21 Community オープンソース版

本記事では Linux 環境における Native Image 機能の情報をまとめています。Windows 環境ではいくつかの制限により同様の結果とならない可能性があることに注意して下さい。

取得可能な情報や内容は GraalVM のバージョンによって異なります。本記事では GraalVM for JDK 21 に基づく情報を記載しています。お手元で試す場合は 21 以降のバージョンを使用することを推奨します。

検証用アプリケーションとビルド手順

情報の取得方法や参照方法を説明する前にまず簡単に Native Image の使用方法を紹介します。

はじめに公式の GitHub リポジトリから GraalVM for JDK 21 Community を取得し、 PATH や JAVA_HOME を設定して環境を整えて下さい。

SDKMAN を使用すると簡単に取得・設定できます。

次に検証用に簡単な Java アプリケーションを作成しましょう。ここでは何もせず待機し続けるだけの Sleep と意図的に OutOfMemoryError を引き起こす OutOfMemoryError を作成します。

Sleep.java
class Sleep {
    public static void main(String[] args) throws Exception {
        Thread.sleep(10000000);
    }
}
OutOfMemoryError.java
public class OutOfMemoryError {
        public static void main(String[] args) {
            StringBuilder sb = new StringBuilder();
                while(true){
                    sb.append("OOME will occur.");
                }
        }
}

最後に Native Image を生成します。はじめに javac で Java アプリケーションをコンパイルした後、GraalVM に付属の native-image でビルドします。

ビルド
$ javac MyApp.java
$ native-image MyApp

何もトラブルがなければ native-image を実行した後に実行ファイル（Native Image）が生成されているはずです。Native Image は元となるクラスファイルや JAR ファイルの名前部分がすべて小文字表記になったファイル名で生成されます。以下の例では myapp が該当します。

ファイル確認
$ ls
myapp MyApp.java MyApp.class

実際のところいくつかの情報の取得には別途 native-image へビルドオプション指定が必要ですが、詳しくは後述します。

（参考）Spring Petclinic

フライトレコードなどの長時間の情報を参照する時は前述の様なシンプルなアプリケーションでは十分な情報が記録されません。そのため Web アプリケーションの様な複雑なアプリケーションが欲しくなります。その場合は Spring Petclinic をお勧めします。これは Sprin Boot を使用して実装された架空の動物病院のサイトを模した Web アプリケーションのサンプルです。Native Image をサポートしていますので簡単にビルドできます。

詳しい手順は省略しますが以下のいずれかのコマンドを実行することでビルドできます。ビルドにはやや時間がかかるのでコーヒーでも淹れてゆっくりと待ちましょう。

Maven ビルドの場合
$ mvn -Pnative native:compile
Gradle ビルドの場合
$ gradle nativeCompile

Spring Boot アプリケーションの Native Image ビルドに関する詳細は GraalVM Native Image Support を参照して下さい。

情報取得方法および参照方法

以降は Native Image から各種情報を取得する方法と参照方法についてまとめます。

バージョン

トラブルシューティングを始めるにあたり、どのバージョンの JRE/JDK で動作しているかを把握する必要があるでしょう。

通常の Java 実行環境でバージョンを確認するには java -version を実行しますが、 Native Image の場合は実行ファイルそのものに JVM が含まれるため、strings コマンドを使用してバージョンを含めた文字列を抽出します。バージョン情報だけ抽出するには com.oracle.svm.core.VM で grep して下さい。以下は実行例です。ここで <native_image> は生成した Native Image 自身か、そのファイル名を指します。

バージョン確認
$ strings <native_image> | grep com.oracle.svm.core.VM
com.oracle.svm.core.VMInspectionOptions_OptionDescriptors
com.oracle.svm.core.VMInspectionOptions_OptionDescriptors
com.oracle.svm.core.VMInspectionOptions
com.oracle.svm.core.VM
com.oracle.svm.core.VM=21+35
com.oracle.svm.core.VM.Java.Version=21
...省略

この例では com.oracle.svm.core.VM.Java.Version=21 から Java バージョンは 21 であること、com.oracle.svm.core.VM=21+35 から GraalVM のバージョンとビルド番号は 21+35 であることが分かります。

JVM オプション

実行中のアプリケーションの設定を把握するために指定されている JVM オプションを確認したい場合があります。

これは通常の Java アプリケーションと同様に ps aux | grep <native_image_name> コマンドを実行することで確認できます。

JVM オプション確認
$ ps aux | grep <native_image>
user 1327261 2.5 0.3 1828040 213956 pts/0 Sl+ 17:26 0:00 /path/to/native_image -XX:+PrintGC -XX:+PrintGCSummary
...省略

この例では GC 関連の JVM オプション -XX:+PrintGC -XX:+PrintGCSummary を指定していることが分かります。

Native Image に -XX:+PrintFlags= を指定して実行すると指定可能な JVM オプション一覧を確認できます。

JVM オプション一覧表示
$ <native_image> -XX:PrintFlags=
-XX:ActiveProcessorCount=-1 Overwrites the available number of processors
provided by the OS. Any value <= 0 means using the processor count from
the OS.
-XX:±AutomaticReferenceHandling Determines if the reference handling is executed
automatically or manually. Default: + (enabled).
...省略

GC ログ（Serial GC）

Native Image に以下の JVM オプションを指定することで GC ログが標準エラー出力されます。基本となる JVM オプションは -XX:+PrintGC と -XX:+VerboseGC です。その他のオプションはこれら２つのオプションが指定されていないと有効化できない場合があります。詳細な使用方法は前述の -XX:+PrintFlags= で確認して下さい。

JVM オプション名 内容
-XX:±PrintGC 各 GC 実行後の GC 情報を表示
-XX:±VerboseGC 各 GC 実行前後の詳細な情報を表示
-XX:±PrintGCSummary アプリケーション終了後の GC 情報サマリを表示
-XX:±PrintGCTimes 各 GC のフェーズごとの実行時間を表示
-XX:±TraceHeapChunks GC 実行中のヒープチャンクを追跡

以下は前述の OutOfMemoryError を使用して -XX:+PrintGC と -XX:VerboseGC を指定した場合の出力例です。またヒープ領域を制限するために -Xmx100m -Xms100m -Xmn30m も指定しています。

GC ログ出力
$ ./outofmemoryerror -Xmx100m -Xms100m -Xmn30m -XX:+PrintGC -XX:+VerboseGC
[0.059s] GC(0) Using Serial GC
[0.059s] GC(0)   Memory: 64026M
[0.059s] GC(0)   Heap policy: adaptive
[0.059s] GC(0)   Maximum young generation size: 30M
[0.059s] GC(0)   Maximum heap size: 100M
[0.059s] GC(0)   Minimum heap size: 100M
[0.059s] GC(0)   Aligned chunk size: 512K
[0.059s] GC(0)   Large array threshold: 128K
[0.059s] GC(0) Collect on allocation
[0.060s] GC(0)   Eden: 37.85M->0.00M
[0.060s] GC(0)   Survivor: 0.00M->0.00M
[0.060s] GC(0)   Old: 0.00M->18.50M
[0.060s] GC(0)   Free: 0.00M->2.00M
[0.060s] GC(0) Full GC (Collect on allocation) 37.85M->18.50M 1.313ms
[0.104s] GC(1) Collect on allocation
[0.105s] GC(1)   Eden: 36.00M->0.00M
[0.105s] GC(1)   Survivor: 0.00M->0.00M
[0.105s] GC(1)   Old: 18.50M->36.50M
[0.105s] GC(1)   Free: 2.00M->2.00M
[0.105s] GC(1) Full GC (Collect on allocation) 54.50M->36.50M 1.265ms
[0.189s] GC(2) Collect on allocation
[0.191s] GC(2)   Eden: 72.00M->0.00M
[0.191s] GC(2)   Survivor: 0.00M->0.00M
[0.191s] GC(2)   Old: 36.50M->72.50M
[0.191s] GC(2)   Free: 2.00M->2.00M
[0.191s] GC(2) Full GC (Collect on allocation) 108.50M->72.50M 2.502ms
...省略

これは GC 番号 0 から 2 の出力例です。-XX:+PrintGC を指定することで [0.060s] GC(0) Full GC (Collect on allocation) 37.85M->18.50M 1.313ms の様な一行が出力されます。この行から GC 種別とその理由、Java ヒープ使用量の推移、実行時間が分かります。その他の部分は -XX:VerboseGC を指定することで出力される詳細なログです。

見ての通り Native Image（Substrate VM）が出力する GC ログは独自の形式です。そのため既存の GC ログ解析ツール（GCViewer など）が対応していないことに注意して下さい。

本記事ではオープンソースの GraalVM Community for JDK 21 を使用し、唯一選択可能な Serial GC 方式に基づく内容を記載しています。JDK バージョンが異なる場合や、プロプライエタリの Oracle GraalVM を使用して G1GC 方式を選択してビルドした場合は前述の説明と異なる点があることに注意して下さい。

スレッドダンプ

スレッドダンプを取得したい場合は Native Image 機能によるビルド時から設定が必要です。スレッドダンプ出力機能はデフォルトで Native Image に含まれません。そのため native-image のビルドオプション -H:+DumpThreadStacksOnSignal を指定してビルドする必要があります。

ビルド
$ javac MyApp.java
$ native-image -H:+DumpThreadStacksOnSignal MyApp

-H:+DumpThreadStacksOnSignal は実験的（Experimental）なビルドオプションであるためビルド時に警告が出ます。

このビルドオプションを指定してビルドした Native Image はスレッドダンプ出力機能を持ちます。スレッドダンプを出力するには実行中のアプリケーションプロセスに対して QUIT シグナルを送信して下さい。QUIT シグナルを受信した Native Image はスレッドダンプを標準エラー出力します。

スレッドダンプ出力
$ kill -QUIT <native_image_pid>

以下は Sleep のスレッドダンプを出力した例です。

スレッドダンプ（抜粋）
Full thread dump:
"Signal Dispatcher" #29 daemon thread=0x00007fd65c000b80 state=RUNNABLE
SP 0x00007fd668dfedd0 IP 0x000055f07d5c966a [image code]
com.oracle.svm.core.posix.headers.CSunMiscSignal.await(CSunMiscSignal.java)
SP 0x00007fd668dfedd0 IP 0x000055f07d5c966a [image code]
com.oracle.svm.core.posix.Util_jdk_internal_misc_Signal$SignalState.await(SunMiscSubstitutions.java:353)
SP 0x00007fd668dfedd0 IP 0x000055f07d5c966a [image code]
com.oracle.svm.core.posix.Util_jdk_internal_misc_Signal$DispatchThread.run(SunMiscSubstitutions.java:289)
SP 0x00007fd668dfee40 IP 0x000055f07d64dce4 [image code] java.lang.Thread.run(Thread.java:833)
SP 0x00007fd668dfee50 IP 0x000055f07d5e327a [image code]
com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:775)
SP 0x00007fd668dfee80 IP 0x000055f07d5cfb17 [image code]
com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:203)
SP 0x00007fd668dfeea0 IP 0x000055f07d55e7ef [image code]
com.oracle.svm.core.code.IsolateEnterStub.PosixPlatformThreads_pthreadStartRoutine_cf47bd191b082a3631657d369b9255c828b9
a95c(IsolateEnterStub.java:0)
"Reference Handler" #28 daemon thread=0x00007fd664000b80 state=WAITING
SP 0x00007fd6697fed90 IP 0x000055f07d57cf56 [image code]
com.oracle.svm.core.genscavenge.HeapImpl.transitionToNativeThenAwaitPendingRefs(HeapImpl.java:569)
SP 0x00007fd6697fedc0 IP 0x000055f07d57d02b [image code]
com.oracle.svm.core.genscavenge.HeapImpl.waitForPendingReferenceList(HeapImpl.java:558)
SP 0x00007fd6697fedf0 IP 0x000055f07d57d113 [image code]
com.oracle.svm.core.genscavenge.HeapImpl.waitForReferencePendingList(HeapImpl.java:548)
SP 0x00007fd6697fee20 IP 0x000055f07d5977c0 [image code]
com.oracle.svm.core.heap.ReferenceInternals.waitForPendingReferences(ReferenceInternals.java:147)
SP 0x00007fd6697fee20 IP 0x000055f07d5977c0 [image code]
com.oracle.svm.core.heap.ReferenceHandlerThread.run(ReferenceHandlerThread.java:83)
SP 0x00007fd6697fee40 IP 0x000055f07d64dce4 [image code] java.lang.Thread.run(Thread.java:833)
SP 0x00007fd6697fee50 IP 0x000055f07d5e327a [image code]
com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:775)
SP 0x00007fd6697fee80 IP 0x000055f07d5cfb17 [image code]
com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:203)
SP 0x00007fd6697feea0 IP 0x000055f07d55e7ef [image code]
com.oracle.svm.core.code.IsolateEnterStub.PosixPlatformThreads_pthreadStartRoutine_cf47bd191b082a3631657d369b9255c828b9
a95c(IsolateEnterStub.java:0)
"main" #1 thread=0x000055f07ff72340 state=TIMED_WAITING
SP 0x00007ffe9c0829b0 IP 0x000055f07d5ceba9 [image code]
com.oracle.svm.core.posix.headers.Pthread.pthread_cond_timedwait(Pthread.java)
SP 0x00007ffe9c0829b0 IP 0x000055f07d5ceba9 [image code]
com.oracle.svm.core.posix.thread.PosixParkEvent.condTimedWait(PosixPlatformThreads.java:346)
SP 0x00007ffe9c082a30 IP 0x000055f07d5e2232 [image code]
com.oracle.svm.core.thread.PlatformThreads.sleep0(PlatformThreads.java:943)
SP 0x00007ffe9c082a70 IP 0x000055f07d5e1ddc [image code]
com.oracle.svm.core.thread.PlatformThreads.sleep(PlatformThreads.java:910)
SP 0x00007ffe9c082aa0 IP 0x000055f07d53d02a [image code]
com.oracle.svm.core.thread.JavaThreads.sleep(JavaThreads.java:340)
SP 0x00007ffe9c082aa0 IP 0x000055f07d53d02a [image code] java.lang.Thread.sleep(Thread.java:541)
SP 0x00007ffe9c082aa0 IP 0x000055f07d53d02a [image code] Sleep.main(Sleep.java:3)
SP 0x00007ffe9c082aa0 IP 0x000055f07d53d02a [image code]
com.oracle.svm.core.JavaMainWrapper.runCore0(JavaMainWrapper.java:180)
SP 0x00007ffe9c082ad0 IP 0x000055f07d53ccd5 [image code]
com.oracle.svm.core.JavaMainWrapper.runCore(JavaMainWrapper.java:137)
SP 0x00007ffe9c082ad0 IP 0x000055f07d53ccd5 [image code]
com.oracle.svm.core.JavaMainWrapper.doRun(JavaMainWrapper.java:237)
SP 0x00007ffe9c082b00 IP 0x000055f07d55e72b [image code]
com.oracle.svm.core.JavaMainWrapper.run(JavaMainWrapper.java:223)
SP 0x00007ffe9c082b00 IP 0x000055f07d55e72b [image code]
com.oracle.svm.core.code.IsolateEnterStub.JavaMainWrapper_run_3148eece06270530b6e0d4d60311411342c82698(IsolateEnterStub
.java:0)

GC ログと同様に、スレッドダンプの内容も独自の形式です。そのため既存のスレッドダンプ解析ツールでは対応していないことに注意して下さい。

HotSpot VM のそれと大きく異なる点は Substrate VM コード（com.oracle.svm.*）も含まれることです。HotSpot VM のスレッドダンプは通常 Java レイヤしか表示されず JVM 実装コード(C++)はほぼ出力されませんが、Substrate VM はそれ自体が Java で実装されているため JVM 実装コードもスレッドダンプにも含まれます。

ヒープダンプ

ヒープダンプを取得したい場合も Native Image 機能によるビルド時から設定が必要です。ヒープダンプ出力機能もデフォルトで Native Image に含まれません。そのため native-image のビルドオプション --enable-monitoring=heapdump を指定してビルドする必要があります。モニタ機能を全て有効化する all サブオプションの指定でも可能です。

ビルド
$ javac MyApp.java
$ native-image --enable-monitoring=heapdump MyApp

このビルドオプションを指定してビルドした Native Image はヒープダンプ出力機能を持ちます。ヒープダンプを出力するには実行中のアプリケーションに対して USR1 シグナルを送信して下さい。USR1 シグナルを受信した Native Image はヒープダンプをカレントディレクトリにファイル出力します。

ヒープダンプ出力
$ kill -USR1 <native_image_pid>

Native Image は USR1 シグナルを受信すると特定のファイル名規則（svm-heapdump-<PID>-<yyyyMMddHHmmss>Z.hprof）に従ったヒープダンプファイルをカレントディレクトリに出力します。

ファイル出力確認
$ ls
svm-heapdump-1875565-20230711T072608Z.hprof

さらに GraalVM for JDK 21 からは以下の２つの JVM オプションが追加されています。なおこれらは 21 以前のバージョンでは使用できません。

JVM オプション名 内容
-XX:HeapDumpPath= ヒープダンプ出力パスを指定
-XX:+HeapDumpOnOutOfMemoryError OutOfMemoryError 発生時にヒープダンプを出力

例として -XX:+HeapDumpOnOutOfMemoryError を指定して OutOfMemoryError を実行すると OutOfMemoryError 発生時に以下の様なメッセージとヒープダンプファイルが出力されます。

ヒープダンプ出力（OutOfMemoryError 発生時）
$ ./outofmemoryerror -Xmx100m -Xms100m -Xmn30m -XX:+HeapDumpOnOutOfMemoryError
Dumping heap to svm-heapdump-2977021-OOME.hprof ...
Heap dump file created [102395861 bytes in 0.122 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Array allocation too large.
...省略
$ ls
svm-heapdump-2977021-OOME.hprof

ヒープダンプファイルは既存の解析ツール（Eclipse Memory Analyzer や VisualVM）に対応しています。

HotSpot VM のそれと大きく異なる点はスレッドダンプ同様に Substrate VM コード（com.oracle.svm.*）も含まれることです。さらに Native Image に含まれる固有の byte 情報もわずかに含まれます。

フライトレコード

フライトレコードを取得したい場合も Native Image 機能によるビルド時から設定が必要です。JDK Flight Recorder(JFR) 機能もデフォルトで Native Image に含まれません。そのため native-image のビルドオプション --enable-monitoring=jfr を指定してビルドする必要があります。モニタ機能を全て有効化する all サブオプションの指定でも可能です。

ビルド
$ javac MyApp.java
$ native-image --enable-monitoring=jfr MyApp

このビルドオプションを指定してビルドした Native Image は JFR 機能を持ちます。フライトレコードの記録開始をするには JVM 実行オプション –XX:StartFlightRecording= を指定して下さい。指定可能なサブオプションは HotSpot VM のそれと同じです。

JFR 記録開始設定
$ <native_image> –XX:StartFlightRecording=settings=default,filename=<filename>…

–XX:StartFlightRecording= を指定して Native Image を実行することで起動時からフライトレコードの記録を開始します。Native Image を終了するとカレントディレクトリにフライトレコードがファイル出力されます。なお Native Image は jcmd に対応していませんので、現在のところアプリケーションの外側から実行中のアプリケーションの JFR 機能に働きかけて記録を開始・停止・ダンプをできません。

フライトレコードファイルは既存の解析ツール（JDK 付属の jfr や VisualVM、JDK Mission Control など）に対応しています。

HotSpot VM のそれと異なる点は未実装の JFR イベントがあることです。JFR 機能はまだ開発が続けられていますが多くの JFR イベントが実装されていません。各 JFR イベントの実装状況を確認する場合は GraalVM イシュー #5410 を参照して下さい。

（参考）VisualVM から見た未実装 JFR イベント

例として GraalVM for JDK 21 から取得したフライトレコードを VisualVM で読み込んだ場合は以下の項目の情報を参照できません。

  • スレッドダンプ
  • CPU 使用量
  • Metaspace 使用量
  • File IO
  • Socket IO
  • Error/Exception
  • GC 関連の設定値
  • メモリサンプラ
  • ネットワーク使用量
  • CPU 固有情報
  • ネットワークインタフェース固有情報
  • システムプロセス一覧

これは以下の JFR イベントが実装されていないためです。

JFR イベント VisualVM メニュー 備考
jdk.ThreadDump Overview - Thread dump
jdk.CPULoad Monitor - CPU usage/Environment - CPU utilization
jdk.MetaspaceSummary Monitor - Metaspace usage
jdk.FileRead File IO
jdk.FileWrite File IO
jdk.SocketRead Socket IO
jdk.SocketWrite Socket IO
jdk.JavaErrorThrow Exceptions
jdk.JavaExceptionThrow Exceptions
jdk.GCConfiguration GC - GC configuration
jdk.GCHeapConfiguration GC - Heap configuration
jdk.YoungGenerationConfiguration GC - Young Generation configuration
jdk.GCSurvivorConfiguration GC - Survivor configuration
jdk.GCTLABConfiguration GC - TLAB configuration
jdk.ObjectCount Sampler - Heap histogram #7402 で実装リクエスト中
jdk.ThreadAllocationStatistics Sampler - Per Thread Allocation #7263 で JDK 22 にマージ
jdk.CPUInformation Environment - CPU details
jdk.NetworkUtilization Environment - Network utilization
jdk.SystemProcess Environment - System processes

エラーレポート

HotSpot VM は JVM レイヤで異常（Segmentation Fault など）が発生した場合にエラーレポートをファイル出力（hs_err_pid<pid>.log）します。Native Image の Substrate VM でも同様に異常時はエラーレポートを標準エラー出力します。

エラーレポートの出力機能は Native Image の Segfault ハンドラ実装（SubstrateSegfaultHandler）が行いますがデフォルトで有効化されているため native-image のビルドオプション設定は必要ありません。

以下は実行中の Native Image に対し意図的に SEGV シグナルを送信したときのエラーレポート抜粋です。エラーレポートも Substrate VM 独自の内容が出力されるため HotSpot VM のそれとは違うことに注意して下さい。

エラーレポート（抜粋）
[ [ SubstrateSegfaultHandler caught a segfault in thread 0x000055e0aad45700 ] ]
siginfo: si_signo: 11, si_code: 0, si_addr: 0x000003e800162976

Current timestamp: 1688534135235

General purpose register values:
    RAX 0xfffffffffffffffc is an unknown value
    RBX 0x0000000000000000
...省略

Printing Instructions (ip=0x00007ff24877a376):
    0x00007ff24877a356: 0x38 0x00 0x00 0xe8 0xe2 0x3c 0x00 0x00 0x89 0xde 0x45 0x31 0xd2 0x31 0xd2 0x41
...省略

Top of stack (sp=0x00007ffcf1a60c50):
    0x00007ffcf1a60c50: 0x0000000000000001 0x0000008145e3a1a8
...省略

Top frame info:
    Does not look like a Java Frame. Use JavaFrameAnchors to find LastJavaSP:
    Found matching Anchor:0x00007ffcf1a60d80
    LastJavaSP 0x00007ffcf1a60d70
    LastJavaIP 0x000055e09f439f96

Threads:
    0x000055e0aad45700 STATUS_IN_JAVA (PREVENT_VM_FROM_REACHING_SAFEPOINT) "DestroyJavaVM" - 0x00007ff240c01028,
stack(0x00007ffcf1264000,0x00007ffcf1a61000)
    0x00007ff1e0000b80 STATUS_IN_NATIVE (ALLOW_SAFEPOINT) "http-nio-8080-Acceptor" - 0x00007ff21200b158, daemon,
stack(0x00007ff209ffe000,0x00007ff20a7fd000)
    0x00007ff1dc000b80 STATUS_IN_NATIVE (ALLOW_SAFEPOINT) "http-nio-8080-Poller" - 0x00007ff212008bc0, daemon,
stack(0x00007ff20a7ff000,0x00007ff20affe000)
    0x00007ff1e8000b80 STATUS_IN_NATIVE (ALLOW_SAFEPOINT) "http-nio-8080-exec-9" - 0x00007ff212004698, daemon,
stack(0x00007ff20b801000,0x00007ff20c000000)
...省略

VM thread locals for the failing thread 0x000055e0aad45700:
    0 (8 bytes): JNIThreadLocalEnvironment.jniFunctions = (bytes)
        0x000055e0aad45700: 0x0000000000000000
    8 (8 bytes): StackOverflowCheckImpl.stackBoundaryTL = (Word) 1 (0x0000000000000001)
    16 (4 bytes): Safepoint.safepointRequested = (int) 2147458250 (0x7fff9cca)
    20 (4 bytes): StatusSupport.statusTL = (int) 1 (0x00000001)
    24 (32 bytes): ThreadLocalAllocation.regularTLAB = (bytes)
        0x000055e0aad45718: 0x00007ff240c00000 0x00007ff240d00000
        0x000055e0aad45728: 0x00007ff240c01138 0x0000000000000000
    56 (8 bytes): PlatformThreads.currentThread = (Object) java.lang.Thread (0x00007ff240c01028)
...省略

No VMOperation in progress

The 15 most recent VM operation status changes (oldest first):
    1688534107583 - Started Garbage collection (safepoint: true, queueingThread: 0x000055e0aad44340, executingThread:
    0x000055e0aad44340, safepointId: 1)
    1688534107600 - Finished Garbage collection (safepoint: true, queueingThread: 0x000055e0aad44340, executingThread:
    0x000055e0aad44340, safepointId: 1)
...省略

Counters:

Java frame anchors for the failing thread 0x000055e0aad45700:
    Anchor 0x00007ffcf1a60d80 LastJavaSP 0x00007ffcf1a60d70 LastJavaIP 0x000055e09f439f96

Stacktrace for the failing thread 0x000055e0aad45700:
    SP 0x00007ffcf1a60c50 IP 0x00007ff24877a376 IP is not within Java code. Trying frame anchor of last Java frame
instead.
    SP 0x00007ffcf1a60d70 IP 0x000055e09f439f96 [image code]
com.oracle.svm.core.thread.PlatformThreads.joinAllNonDaemonsTransition(PlatformThreads.java:354)
    SP 0x00007ffcf1a60da0 IP 0x000055e09f276b08 [image code]
com.oracle.svm.core.thread.PlatformThreads.joinAllNonDaemons(PlatformThreads.java:338)
    SP 0x00007ffcf1a60da0 IP 0x000055e09f276b08 [image code]
com.oracle.svm.core.JavaMainWrapper.runShutdown0(JavaMainWrapper.java:205)
    SP 0x00007ffcf1a60dc0 IP 0x000055e09f276031 [image code]
com.oracle.svm.core.JavaMainWrapper.runShutdown(JavaMainWrapper.java:198)
    SP 0x00007ffcf1a60dc0 IP 0x000055e09f276031 [image code]
com.oracle.svm.core.JavaMainWrapper.doRun(JavaMainWrapper.java:242)
    SP 0x00007ffcf1a60df0 IP 0x000055e09f31c32b [image code]
com.oracle.svm.core.JavaMainWrapper.run(JavaMainWrapper.java:223)
    SP 0x00007ffcf1a60df0 IP 0x000055e09f31c32b [image code]
com.oracle.svm.core.code.IsolateEnterStub.JavaMainWrapper_run_e6899342f5939c89e6e2f78e2c71f5f4926b786d(IsolateEnterStub
.java:0)

VM mutexes:
    mutex "thread" is unlocked.
    mutex "mainVMOperationControlWorkQueue" is unlocked.
    mutex "jfrSymbolRepository" is unlocked.
    mutex "jfrThreadRepository" is unlocked.
    mutex "perfDataInitialization" is unlocked.
    mutex "SamplerBufferPool" is unlocked.
    mutex "jfrRecorder" is unlocked.
    mutex "referencePendingList" is unlocked.

AOT compiled code is mapped at 0x000055e09eb93000 - 0x000055e0a3ce7bff

Heap settings and statistics:
    Supports isolates: true
    Heap base: 0x00007ff243200000
    Object reference size: 8
    Aligned chunk size: 1048576
    Incremental collections: 3
    Complete collections: 2

Native image heap boundaries:
    ReadOnly Primitives: 0x00007ff243301028 - 0x00007ff244351d50
    ReadOnly References: 0x00007ff244351d50 - 0x00007ff244ccb628
    ReadOnly Relocatables: 0x00007ff244ccc000 - 0x00007ff2454c5668
    Writable Primitives: 0x00007ff2454c6000 - 0x00007ff245644dd8
    Writable References: 0x00007ff245644dd8 - 0x00007ff2462f4138
    Writable Huge: 0x00007ff246300030 - 0x00007ff24660ba70
    ReadOnly Huge: 0x00007ff24660c030 - 0x00007ff24850a7e8

Heap:
    Young generation:
        ...省略
    Old generation:
        ...省略

Segfault detected, aborting process. Use runtime option -R:-InstallSegfaultHandler if you don't want to use
SubstrateSegfaultHandler.

native-image のビルドオプション –R:-InstallSegfaultHandler を指定してビルドするか、JVM オプション -XX:-InstallSegfaultHandler を指定して実行すると Segfault ハンドラを無効化できます。無効化した場合は異常発生時にエラーレポートが出力されなくなりますが、代わりにコアダンプが出力されます。異常発生時のコアダンプ出力を期待する場合は Segfault ハンドラを無効化する必要があることに注意して下さい。

コアダンプ

ざっくりいうと Native Image は Java コード + JVM コードが等価な C++ コードに変換されて１つの実行ファイルとしてコンパイルされたものです。そのため Native Image は GDB を使用してデバッグします。

コアダンプを使用せず直接 Native Image のデバッグをする場合は GDB の代わりに VS Code プラグインを使用できます。詳細は GraalVM ドキュメントの Debug Native Images in VS Code を参照して下さい。

GDB を使用すると実行中の Native Image や Native Image から生成されたコアダンプをデバッグできます。ここでは Native Image の異常でコアダンプが生成された場合の解析の取り掛かりとして GDB でコアダンプを参照できるまでの手順をまとめます。

異常発生時にコアダンプを出力させる場合は Segfault ハンドラを無効化して下さい。

GDB の使用方法や GDB を使用した Native Image の情報を参照する手順は大変複雑なためこの記事では省略します。詳細は GraalVM ドキュメントの Debug Native Executables with GDB を参照して下さい。

コアダンプは OS の機能によるプロセスのメモリダンプですので GraalVM や Native Image 機能の設定によって取得が制限されることはありません。ただしコアダンプのデバッグにはデバッグ情報（debuginfo）が必要です。これがない場合は GDB で Native Image のコアダンプを参照しても関数名や変数名を読み取れず変数値の参照などもできません。そのため Java コンパイルと Native Image のビルド時にデバッグ情報を生成するオプションを指定します。

デバッグ情報を生成するには javac 実行時に -g オプションを、native-image 実行時に -g オプションを指定します。さらに詳細なデバッグを実現するため native-image に -O0 （オーゼロ）オプションも指定することが推奨されます。このオプションは最適化レベルを 0 （最適化なし）に指定しますが、最適化をしないことでインライン化されたコードなども参照できる様になります。以下はデバッグ情報を生成してビルドする例です。

ビルド
$ javac –g MyApp.java
$ native-image –g –O0 MyApp

native-image に -g を指定することでデバッグ情報のファイル一式が生成されます。以下は native-image 実行ログの抜粋です。Native Image の app だけでなく、そのデバッグ情報ファイル app.debug とソースキャッシュ一式を含むディレクトリ sources が生成されています。

生成されたアーティファクト一覧
Produced artifacts:
/path/to/build/home/app (executable)
/path/to/build/home/app.debug (debug_info)
/path/to/build/home/sources (debug_info)

GDB による Native Image のコアダンプ解析は上記の過程で得た以下のファイル一式が必要です。

  • Native Image（実行ファイル）
  • コアダンプ
  • デバッグ情報
  • ソースキャッシュ

GDB で Native Image のコアダンプを参照するには以下のコマンドを実行します。デバッグ情報ファイルとソースキャッシュは実行ディレクトリに配置していれば GDB が自動で読み込みます。

GDB によるコアダンプの読み込み
$ gdb <native_image> <coredump>

以下は GDB でコアダンプを参照し、特定のスレッドのバックトレース（スタックトレースの様なもの）を参照した２つの例です。これらはいずれも同じコアダンプを参照していますが、前者はデバッグ情報（およびソースキャッシュ）なしの場合で、後者はありの場合です。

デバッグ情報なし
(gdb) bt
#0 0x00007fd01dc937d1 in
pthread_cond_timedwait@@GLIBC_2.3.2 () from
/lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00005612786a5a45 in ?? ()
...省略
デバッグ情報あり
(gdb) bt
#0 0x00007fd01dc937d1 in pthread_cond_timedwait@@GLIBC_2.3.2 () from
/lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00005612786a5a45 in com.oracle.svm.core.posix.headers.Pthread::pthread_cond_timedwait(com.ora
cle.svm.core.posix.headers.Pthread$pthread_cond_t, com.oracle.svm.core.posix.headers.Pthread$pthread_mutex_t, com.oracle.svm.core.posix.headers.Time$timespec) (__0=<optimized out>, __1=<optimized out>, __2=<optimized out>) 
… 省略

フレーム #1 は Substrate VM 実装部分ですが、デバッグ情報なしのため Native Image 部分の関数は ??? の表記となってしまっています。一方デバッグ情報があると実行している関数名や引数まできちんと確認できます。この様に GDB によるデバッグはデバッグ情報がほぼ必須で、デバッグ情報がないとデバッグは非常に困難になります。なおデバッグ情報を生成することで性能には影響はなくファイルサイズが増えるだけです。Native Image を使用する場合はセンシティブなファイルサイズの縛りがない限りデバッグ情報を生成しておくことを推奨します。

（参考）GDB による Native Image のデバッグで利用可能な機能

GDB を使用した Native Image のデバッグでは以下のことができます。

  • Java ソースコードの表示
  • ブレークポイント設定
  • ステップ実行
  • バックトレース表示
  • プリミティブ値の表示
  • Java オブジェクト（構造体表現）の表示
  • Java オブジェクトのキャストと表示
  • パス式を使用したオブジェクトへのアクセス
  • メソッドおよび静的フィールドデータの名前による参照
  • パラメータおよびローカル変数にバインドされた値の名前による参照

以下は簡単な例として Sleep のコアダンプから Thread.sleep() に指定した秒数のプリミティブ値を確認する例です。

Thread.sleep(long) のソース表示とプリミティブ値の参照例
(gdb) frame 8
#8 java.lang.Thread::sleep(long) (millis=10000000) at java/lang/Thread.java:509
509 sleep0(nanos);
(gdb) list ★ Thread.sleep() の Java ソース（.java）を表示
504             ThreadSleepEvent event = beforeSleep(nanos);
505             try {
506                 if (currentThread() instanceof VirtualThread vthread) {
507                     vthread.sleepNanos(nanos);
508                 } else {
509                     sleep0(nanos);
510                 }
511             } finally {
512                 afterSleep(event);
513             }
(gdb) print nanos
$2 = 10000000000000 ★プリミティブ値の表示

はじめに frame コマンドでバックトレースから java.lang.Thread.sleep(long) を実行しているフレーム #8 を指定します。ここでは 509 行目の sleep0(nanos) を実行していることが分かります。続いて list コマンドで Thread.sleep() のソースキャッシュを参照しています。実行している処理は 509 行目の sleep0(nanos) ですので、print コマンドを実行してこれに渡されるプリミティブ値 nanos を参照すると 10000000000000 であることが分かります。この様に GDB を使用して Java コードを参照しつつ、確認したいプリミティブ値を参照できます。

実際のところ Native Image の GDB によるデバッグはこの様な簡単なものだけではありません。先ほど Native Image は Java コードを等価な C++ に変換しているとざっくり述べましたが、実際はかなり複雑に変換しているため高度な理解と考慮が必要です。例えば Java クラスは C++ の構造体として表し、参照はポインタで示されます。つまり Java の大半の参照型オブジェクトはポインタを辿って内容を確認していく必要があり、加えて C++ や GDB に対して深い造詣が要求されます。ここでは詳しく述べませんので詳細は GraalVM ドキュメントの Debug Native Executables with GDB を参照して下さい。

まとめ

この記事では GraalVM Native Image から JVM 関連情報を取得する方法とその情報を参照する方法を記載してきました。2023年12月現在最新の GraalVM for JDK 21 では一部の JFR イベントが開発中であることを除き、おおむね JVM 関連情報が取得できる様になってきました。

最後に簡単なまとめを記載します。なお本記事の内容は GraalVM for JDK 21 Community に基づいた調査結果であり、将来的なバージョンでは取得方法や各種オプションが変更になる可能性があることに注意して下さい。

情報種別 取得可否 ビルドオプション 取得方法 出力形式 解析ツール
バージョン o - $ strings NATIVE-IMAGE | grep “com.oracle.svm.core.VM stdout -
JVM オプション o - $ ps aux | grep NATIVE-IMAGE-NAME stdout -
GC ログ(Serial GC) o - $ NATIVE-IMAGE -XX:+PrintGC -XX:+VerboseGC ... stderr -
スレッドダンプ o -H:+DumpThreadStacksOnSignal $ kill -QUIT PID stderr -
ヒープダンプ o --enable-monitoring=heapdump $ kill -USR1 PID
or
$ NATIVE-IMAGE -XX:+HeapDumpOnOutOfMemoryError		 file
(.hprof)		 Eclipse Memory Analyzer
VisualVM
フライトレコード △ --enable-monitoring=jfr $ NATIVE-IMAGE -XX:StartFlightRecording= file
(.jfr)		 jfr
VisualVM
JDK Mission Control
エラーレポート o - 異常時に自動出力 stderr -
コアダンプ o -g OS による出力 file(core) GDB

※記載されている会社名、製品名、サービス名は、各社の商標または登録商標です。

12
6
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
12
6

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?