javacのバグのせいでずっとJDK1.8.0_20以降へ乗り換え出来ずにいたわけですが、
(参考: http://takahashikzn.hatenablog.com/entry/2014/10/15/204657 )
とうとう諦めて、このバグを回避するようソースを全面的を書き換えることにしました。
書き換えた内容は、概ね
<T extends Enum<T> & SomeInterface<T>> T someProc(Class<T> type);
のような箇所です。どうやら、
のようなコードを書くとアウトっぽい。但し必ずアウトというわけではなく、コンパイルできるケースもあります。
解決策ですが、Enumの型合成をやめるとコンパイルできるようになりました。
本題
丸1日を上記修正に当て、やっとJDK1.8.0_25を使うことが出来るようになりました。
早速、JVMのオプションに
-XX:+UseStringDeduplication -XX:+PrintStringDeduplicationStatistics
を指定して自作ベンチマークアプリを実行。
自作ベンチマークアプリの概要ですが、
- 弊社が担当した、実運用中の業務Webアプリ
- ユースケース数158、画面数231。ステップ数は20万行以上*1
- （性能測定とは関係ないが）帳票数150
- この業務用Webアプリの結合テストとしてのSeleniumテストケース
- 約500個のテストスイート、全実行に60分を要する
- 性質上、測定できるのはシングルスレッド性能のみ
といったところです。Seleniumベースですので正確な性能測定はできませんが、今回はUseStringDeduplicationの効果測定が目的です。
ありがちな「ベンチマークのためのアプリケーション」ではなく実アプリケーションを使用しているため、より現実的な数字が出ると思います。
ちなみに、この業務用Webアプリのコードの99%は弊社製品MOD99で自動生成しました。
[ここにアナタが想像するドヤ顔を入れて下さい]
測定結果
平均的な内容を抜き出してきたのが以下。
[GC concurrent-string-deduplication, 87.0K->1968.0B(85.1K), avg 55.6%, 0.0003136 secs]
[Last Exec: 0.0003136 secs, Idle: 0.1422424 secs, Blocked: 0/0.0000000 secs]
[Inspected: 415]
[Skipped: 0( 0.0%)]
[Hashed: 297( 71.6%)]
[Known: 1( 0.2%)]
[New: 414( 99.8%) 87.0K]
[Deduplicated: 390( 94.2%) 85.1K( 97.8%)]
[Young: 390(100.0%) 85.1K(100.0%)]
[Old: 0( 0.0%) 0.0B( 0.0%)]
[Total Exec: 786/0.4695493 secs, Idle: 786/1932.3643624 secs, Blocked: 179/0.0479712 secs]
[Inspected: 1277420]
[Skipped: 0( 0.0%)]
[Hashed: 498483( 39.0%)]
[Known: 96434( 7.5%)]
[New: 1180986( 92.5%) 140.1M]
[Deduplicated: 916964( 77.6%) 77.8M( 55.6%)]
[Young: 546871( 59.6%) 43.9M( 56.4%)]
[Old: 370093( 40.4%) 34.0M( 43.6%)]
[Table]
[Memory Usage: 8600.4K]
[Size: 262144, Min: 1024, Max: 16777216]
[Entries: 279567, Load: 106.6%, Cached: 0, Added: 348577, Removed: 69010]
[Resize Count: 8, Shrink Threshold: 174762(66.7%), Grow Threshold: 524288(200.0%)]
[Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0x0]
[Age Threshold: 3]
[Queue]
[Dropped: 0]その5分後のログ。これはベンチマークアプリ終了直前のタイミングです。
[GC concurrent-string-deduplication, 334.5K->202.6K(131.9K), avg 55.1%, 0.0019967 secs]
[Last Exec: 0.0019967 secs, Idle: 8.6809495 secs, Blocked: 0/0.0000000 secs]
[Inspected: 6872]
[Skipped: 0( 0.0%)]
[Hashed: 2490( 36.2%)]
[Known: 1363( 19.8%)]
[New: 5509( 80.2%) 334.5K]
[Deduplicated: 2459( 44.6%) 131.9K( 39.4%)]
[Young: 2459(100.0%) 131.9K(100.0%)]
[Old: 0( 0.0%) 0.0B( 0.0%)]
[Total Exec: 927/0.5042536 secs, Idle: 927/2434.7128594 secs, Blocked: 179/0.0479712 secs]
[Inspected: 1334587]
[Skipped: 0( 0.0%)]
[Hashed: 533158( 39.9%)]
[Known: 98374( 7.4%)]
[New: 1236213( 92.6%) 148.7M]
[Deduplicated: 960772( 77.7%) 81.9M( 55.1%)]
[Young: 589843( 61.4%) 47.9M( 58.5%)]
[Old: 370929( 38.6%) 34.0M( 41.5%)]
[Table]
[Memory Usage: 8728.7K]
[Size: 262144, Min: 1024, Max: 16777216]
[Entries: 285042, Load: 108.7%, Cached: 0, Added: 361869, Removed: 76827]
[Resize Count: 8, Shrink Threshold: 174762(66.7%), Grow Threshold: 524288(200.0%)]
[Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0x0]
[Age Threshold: 3]
[Queue]
[Dropped: 0]このログはマイナーGC毎に出力されます。2つめのログの意味は次の通り。
- 前回のマイナーGCから今回のマイナーGCまでに334.5Kbyteの文字列がnewされた
- 今回の文字列重複除去で131.9Kが削減された
- 通算で、文字列重複除去は927回実行された
- 文字列の統計は以下の通り
- 調査済文字列: およそ133万
- ハッシュ計算済: およそ53万
- 文字列重複除去の対象(現在): およそ9.8万
- 文字列重複除去の対象外: およそ123万
- 通算で、生成された文字列オブジェクトの77.7%が除去対象になった
- 文字列全体で消費されたメモリの55%を節約した
- アプリの処理が優先されたために、文字列重複除去がスキップされた回数は0回(最後のDropped)
今回のベンチマークアプリは決して小規模の業務システムでなく、本質的に文字列を多用するWebアプリという形態であるにもかかわらず、思っていたよりも文字列が占めるメモリは大したことが無いということがわかります。
個人的な見解
僕の感想は次の通り。
- 普通のWebアプリかつ通常の実行環境ならばそれほどの効果は無い。ただし性能ダウンも無いので気休め程度にはなる
- 億単位の文字列オブジェクトをメモリに乗せておく必要があるような、特殊なアプリなら効果があるかも
- 一つのコンテナに複数アプリをデプロイするような運用なら効果があるかも
*1:コメント行も含めたら50万行以上
