9.3.3 動的コンパイル発生状況のログ出力機能

動的コンパイル発生状況のログ出力機能はFJVM固有機能です。

Java VMは、Javaアプリケーションとして実行されるJavaメソッドに対して、必要に応じて自動的にコンパイル処理を行います(動的コンパイル)。

FJVMでは、動的コンパイルの発生状況を出力する機能を「動的コンパイル発生状況のログ出力機能」として実装しています。

動的コンパイル発生状況のログ出力機能では、以下の情報を出力します。

コンパイラスレッドのCPU使用状況
コンパイラスレッド(動的コンパイルを行っているスレッド)が20個のJavaメソッドをコンパイルするごとに、コンパイルを行うのに使用したCPU時間と経過時間を出力します。
経過時間に対してCPU時間の割合が高い場合には、Javaアプリケーションの実行性能に動的コンパイルが影響を与えている可能性があります。
動的コンパイル結果情報
どのJavaメソッドが、いつコンパイルされたかの情報を出力します。
Javaメソッドのコンパイルが、短い間に連続して発生している場合、Javaアプリケーションの実行性能に動的コンパイルが影響を与えている可能性があります。

コンパイラスレッドのCPU使用状況を出力するオプション

コンパイラスレッドのCPU使用状況を出力する場合に指定します。

-XX:+PrintCompilationCPUTime

コンパイラスレッドのCPU使用状況および動的コンパイル結果情報を出力するオプション

コンパイラスレッドのCPU使用状況および動的コンパイル結果情報を出力する場合に指定します。

-XX:+FJPrintCompilation

上記の両方のオプションの指定により、動的コンパイルが発生するたびに、その発生状況ログが標準出力へ、以下に示す形式で出力されます。

コンパイラスレッドのCPU使用状況の出力形式

$1: [$2: cpu=$3ms elapsed=$4ms $5]

$1: ログ出力時の時間: ログ出力時の時間を示します。
ログ出力時の時間のフォーマットは、ログ出力における「9.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。
デフォルトは、「Java VMが起動されてからの経過時間(秒)」です。

$2: コンパイラスレッド名: 情報の出力対象となるコンパイラスレッドの名前を「CompilerThread数字」の形式で示します。

$3: CPU時間: $2のコンパイラスレッドが、20個のJavaメソッドのコンパイルを行うのに使用したCPU時間(ミリ秒)を示します。
なお、ネイティブメソッド自体はコンパイル処理の対象となりません。ネイティブメソッドに対しては、ネイティブプログラムを呼び出すための専用コードの作成処理が、コンパイラスレッドで実行されますが、作成処理は軽微なため、CPU時間を求める際の20個のJavaメソッドに含まれません。

$4: 経過時間: $2のコンパイラスレッドが、20個のJavaメソッドのコンパイルを行うまでに経過した時間(ミリ秒)を示します。

$5: 通し番号: コンパイラスレッドごとの本情報の出力数を、通し番号で示します。
通し番号×20」の値が、そのコンパイラスレッドでコンパイルしたJavaメソッドの累計数になります。

動的コンパイル結果情報の出力形式

$1: $2 $3 ($4 bytes) $5

$1: Javaメソッドのコンパイル要求発生時間(ログ出力時の時間): Javaメソッドのコンパイル要求が発生した時間(ログ出力時の時間)を示します。
ログ出力時の時間のフォーマットは、ログ出力における「9.5.7 ログ出力における時間情報のフォーマット指定機能」により指定できます。
デフォルトは、「Java VMが起動されてからの経過時間(秒)」です。

$2: 通し番号: コンパイル要求の数(コンパイル要求が発生したJavaメソッドの数)を通し番号で示します。
通し番号の後ろに「%」がない場合は、コンパイル対象のJavaメソッド全体をコンパイルする要求です。
通し番号の後ろに「%」がある場合は、コンパイル対象のJavaメソッドを部分的にコンパイルする要求です。
通し番号の後ろに「%」がない場合とある場合は、別の通し番号になります。

$3: Javaメソッド名: コンパイル要求が発生したJavaメソッドの名前を示します。
Javaメソッドを部分的にコンパイルする要求の場合($2に「%」の表示が含まれる場合)、Javaメソッド名の後に、Javaメソッド(バイトコード)のどの部分からコンパイルの対象になっているかを示す情報「(@ 数字)」が付加されます。

$4: Javaメソッドのバイト数: コンパイル対象となったJavaメソッドの大きさ(バイトコード・サイズ)をバイト数で示します。
ネイティブメソッドの場合は、0 bytes と表示されます。

$5: 空白または(static): コンパイル対象となったJavaメソッドが、static修飾子を持つネイティブメソッドだった場合は、“(static)”と出力されます。コンパイル対象となったJavaメソッドが、ネイティブメソッドでない場合、またはstatic修飾子を持たないネイティブメソッドだった場合、この位置には何も出力されません。

例

-XX:+PrintCompilationCPUTime指定時の出力例

0.586: [CompilerThread1: cpu=78.13ms elapsed=450.72ms 1]
0.822: [CompilerThread0: cpu=437.50ms elapsed=686.32ms 1]
1.312: [CompilerThread0: cpu=218.75ms elapsed=489.93ms 2]
1.637: [CompilerThread1: cpu=546.88ms elapsed=1050.52ms 2]
2.385: [CompilerThread0: cpu=296.88ms elapsed=1073.57ms 3]
3.365: [CompilerThread0: cpu=140.63ms elapsed=979.67ms 4]
3.557: [CompilerThread1: cpu=343.75ms elapsed=1919.97ms 3]
4.096: [CompilerThread1: cpu=390.63ms elapsed=539.47ms 4]
4.995: [CompilerThread1: cpu=140.63ms elapsed=898.45ms 5]

例

-XX:+FJPrintCompilation指定時の出力例

0.074:   1   java.util.Properties$LineReader::readLine (383 bytes)
0.102:   2   java.io.Win32FileSystem::normalize (143 bytes)
0.107:   3   java.lang.String::hashCode (60 bytes)
0.179:   4   sun.security.provider.SHA::implCompress (494 bytes)
0.206:   5   sun.reflect.UTF8::utf8Length (81 bytes)
0.229:   6   java.util.jar.Manifest$FastInputStream::readLine (167 bytes)
0.232:   7   sun.nio.cs.UTF_8$Decoder::decodeArrayLoop (1814 bytes)
0.244:   1%  sun.text.NormalizerDataReader::read @ 38 (139 bytes)
0.261:   8   java.math.BigInteger::mulAdd (82 bytes)
  (中略)
0.742: [CompilerThread1: cpu=406.25ms elapsed=677.52ms 1]
0.744:  40   java.lang.String::replace (142 bytes)