概要
HotSpot コンパイラの行うネイティブなコード生成や最適化処理に関しては、対象コードの構文解析が必要となります。
その構文解析に利用されるメモリエリアはネイティブヒープ（Cヒープ）が利用され大きなメソッドや複雑な構文を解析した場合は、その分 Cヒープも多く利用します。
この投稿は、その HotSpot コンパイラによって Cヒープが増加する状況を確認してみようと言う内容です。
ちなみに Java のプログラムも、他の言語と同様にオプティマイズ（最適化）されますが、それは javac でのコンパイル時ではありません。
いつ最適化されるかというと Javaプログラムが実行され、そのコードが HotSpot コンパイラのコンパイル対象になった時に、HotSpot コンパイラによって最適化されます。
簡単なプログラムを作ってみる。
メモリー利用量の確認については、コンパイラがギブアップするまで構文解析を行わせ、その前後でのメモリ利用量の変化を確認してみます。
HotSpot コンパイラが Out Of Nodes で諦める良い方法が見つからず延々と長いコードになってしまいました。
プログラム全体は、https://github.com/takimai39/sample/blob/master/OutOfNodes.java をご覧ください。
import java.io.*;
public class OutOfNodes {
public static void main(String[] args) {
for ( int n = 0 ; n < 2 ; n++ ) {
// CompileThreshold=10000 なので、ループ１回目はHotSpot コンパイラされない。
System.out.println("Hit return to continue"); keyin();
for ( int x = 0 ; x < 9999; x++) {
challenge();
}
}
System.out.println("Hit return to exit"); keyin();
}
private static void keyin() {
BufferedReader userInputStreamReader = new BufferedReader(new InputStreamReader(System.in));
try {
String inputString = userInputStreamReader.readLine();
}
catch (Exception e) {
e.printStackTrace();
}
}
private static String getX() {
String str = "ABCDEFGHIJKLMNOPQRSTUVWXYZ";
return(str);
}
private static String challenge() {
String a[] = new String[300];
String b[] = new String[300];
a[0] = getX();
a[1] = getX();
// ... 中略、延々と、このパターンを 230 回 繰り返す ...
b[0] = 0 + a[0];
b[1] = 1 + a[1];
// ... 同様に 230回 繰り返す...
return(b[0]);
}
}
プログラムを実行し、メモリ利用量を確認
HotSpotコンパイラが、何のメソッドをコンパイルしているのかを確認するために PrintCompilation オプションを付け実行してみます。
表示のフォーマットは左から
タイムスタンプ compilation_number アトリビュート文字 クラス名::メソッド名(コードサイズ）
$ java -XX:+PrintCompilation OutOfNodes
Hit return to continue
3106 1 n java.lang.System::arraycopy (native) (static)
3108 2 java.lang.Integer::stringSize (21 bytes)
3110 3 java.lang.Integer::getChars (131 bytes)
3118 4 java.lang.Object::<init> (1 bytes)
3118 5 java.lang.Math::min (11 bytes)
3118 6 java.lang.AbstractStringBuilder::ensureCapacityInternal (16 bytes)
3121 7 java.lang.String::length (6 bytes)
3121 9 java.lang.AbstractStringBuilder::append (48 bytes)
3124 10 java.lang.String::<init> (67 bytes)
3125 11 java.util.Arrays::copyOfRange (63 bytes)
3127 12 java.lang.StringBuilder::append (8 bytes)
3129 8 java.lang.String::getChars (62 bytes)
3130 13 java.lang.AbstractStringBuilder::<init> (12 bytes)
3130 14 java.lang.StringBuilder::<init> (7 bytes)
3130 15 java.lang.StringBuilder::toString (17 bytes)
3130 16 OutOfNodes::getX (5 bytes)
3130 17 java.lang.StringBuilder::append (8 bytes)
3132 18 java.lang.AbstractStringBuilder::append (62 bytes)
Hit return to continue
841500 19 OutOfNodes::challenge (7992 bytes)
841658 20 % OutOfNodes::main @ 20 (55 bytes)
Hit return to exit
846756 19 OutOfNodes::challenge (7992 bytes) COMPILE SKIPPED: out of nodes during split (not retryable)
別のターミナル画面で、プロセスサイズを観測しながら core ファイルを取得してみます。
COMPILE SKIPPED: が確認された後に、もう一度サイズを確認すると 64M byte ほど増加しています。
$ pmap `jps | grep OutOfNodes | awk '{print $1}' ` | grep total
total 2127304K
$ pmap `jps | grep OutOfNodes | awk '{print $1}' ` | grep total
total 2192840K
後の確認のため、にそれぞれの状況を gcore コマンドにて core ファイルを取得しておきます。
gdb plus (CORE ANALYZER) で core ファイルを確認します
pmap などのコマンドの出力でも良いのですが、malloc() などでアロケートされたメモリエリアを確認するツールとしては CORE ANALYZER があり、core ファイルを確認する人にとっては非常にありがたい、素晴らしいツールです。
この core analyzer に含まれる gdb plus では、heap /v などのコマンドが利用できます。
さらに、個々のアリーナの内訳を heap /c にて確認できますので、出力された結果から何バイトのエリアが多く malloc されているのかなどの確認に利用できます。
$ /work/core_analyzer-master/bin/Linux/ptmalloc/gdb-7.11.1/gdb /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.141-2.6.10.5.el7.x86_64/bin/java ./core.24437.before
(gdb) heap /v メモリ利用量増加前のもの
Warning: 17 mmap memory blocks were found while mp_ reports 16
Python Exception <type 'exceptions.NameError'> Installation error: gdb.execute_unwinders function is missing:
Tuning params & stats:
mmap_threshold=131072
pagesize=4096
n_mmaps=16
n_mmaps_max=65536
total mmap regions created=16
mmapped_mem=11202560
sbrk_base=0x15b8000
Main arena (0x7fb6ab64a760) owns regions:
[0x15d900f - 0x15d9000] Total 17179869184.0GBFailed to get the first chunk at 0x15d8fff
Dynamic arena (0x7fb670000020) owns regions:
[0x7fb6700008c0 - 0x7fb670021000] Total 129KB in-use 1(312) free 3(129KB)
Dynamic arena (0x7fb66c000020) owns regions:
[0x7fb66c0008c0 - 0x7fb66c021000] Total 129KB in-use 1(312) free 2(129KB)
Dynamic arena (0x7fb678000020) owns regions:
[0x7fb6780008c0 - 0x7fb678021000] Total 129KB in-use 1(312) free 2(129KB)
Dynamic arena (0x7fb674000020) owns regions:
[0x7fb6740008c0 - 0x7fb674021000] Total 129KB in-use 11(3KB) free 1(126KB)
Dynamic arena (0x7fb67c000020) owns regions:
[0x7fb67c0008c0 - 0x7fb67c021000] Total 129KB in-use 1(312) free 2(129KB)
Dynamic arena (0x7fb68c000020) owns regions:
[0x7fb68c0008c0 - 0x7fb68c021000] Total 129KB in-use 10(1KB) free 3(128KB)
Dynamic arena (0x7fb688000020) owns regions:
[0x7fb6880008c0 - 0x7fb688021000] Total 129KB in-use 3(22KB) free 2(107KB)
Dynamic arena (0x7fb694000020) owns regions:
[0x7fb6940008c0 - 0x7fb694021000] Total 129KB in-use 1(312) free 2(129KB)
Dynamic arena (0x7fb690000020) owns regions:
[0x7fb6900008c0 - 0x7fb690021000] Total 129KB in-use 0(0) free 2(129KB)
Dynamic arena (0x7fb698000020) owns regions:
[0x7fb6980008c0 - 0x7fb698021000] Total 129KB in-use 0(0) free 2(129KB)
Dynamic arena (0x7fb6a4000020) owns regions:
[0x7fb6a40008c0 - 0x7fb6a40fe000] Total 1013KB in-use 1622(964KB) free 4(36KB)
mmap-ed large memory blocks:
...
下記は、HotSpot コンパイラが COMPILE SKIPPED: out of nodes... となった後のメモリ利用量です。
(gdb) heap /v メモリ利用量増加後のもの
Warning: 18 mmap memory blocks were found while mp_ reports 16
Python Exception <type 'exceptions.NameError'> Installation error: gdb.execute_unwinders function is missing:
Tuning params & stats:
mmap_threshold=8527872
pagesize=4096
n_mmaps=16
n_mmaps_max=65536
total mmap regions created=23
mmapped_mem=11202560
sbrk_base=0x15b8000
Main arena (0x7fb6ab64a760) owns regions:
[0x15d900f - 0x15d9000] Total 17179869184.0GBFailed to get the first chunk at 0x15d8fff
Dynamic arena (0x7fb670000020) owns regions:
[0x7fb6700008c0 - 0x7fb670021000] Total 129KB in-use 1(312) free 3(129KB)
Dynamic arena (0x7fb66c000020) owns regions:
[0x7fb66c0008c0 - 0x7fb66c021000] Total 129KB in-use 1(312) free 2(129KB)
Dynamic arena (0x7fb678000020) owns regions:
[0x7fb6780008c0 - 0x7fb67807e000] Total 501KB in-use 14(6KB) free 4(494KB)
+ Dynamic arena (0x7fb674000020) owns regions: <-- この arena が特に増加してる！
+ [0x7fb664000030 - 0x7fb667b15000] Total 59MB in-use 4(127KB) free 4(58MB)
+ [0x7fb6740008c0 - 0x7fb678000000] Total 63MB in-use 49(51KB) free 12(63MB)
Dynamic arena (0x7fb67c000020) owns regions:
[0x7fb67c0008c0 - 0x7fb67c021000] Total 129KB in-use 1(312) free 2(129KB)
Dynamic arena (0x7fb68c000020) owns regions:
[0x7fb68c0008c0 - 0x7fb68c021000] Total 129KB in-use 10(1KB) free 3(128KB)
Dynamic arena (0x7fb688000020) owns regions:
[0x7fb6880008c0 - 0x7fb688021000] Total 129KB in-use 3(22KB) free 2(107KB)
Dynamic arena (0x7fb694000020) owns regions:
[0x7fb6940008c0 - 0x7fb694021000] Total 129KB in-use 4(560) free 1(129KB)
Dynamic arena (0x7fb690000020) owns regions:
[0x7fb6900008c0 - 0x7fb690021000] Total 129KB in-use 0(0) free 1(129KB)
Dynamic arena (0x7fb698000020) owns regions:
[0x7fb6980008c0 - 0x7fb698021000] Total 129KB in-use 10(6KB) free 2(122KB)
Dynamic arena (0x7fb6a4000020) owns regions:
[0x7fb6a40008c0 - 0x7fb6a40fe000] Total 1013KB in-use 1643(839KB) free 7(161KB)
mmap-ed large memory blocks:
...
増加した arena の内訳を確認する
heap /c コマンドで、上記の arena のさらに内訳を確認することができます。
その増加したエリアは、56380088 bytes free と、ほとんどフリーされていて利用されていません。
つまり一旦は malloc() されて利用されたが、不要になりフリーされたエリアが計上されています。
(gdb) heap /c 0x7fb664000030
Dynamic arena (0x7fb674000020): [0x7fb664000020 - 0x7fb667b15000]
[0x7fb664000030 - 0x7fb6675c4ae8] 56380088 bytes free
[0x7fb6675c4af0 - 0x7fb6675ccad8] 32744 bytes inuse
[0x7fb6675ccae0 - 0x7fb6677ac8b8] 1965528 bytes free
[0x7fb6677ac8c0 - 0x7fb6677b48a8] 32744 bytes inuse
[0x7fb6677b48b0 - 0x7fb667994868] 1966008 bytes free
[0x7fb667994870 - 0x7fb66799c858] 32744 bytes inuse
[0x7fb66799c860 - 0x7fb6679a4848] 32744 bytes inuse
[0x7fb6679a4850 - 0x7fb667b15000] 1509296 bytes free
Total inuse 4 blocks 130976 bytes
Total free 4 blocks 61820920 bytes
(gdb)
empty_block 情報をヒントにしてみる。
情報として core ファイルしかない場合に、free()されたエリアが、以前何のために利用されていたのかを判断することは非常に困難です。
しかし、それでも何かの案を考えてみると、このケースに関しては empty_block のアドレス情報がヒントとして利用できるかもしれません。
HotSpot コンパイラは、利用するメモリエリアを Chunk という単位で確保し、利用し終えると empty_block のアドレスをセットしています。
OpenJDK のソースコードより抜粋 indexSet.cpp
...
184 //---------------------------- IndexSet::free_block() -------------------------
185 // Add a BitBlock to the free list.
186
187 void IndexSet::free_block(uint i) {
188 debug_only(check_watch("free block", i));
189 assert(i < _max_blocks, "block index too large");
190 BitBlock *block = _blocks[i];
191 assert(block != &_empty_block, "cannot free the empty block");
192 block->set_next((IndexSet::BitBlock*)Compile::current()->indexSet_free_block_list());
193 Compile::current()->set_indexSet_free_block_list(block);
194 set_block(i,&_empty_block);
195 }
gdb で empty_block のアドレスを確認し、core ファイルにどのくらい発見できるのか試してみます。
COMPILE SKIPPED となった後の core には多くの empty_block のアドレスが存在している様子がわかります。
(gdb) info var empty_block
All variables matching regular expression "empty_block":
File /usr/src/debug/java-1.7.0-openjdk-1.7.0.141-2.6.10.5.el7.x86_64/openjdk/hotspot/src/share/vm/opto/indexSet.cpp:
IndexSet::BitBlock IndexSet::_empty_block;
Non-debugging symbols:
0x00007fb6ab053ac0 IndexSet::_empty_block
(gdb)
$ od -An -x -w8 core.24437.before | grep "7fb6 0000 3ac0 ab05" | wc -l
1
$ od -An -x -w8 core.24437.after | grep "7fb6 0000 3ac0 ab05" | wc -l
54655
$
そのエリア付近をダンプしてみると、うじゃうじゃ。
$ gdb /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.141-2.6.10.5.el7.x86_64/bin/java ./core.24437.after
...
(gdb) x/20gx 0x7fb665322f30
0x7fb665322f30: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322f40: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322f50: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322f60: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322f70: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322f80: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322f90: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322fa0: 0x00007fb6756461c0 0x00007fb6ab053ac0
0x7fb665322fb0: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322fc0: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
(gdb)
0x7fb665322fd0: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322fe0: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665322ff0: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665323000: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665323010: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665323020: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665323030: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665323040: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665323050: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
0x7fb665323060: 0x00007fb6ab053ac0 0x00007fb6ab053ac0
(gdb)
少し整理してみたい
ノードとは？
COMPILE SKIPPED: out of nodes during split ... のメッセージにあるノードとは、コンパイル時の構文解析で Tree 構造に分解された後の１データ。
※ 何をいっているのかわからなくなってしまった、イメージとしては http://www.atmarkit.co.jp/ait/articles/0707/11/news129.html の木構造の説明図などが良いかも。
Java VM のデフォルトでの制限は
-XX:MaxNodeLimit=65000
この値がデフォルト値です。ここでテストしたプログラムも -XX:MaxNodeLimit=150000 オプションで起動すれば、out of nodes によりスキップされず HotSpot でコンパイルされます。
-XX:-DontCompileHugeMethods
デフォルトでは、8000 byte 以上のサイズを HugeSize としており、そのサイズ以上のメソッドは HotSpot コンパイル対象にはしません。
今回利用したプログラムは、OutOfNodes::challenge (7992 bytes)とありますので、ギリギリ対象になるサイズです。
このオプションを意図的につけて起動すれば 8000 バイト以上のメソッドもHotSpotコンパイル対象にします。
-XX:+PrintCompilation での表示タイミング
HotSpot がこれからコンパイルを始めるというタイミングでレポートされます。
その後、out of nodes などで諦めると COMPILE SKIPPED など、その旨がレポートされます。
メモリ利用量は
実測で 64Mbyte 程度増加しましたが、このサイズが実際に問題になることはほとんど無いでしょう。
また、free() されているので、その JavaVM により再利用されるエリアとなります。
HotSpot コンパイル出来ていない
PrintCompilation の出力結果から、HotSpot コンパイルできておらず timestamp から５秒程度の時間を費やしています。
何か対処は必要なのか
64Mbyteのメモリ利用量増加や５秒のコンパイル時間が実害につながるケースは稀だと思います。
いつもコンパイルに失敗するのだから .hotspot_compiler ファイルに exclude 指定して HotSpot コンパイラの対象にしないようにする。
または、その逆に対象外にするのではなく MaxNodeLimit を大きくしてコンパイルを通してしまうということも考えられます。
実行している Java プログラムの変更が可能なのであれば、問題のコードをもっと簡略化するという方法もありますね。
十分テストしてからの判断になると思いますが、実害がなければデフォルトの設定のままで良いのではないかと個人的には思いました。