ページの先頭行へ戻る
Interstage Application Server/Interstage Web Server Express チューニングガイド
FUJITSU Software

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

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

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

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

  コンパイラスレッドのCPU使用状況を出力する場合は、図1のオプションを指定します。

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

  図1および図2のオプションの指定により、動的コンパイルが発生するたびに、その発生状況ログが標準出力へ、図3および図4に示す形式で出力されます。

  また、図5および図6に出力例を示します。

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

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

-XX:+PrintCompilationCPUTime

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

-XX:+FJPrintCompilation

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

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

  図3の各要素について、以下で説明します。

$1: ログ出力時の時間

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

$2: コンパイラスレッド名

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

$3: CPU時間

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

なお、コンパイル対象となるJavaメソッドがネイティブメソッドだった場合は、コンパイル処理としての時間を必要としないため、当該メソッドに関する処理はCPU時間に含まれていません。

$4: 経過時間

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

$5: 通し番号

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

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

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

  図4の各要素について、以下で説明します。

$1: Javaメソッドのコンパイル要求発生時間(ログ出力時の時間)

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

$2: 通し番号

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

    

$3: Javaメソッド名

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

$4: Javaメソッドのバイト数

コンパイル対象となったJavaメソッドの大きさ(バイトコード・サイズ)をバイト数で示します。

$5: 空白または(static)

コンパイル対象となったJavaメソッドが、コンパイル処理としての時間を必要としないネイティブメソッドだった場合、“(static)”と出力されます。

Javaメソッドが、ネイティブメソッドでない場合は、この位置に何も出力されません。

なお、動的コンパイル結果情報の出力対象Javaメソッドとしてネイティブメソッドを含むのは、JDK/JRE 7の場合です。JDK/JRE 6の場合は、動的コンパイル結果情報の出力対象Javaメソッドとしてネイティブメソッドを含みません。

5 -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]

6 -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)