JJUG CCC 2018 Fallのセッション、GCを発生させないJVMとコーディングスタイルにて、GCの発生を抑えるアプリケーション側の対処として、以下のことをするケースもある、とありました。
（https://www.slideshare.net/kenjikazumura/gcjvm より抜粋）
String#internは、こういうメソッドです。
「internメソッドが呼び出されたときに、equals(Object)メソッドによってこのStringオブジェクトに等しいと判定される文字列がプールにすでにあった場合は、プール内の該当する文字列が返されます。」
同一内容の文字列なら、プールにあるものを使います。すなわち、メモリ領域の節約という観点からでは、intern()を使えば、GC回数を減らせるのではないか、ということです。
そのとき、Red Hat社のAlekseyさんの個人サイトに、String#intern()の話があったなあ、と思い出しました。
JVM Anatomy Park #10: String.intern()
知識としては持っているけれども、ここに書かれている内容を試したことはありません。なぞりながら、実行してみることにします。
スループット
まずは、Alekseyさんのエントリにある、JMH (Java Microbenchmark Harness) のコードを実行します。JMHについてご存じない方は、ばふぁさんのすばらしいブログエントリがおすすめです。
文字列をキャッシュから取得するケースで、String#intern()で取得するパターン、HashMapをキャッシュ先として作り、そこから取得するパターン、ConcurrentHashMapで同様にするパターンの3つです。
その3パターンに対して、文字列の個数を、1、100、10000、1000000の4パターンで実行します。合計、3 * 4の12パターンが計測できます。
@State(Scope.Benchmark) @BenchmarkMode(Mode.Throughput) public class StringIntern { @Param({"1", "100", "10000", "1000000"}) private int size; private StringInterner str; private CHMInterner chm; private HMInterner hm; @Setup public void setup() { str = new StringInterner(); chm = new CHMInterner(); hm = new HMInterner(); } public static class StringInterner { public String intern(String s) { return s.intern(); } } @Benchmark public void intern(Blackhole bh) { for (int c = 0; c < size; c++) { bh.consume(str.intern("String" + c)); } } public static class CHMInterner { private final Map<String, String> map; public CHMInterner() { map = new ConcurrentHashMap<>(); } public String intern(String s) { String exist = map.putIfAbsent(s, s); return (exist == null) ? s : exist; } } @Benchmark public void chm(Blackhole bh) { for (int c = 0; c < size; c++) { bh.consume(chm.intern("String" + c)); } } public static class HMInterner { private final Map<String, String> map; public HMInterner() { map = new HashMap<>(); } public String intern(String s) { String exist = map.putIfAbsent(s, s); return (exist == null) ? s : exist; } } @Benchmark public void hm(Blackhole bh) { for (int c = 0; c < size; c++) { bh.consume(hm.intern("String" + c)); } } }
今回、マシンスペックが決定要因にはならないと考えていますが、以下の環境で実行しました。
- MacBook Pro (13-inch, 2017)
- CPU 3.1 GHz Intel Core i5
- メモリ 16 GB 2133 MHz LPDDR3
- VirtualBox上のUbuntu 14.04 LTS
- JDK 11.0.1, OpenJDK 64-Bit Server VM, 11.0.1+13
java -jar benchmark.jarで実行します。
Benchmark (size) Mode Cnt Score Error Units StringIntern.chm 1 thrpt 25 3825042.597 ± 296523.249 ops/s StringIntern.chm 100 thrpt 25 38813.343 ± 5417.572 ops/s StringIntern.chm 10000 thrpt 25 273.596 ± 44.451 ops/s StringIntern.chm 1000000 thrpt 25 1.836 ± 0.298 ops/s StringIntern.hm 1 thrpt 25 5058115.030 ± 694904.258 ops/s StringIntern.hm 100 thrpt 25 50526.452 ± 9690.127 ops/s StringIntern.hm 10000 thrpt 25 553.058 ± 18.948 ops/s StringIntern.hm 1000000 thrpt 25 3.799 ± 0.077 ops/s StringIntern.intern 1 thrpt 25 2334328.135 ± 75208.885 ops/s StringIntern.intern 100 thrpt 25 23079.788 ± 552.900 ops/s StringIntern.intern 10000 thrpt 25 199.286 ± 7.376 ops/s StringIntern.intern 1000000 thrpt 25 0.197 ± 0.012 ops/s
String#intern()を使うパターンは、すべてスループットが低く出ました。つまり、intern()を使うと、メモリは節約できるかもしれないが、スループットは落ちるということです。
Alekseyさんがperfで見ているので、私も見ます。JMHでなくてよいだろうと考え、ループでString#intern()するクラスを作りました。perfはLinuxの性能解析ツールです。私、使うのは初めてだったりします。perfをインストールし、言われるがままに設定値を変えました。
public class CallIntern { public static void main(String[] args) { String s1 = "Hello, World!"; for (int i = 0; i < 10000; i++) { System.out.println((s1 + i).intern()); } } }
sudo apt-get install linux-tools-3.13.0-24-generic linux-cloud-tools-3.13.0-24-generic linux-tools-common sudo sysctl -w kernel.kptr_restrict=0 sudo sysctl -w kernel.perf_event_paranoid=0
perf record -g java CallInternで実行したあと、perf report -g -Gします。
- 1.07% java libjvm.so [.] StringTable::do_intern(Handle, unsigned short*, int, unsigned long, Thread*)
- start_thread
- JavaMain
- 87.50% jni_CallStaticVoidMethod
jni_invoke_static(JNIEnv_*, JavaValue*, _jobject*, JNICallType, _jmethodID*, JNI_ArgumentPusher*, Thread*) [clone .isra.65] [clone .constprop.193]
JavaCalls::call_helper(JavaValue*, methodHandle const&, JavaCallArguments*, Thread*)
0x7f34c8c5c849
- 0x7f34c8c659c0
- 85.71% 0x7f34d07335e9
- JVM_InternString
- 83.33% StringTable::intern(oopDesc*, Thread*)
StringTable::do_intern(Handle, unsigned short*, int, unsigned long, Thread*)
16.67% StringTable::do_intern(Handle, unsigned short*, int, unsigned long, Thread*)
StringTable::do_intern()が、それなりの割合を占めており、パフォーマンスに影響を及ぼしているとわかります。名前からして、String#intern()に関係していそうです。内部は、jni_CallStaticVoidMethod、つまりJNI呼び出しで、さらにJVM_InternStringが呼び出されます。つまり、intern()は呼び出しの度に、JVMに対して問い合わせをしているのです。パフォーマンスへの影響は、大きくないとしても、あります。
StringTable::do_intern()とString#intern()の関係を、ソースを見て確かめます。Stringクラスです。こちらのブログエントリも、大変参考になりました。
【Java】なぜ文字列リテラルは演算子で比較できる時があるのか
public native String intern();
intern()はネイティブメソッドです。OpenJDKのソースで、ネイティブ実装を見ます。src/java.base/share/native/libjava/String.cです。
#include "jvm.h" #include "java_lang_String.h" JNIEXPORT jobject JNICALL Java_java_lang_String_intern(JNIEnv *env, jobject this) { return JVM_InternString(env, this); }
JVM_InternStringを見ます。src/hotspot/share/prims/jvm.cppです。
// String support /////////////////////////////////////////////////////////////////////////// JVM_ENTRY(jstring, JVM_InternString(JNIEnv *env, jstring str)) JVMWrapper("JVM_InternString"); JvmtiVMObjectAllocEventCollector oam; if (str == NULL) return NULL; oop string = JNIHandles::resolve_non_null(str); oop result = StringTable::intern(string, CHECK_NULL); return (jstring) JNIHandles::make_local(env, result); JVM_END
StringTable::intern(string, CHECK_NULL)がありました。StringTableを見ましょう。src/hotspot/share/classfile/stringTable.cppです。
oop StringTable::intern(oop string, TRAPS) {
if (string == NULL) return NULL;
ResourceMark rm(THREAD);
int length;
Handle h_string (THREAD, string);
jchar* chars = java_lang_String::as_unicode_string(string, length,
CHECK_NULL);
oop result = intern(h_string, chars, length, CHECK_NULL);
return result;
}
oop StringTable::intern(Handle string_or_null_h, jchar* name, int len, TRAPS) {
// shared table always uses java_lang_String::hash_code
unsigned int hash = java_lang_String::hash_code(name, len);
oop found_string = StringTable::the_table()->lookup_shared(name, len, hash);
if (found_string != NULL) {
return found_string;
}
if (StringTable::_alt_hash) {
hash = hash_string(name, len, true);
}
return StringTable::the_table()->do_intern(string_or_null_h, name, len,
hash, CHECK_NULL);
}
オーバーロードした関数を呼び出しており、その中でdo_intern()を呼び出しています。バッチリです。
ではなぜ、String#intern()を呼び出すと、StringTable::intern()を通じてスループットが落ちたのでしょうか。OpenJDKには、StringTableに関するオプションがあるので、それを使って見ていきます。
$ java -XX:+PrintFlagsFinal -version | grep -i stringtable
bool PrintStringTableStatistics = false {product} {default}
uintx StringTableSize = 65536 {product} {default}
PrintStringTableStatisticsを付けて、CallInternを実行しました。結果がわかりやすくなるように、ループ回数を100万回に増やしました。
$ java -XX:+PrintStringTableStatistics CallIntern
すると…
クラッシュ
なんとクラッシュしました。
# # A fatal error has been detected by the Java Runtime Environment: # # SIGSEGV (0xb) at pc=0x00007fdf4be18e2d, pid=10646, tid=10647 # # JRE version: OpenJDK Runtime Environment (11.0.1+13) (build 11.0.1+13) # Java VM: OpenJDK 64-Bit Server VM (11.0.1+13, mixed mode, tiered, compressed oops, serial gc, linux-amd64) # Problematic frame: # V [libjvm.so+0xbe9e2d] Monitor::try_lock()+0x1d # # Core dump will be written. Default location: Core dumps may be processed with "/usr/share/apport/apport %p %s %c %P" (or dumping to /home/jyukutyo/core.10646) # # An error report file with more information is saved as: # /home/jyukutyo/hs_err_pid10646.log # # If you would like to submit a bug report, please visit: # http://bugreport.java.com/bugreport/crash.jsp # Aborted (core dumped)
Oracle JDK 8, 9, 10あたりではクラッシュしません。OpenJDK 12でもクラッシュします。バグレポートか！？と意気込みましたが、JDK Bug Systemにすでにありました。
[JDK-8211821] PrintStringTableStatistics crashes JVM - Java Bug System
OpenJDK 10で実行
- JDK 10.0.2, OpenJDK 64-Bit Server VM, 10.0.2+13
$ java -XX:+PrintStringTableStatistics CallIntern StringTable statistics: Number of buckets : 60013 = 480104 bytes, each 8 Number of entries : 286131 = 6867144 bytes, each 24 Number of literals : 286131 = 18325312 bytes, avg 64.045 Total footprint : = 25672560 bytes Average bucket size : 4.768 Variance of bucket size : 2.611 Std. dev. of bucket size: 1.616 Maximum bucket size : 11
Average bucket sizeが、4.768です。そもそも、StringTableは、ネイティブメモリ内にある、固定サイズのhashtableです。そのhashtableが配列を保持しており、配列の各要素をbucketと呼びます。bucket sizeの数は、コリジョンによるチェイニングによって増えます。つまり、Average bucket sizeが4強もあるのは、それなりにコリジョンが発生しており、パフォーマンスに影響を与えているのです。
これを回避する上で、もう1つのオプションを使うこともできます。
$ java -XX:+PrintFlagsFinal -version | grep -i stringtable
bool PrintStringTableStatistics = false {product} {default}
uintx StringTableSize = 65536 {product} {default}
StringTableSizeです。許容される最大サイズ、6661443にして実行してみます。
$ java -XX:+PrintStringTableStatistics -XX:StringTableSize=6661443 CallIntern StringTable statistics: Number of buckets : 6661443 = 53291544 bytes, each 8 Number of entries : 286119 = 6866856 bytes, each 24 Number of literals : 286119 = 18324568 bytes, avg 64.045 Total footprint : = 78482968 bytes Average bucket size : 0.043 Variance of bucket size : 0.043 Std. dev. of bucket size: 0.206 Maximum bucket size : 2
Average bucket sizeが0近くになりました。改善できているようです。JMHもこのオプションをつけて、再度実行します。
Benchmark (size) Mode Cnt Score Error Units StringIntern.intern 1 thrpt 25 5996252.895 ± 1195020.397 ops/s StringIntern.intern 100 thrpt 25 10804.414 ± 877.241 ops/s StringIntern.intern 10000 thrpt 25 142.231 ± 25.777 ops/s StringIntern.intern 1000000 thrpt 25 0.424 ± 0.044 ops/s
オプションなしで以前実行したものは、以下です。100万回のケースは、スループットが向上しています。
StringIntern.intern 1 thrpt 25 2334328.135 ± 75208.885 ops/s StringIntern.intern 100 thrpt 25 23079.788 ± 552.900 ops/s StringIntern.intern 10000 thrpt 25 199.286 ± 7.376 ops/s StringIntern.intern 1000000 thrpt 25 0.197 ± 0.012 ops/s
ただし、前述のとおり、StringTableは固定サイズのhashtableです。サイズを増やせばパフォーマンスは向上しますが、その分ネイティブメモリを確保してしまいます。ヒープは節約できますが、ネイティブメモリの使用量が増えます。
ネイティブ・メモリー・トラッキング (NMT) で見てみました。
StringTableSizeの設定なし。
java -XX:NativeMemoryTracking=detail -Xmx1g -Xms1g CallIntern
- Symbol (reserved=9300KB, committed=9300KB)
(malloc=8940KB #522599)
(arena=360KB #1)
- Native Memory Tracking (reserved=8696KB, committed=8696KB)
(malloc=173KB #2458)
(tracking overhead=8523KB)
StringTableSize=6661443の設定あり。
java -XX:StringTableSize=6661443 -XX:NativeMemoryTracking=detail -Xmx1g -Xms1g CallIntern
- Symbol (reserved=75794KB, committed=75794KB)
(malloc=75434KB #616705)
(arena=360KB #1)
- Native Memory Tracking (reserved=10191KB, committed=10191KB)
(malloc=176KB #2489)
(tracking overhead=10016KB)
大きく差異があったのは、Symbolの項目でした。75794KB - 9300KB = 約66MB違います。他の項目は同じでした。Symbolはシンボルの保持領域なのでしょうが、詳細は調べていません。
GCポーズタイム
もう1つの問題は、StringTableはGCのルートになってしまうことです。AlekseyさんはShenandoahとCMSで試されています。私も、と思ったのですが、build 12-ea+25では、まだShenandoahが入っていなさそうでした。
$ java -version openjdk version "12-ea" 2019-03-19 OpenJDK Runtime Environment (build 12-ea+25) OpenJDK 64-Bit Server VM (build 12-ea+25, mixed mode, sharing) $ java -XX:+UnlockExperimentalVMOptions -XX:+UseShenandoahGC -Xmx1g -Xms1g CallIntern Error occurred during initialization of VM Option -XX:+UseShenandoahGC not supported
G1GC
なので、11.0.1のまま、試します。デフォルトなので、G1GCを使います。
java -Xlog:gc*=trace -Xmx1g -Xms1g CallIntern [4.315s][trace][gc,phases ] GC(0) StringTable Roots (ms): Min: 36.6, Avg: 36.9, Max: 37.2, Diff: 0.5, Sum: 73.8, Workers: 2 [4.315s][trace][gc,phases,task ] GC(0) 37.2 36.6 [8.234s][trace][gc,phases ] GC(1) StringTable Roots (ms): Min: 26.3, Avg: 28.0, Max: 29.7, Diff: 3.4, Sum: 56.1, Workers: 2 [8.234s][trace][gc,phases,task ] GC(1) 29.7 26.3 [12.299s][trace][gc,phases ] GC(2) StringTable Roots (ms): Min: 22.4, Avg: 24.7, Max: 27.0, Diff: 4.6, Sum: 49.5, Workers: 2 [12.299s][trace][gc,phases,task ] GC(2) 27.0 22.4
java -XX:StringTableSize=6661443 -Xlog:gc*=trace -Xmx1g -Xms1g CallIntern [3.979s][trace][gc,phases ] GC(0) StringTable Roots (ms): Min: 20.0, Avg: 21.0, Max: 22.1, Diff: 2.0, Sum: 42.1, Workers: 2 [3.979s][trace][gc,phases,task ] GC(0) 22.1 20.0 [7.007s][trace][gc,phases ] GC(1) StringTable Roots (ms): Min: 29.0, Avg: 32.8, Max: 36.6, Diff: 7.6, Sum: 65.6, Workers: 2 [7.007s][trace][gc,phases,task ] GC(1) 36.6 29.0 [10.112s][trace][gc,phases ] GC(2) StringTable Roots (ms): Min: 29.1, Avg: 33.7, Max: 38.2, Diff: 9.1, Sum: 67.3, Workers: 2 [10.112s][trace][gc,phases,task ] GC(2) 38.2 29.1
それほど変化がないように見えます。ClassUnloadingWithConcurrentMarkを無効にしてみます。
java -XX:-ClassUnloadingWithConcurrentMark -XX:StringTableSize=6661443 -Xlog:gc*=trace -Xmx1g -Xms1g CallIntern [4.175s][trace][gc,phases ] GC(0) StringTable Roots (ms): Min: 16.9, Avg: 21.5, Max: 26.1, Diff: 9.1, Sum: 43.0, Workers: 2 [4.175s][trace][gc,phases,task ] GC(0) 26.1 16.9 [7.481s][trace][gc,phases ] GC(1) StringTable Roots (ms): Min: 27.0, Avg: 44.9, Max: 62.7, Diff: 35.7, Sum: 89.7, Workers: 2 [7.481s][trace][gc,phases,task ] GC(1) 62.7 27.0 [10.863s][trace][gc,phases ] GC(2) StringTable Roots (ms): Min: 32.3, Avg: 35.1, Max: 38.0, Diff: 5.7, Sum: 70.3, Workers: 2 [10.863s][trace][gc,phases,task ] GC(2) 38.0 32.3
影響が出ていると言えるか微妙ですが、設定なしと、-XX:-ClassUnloadingWithConcurrentMark -XX:StringTableSize=6661443であれば、違いがあると言えそうです。JVMがロードしたクラスは、internするStringの対象となります。そのため、不要なクラスをアンロードする仕組みは、StringTableが保持するStringオブジェクトのクリーンナップにもなります。
G1には他に、JEP 192: String Deduplication in G1もあります。これはデフォルトでは無効なので、今回は関係がないです。さらに、internはStringオブジェクトそのものに関するものですが、deduplicationは内部の配列に関するもので、JVMでは内部的に異なるテーブルを使っています。
CMS
今やdeprecatedですが、CMSも試します。
java -XX:+UseConcMarkSweepGC -XX:StringTableSize=6661443 -Xlog:gc:cms1.log -Xmx64m -Xms64m CallIntern [0.003s][info][gc] Using Concurrent Mark Sweep [2.490s][info][gc] GC(0) Pause Young (Allocation Failure) 17M->7M(61M) 84.562ms [4.992s][info][gc] GC(1) Pause Young (Allocation Failure) 24M->14M(61M) 16.707ms [7.651s][info][gc] GC(2) Pause Young (Allocation Failure) 31M->21M(61M) 13.323ms [11.041s][info][gc] GC(3) Pause Young (Allocation Failure) 38M->28M(61M) 66.660ms [11.042s][info][gc] GC(4) Pause Initial Mark 28M->28M(61M) 0.807ms [11.042s][info][gc] GC(4) Concurrent Mark [11.044s][info][gc] GC(4) Concurrent Mark 1.842ms [11.044s][info][gc] GC(4) Concurrent Preclean [11.044s][info][gc] GC(4) Concurrent Preclean 0.181ms [11.061s][info][gc] GC(4) Pause Remark 28M->28M(61M) 16.670ms [11.063s][info][gc] GC(4) Concurrent Sweep [11.161s][info][gc] GC(4) Concurrent Sweep 97.966ms [11.161s][info][gc] GC(4) Concurrent Reset [11.167s][info][gc] GC(4) Concurrent Reset 6.180ms [13.316s][info][gc] GC(5) Pause Young (Allocation Failure) 20M->10M(61M) 21.576ms [15.252s][info][gc] GC(6) Pause Young (Allocation Failure) 27M->17M(61M) 51.479ms [17.839s][info][gc] GC(7) Pause Young (Allocation Failure) 34M->24M(61M) 55.263ms [20.128s][info][gc] GC(8) Pause Young (Allocation Failure) 41M->31M(61M) 61.305ms [20.146s][info][gc] GC(9) Pause Initial Mark 31M->31M(61M) 0.593ms [20.147s][info][gc] GC(9) Concurrent Mark [20.148s][info][gc] GC(9) Concurrent Mark 1.019ms [20.148s][info][gc] GC(9) Concurrent Preclean [20.148s][info][gc] GC(9) Concurrent Preclean 0.046ms [20.157s][info][gc] GC(9) Pause Remark 31M->31M(61M) 9.622ms [20.157s][info][gc] GC(9) Concurrent Sweep [20.230s][info][gc] GC(9) Concurrent Sweep 72.793ms [20.230s][info][gc] GC(9) Concurrent Reset [20.230s][info][gc] GC(9) Concurrent Reset 0.058ms [22.580s][info][gc] GC(10) Pause Young (Allocation Failure) 20M->10M(61M) 73.064ms
-XX:-ClassUnloadingを付けて、クラスのアンロードを無効にして実行します。
java -XX:-ClassUnloading -XX:+UseConcMarkSweepGC -XX:StringTableSize=6661443 -Xlog:gc:cms2.log -Xmx64m -Xms64m CallIntern [0.003s][info][gc] Using Concurrent Mark Sweep [2.400s][info][gc] GC(0) Pause Young (Allocation Failure) 17M->7M(61M) 36.391ms [4.906s][info][gc] GC(1) Pause Young (Allocation Failure) 24M->14M(61M) 20.755ms [7.555s][info][gc] GC(2) Pause Young (Allocation Failure) 31M->21M(61M) 23.173ms [9.704s][info][gc] GC(3) Pause Young (Allocation Failure) 38M->28M(61M) 62.196ms [9.714s][info][gc] GC(4) Pause Initial Mark 28M->28M(61M) 7.120ms [9.714s][info][gc] GC(4) Concurrent Mark [9.756s][info][gc] GC(4) Concurrent Mark 41.800ms [9.756s][info][gc] GC(4) Concurrent Preclean [9.756s][info][gc] GC(4) Concurrent Preclean 0.066ms [9.796s][info][gc] GC(4) Pause Remark 28M->28M(61M) 39.558ms [9.796s][info][gc] GC(4) Concurrent Sweep [9.907s][info][gc] GC(4) Concurrent Sweep 111.484ms [9.908s][info][gc] GC(4) Concurrent Reset [9.913s][info][gc] GC(4) Concurrent Reset 5.054ms [12.126s][info][gc] GC(5) Pause Young (Allocation Failure) 45M->35M(61M) 22.664ms [12.132s][info][gc] GC(6) Pause Initial Mark 35M->35M(61M) 4.907ms [12.132s][info][gc] GC(6) Concurrent Mark [12.224s][info][gc] GC(6) Concurrent Mark 92.310ms [12.225s][info][gc] GC(6) Concurrent Preclean [12.225s][info][gc] GC(6) Concurrent Preclean 0.086ms [12.231s][info][gc] GC(6) Pause Remark 35M->35M(61M) 6.628ms [12.231s][info][gc] GC(6) Concurrent Sweep [12.295s][info][gc] GC(6) Concurrent Sweep 63.765ms [12.295s][info][gc] GC(6) Concurrent Reset [12.295s][info][gc] GC(6) Concurrent Reset 0.064ms [14.309s][info][gc] GC(7) Pause Initial Mark 49M->49M(61M) 13.711ms [14.310s][info][gc] GC(7) Concurrent Mark [14.344s][info][gc] GC(7) Concurrent Mark 33.979ms [14.344s][info][gc] GC(7) Concurrent Preclean [14.344s][info][gc] GC(7) Concurrent Preclean 0.054ms [14.344s][info][gc] GC(7) Concurrent Abortable Preclean [14.722s][info][gc] GC(8) Pause Young (Allocation Failure) 52M->41M(61M) 16.577ms [14.812s][info][gc] GC(7) Concurrent Abortable Preclean 468.732ms [14.821s][info][gc] GC(7) Pause Remark 42M->42M(61M) 8.285ms [14.829s][info][gc] GC(7) Concurrent Sweep [14.928s][info][gc] GC(7) Concurrent Sweep 99.329ms [14.928s][info][gc] GC(7) Concurrent Reset [14.928s][info][gc] GC(7) Concurrent Reset 0.068ms [16.755s][info][gc] GC(10) Pause Full (Allocation Failure) 59M->0M(61M) 88.766ms [16.755s][info][gc] GC(9) Pause Young (Allocation Failure) 59M->0M(61M) 88.912ms [19.135s][info][gc] GC(11) Pause Young (Allocation Failure) 17M->8M(61M) 75.856ms [21.403s][info][gc] GC(12) Pause Young (Allocation Failure) 25M->15M(61M) 61.034ms
[16.755s][info][gc] GC(10) Pause Fullで、フルGCが走っています。クラスのアンロードを無効にしたことで、アンロードできるはずのクラス関連のinternした文字列を、ヒープから削除できないため、ヒープが一杯になってフルGCと考えられます。また、今回はヒープが64MBなので、フルGCの時間、つまりSTWする時間は長くありませんが、ヒープサイズが大きくなるにつれて、STWの時間は長くなるでしょう。
まとめ
String#intern()だけで、長いエントリになってしまいました。理解が深まった反面、新たに調べたいことも出てきました。理解した、というのがどういう状態なのか、自分でよくわからなくなってきました。あることを知ったとき、それを構成する部分部分には、つねにわからないことが含まれるからです。だいたいわかっているつもりだが、詳細に関してはわからない、という状態でしょうか。
AlekseyさんのJVM Anatomy Parkは、とてもおもしろいので、おすすめです。やはり、内容を自分でも動かしてみた方が、手間と時間はかかりますが、理解が深まる感じがします。internと同様に、TLABについても、頭でしか理解していないと感じがするので、今後のエントリで同じようにやってみます。
