2016-07-26 15 views
1

GC用にCMSを使用していますが、2ヶ月ごとにCPU使用率が非常に高くなります。GC(CMS)のパラメータを調整します

状況が悪化したときにGCログが1つあります。長いSTWがあります。

3519696.386: [GC [1 CMS-initial-mark: 8617524K(12582912K)] 17105967K(23907584K), 4.9369140 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 
3519701.324: [CMS-concurrent-mark-start] 
3519709.419: [CMS-concurrent-mark: 8.096/8.096 secs] [Times: user=16.17 sys=0.00, real=8.09 secs] 
3519709.420: [CMS-concurrent-preclean-start] 
3519709.442: [CMS-concurrent-preclean: 0.023/0.023 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
3519709.442: [CMS-concurrent-abortable-preclean-start] 
CMS: abort preclean due to time 3519714.691: [CMS-concurrent-abortable-preclean: 3.345/5.248 secs] [Times: user=3.36 sys=0.00, real=5.25 secs] 
3519714.692: [GC[YG occupancy: 8489655 K (11324672 K)]3519714.692: [Rescan (parallel) , 8.4072250 secs]3519723.099: [weak refs processing, 0.0000190 secs]3519723.099: [scrub string table, 0.0008130 secs] [1 CMS-remark: 8617524K(12582912K)] 17107180K(23907584K), 8.4081940 secs] [Times: user=65.71 sys=0.15, real=8.41 secs] 
3519723.100: [CMS-concurrent-sweep-start] 
3519725.451: [CMS-concurrent-sweep: 2.350/2.350 secs] [Times: user=2.36 sys=0.00, real=2.35 secs] 
3519725.451: [CMS-concurrent-reset-start] 
3519725.478: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
3519727.480: [GC [1 CMS-initial-mark: 8617522K(12582912K)] 17107229K(23907584K), 4.9378950 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 
3519732.418: [CMS-concurrent-mark-start] 

マイGCパラメータ:

java -server -Xmx24g -Xms24g -XX:NewSize=12g -XX:MaxNewSize=12g -XX:+HeapDumpOnOutOfMemoryError -XX:MaxDirectMemorySize=24g -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:ReservedCodeCacheSize=128m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:CMSInitiatingOccupancyFraction=68 

私のサーバー上にインストール9つのCPUと64Gメモリがあります。

なぜ月に悪化するのかを理解するのに役立つでしょうか?

+0

リークやファイナライズの問題があるかどうかをビジュアルで確認しましたか? –

+0

@ThorbjørnRavnAndersenそれを作るためのツールはありますか? – Junjie

+0

Visualvmはjdkディストリビューションの一部です。 –

答えて

4

これで詳細を少し見てみましょう。最初はすべての時間がsysではなくユーザにあるように見えるので、主な疑惑はJVMとアプリケーションです。

GCは古い世代でトリガーされます。占有面積は8617524Kで、容量は12582912Kです。合計ヒープ使用量は17105967K、サイズは23907584Kです。

初期マークは~5秒かかる。

3519696.386: [GC [1 CMS-initial-mark: 8617524K(12582912K)] 17105967K(23907584K), 4.9369140 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 

AFAIK初期マークはGCルーツのみを処理します。あなたはこれらがどれであるかを見ることができますhere、しかしそれはあまりにも多くを取っているという事実は奇妙です。私の最初の疑惑は、これはsafepointsまでの時間によって影響されることが可能なので、多分可能にする:

-XX:+ PrintSafepointStatisticsは-XX:PrintSafepointStatisticsCount = 1

コンカレントマークフェーズが8S

3519709.419: [CMS-concurrent-mark: 8.096/8.096 secs] [Times: user=16.17 sys=0.00, real=8.09 secs] 

を取りますこれはライブオブジェクトをスキャンしています

プリクリーンは比較的高速です。

アボート可能なプリクリーニングは、5秒でキャンセルされます。AFAIKは、CMSMaxAbortablePrecleanTimeで設定可能です。このオプションを掘り下げてみると、この段階でマイナーコレクションを持つことが望ましいことがわかります。そうしなければ、CMSに大きな休止が生じる可能性があります。 CMSMaxAbortablePrecleanTimeを増やし、CMSScavengeBeforeRemarkをアクティブにします。この記事をJon Masamitsuでチェックしてください。

若者の世代は8Gで、再スキャンには8秒かかりました。再び同じコメントが返されます。安全ポイント。

3519714.692:[GC [YG占有:8489655 K(11324672 K)] 3519714.692:[再スキャン(平行)、8.4072250秒] 3519723.099:[弱参考文献処理、0.0000190秒] 3519723.099:[スクラブ文字列テーブル、0.0008130秒] [1 CMS-remark:8617524K(12582912K)] 17107180K(23907584K)、8.4081940秒] [時間:user = 65.71 sys = 0.15、real = 8.41 secs]

実際にこの期間に増加したサイズ:8617524K

同時スイープでの最終的なクリーンアップには2.35秒かかり、ヒープの内容は大幅に変化していないようです。あなたはまだおおよそ同じ若者とヒープの使用法を持っています。

は、だから私は2つの点を参照まとめ:

  • あなたのヒープを使用すると、CMSInitiatingOccupancyFractionに達し、CMSをトリガしている、大規模である、と多くの時間を生きているオブジェクトをスキャンする上で行くことのようです。いずれにしても、これが改善できるかどうかを確認するためには、
    • あなたは長命オブジェクトの多く(例えば:キャッシュ)を維持したい:あなたはこれらのいずれかの状況で、おそらくですので
    • GCは本当に多く収集することはありません。この場合、CMSInitiatingOccuppancyFractionを増やしたいとします(古いgenが非常に満杯になると予想します)。しかし、最終的には(1日か2か月以内に)長いGCにつながるので、あなたは中期または短命のオブジェクトを宣伝しないように注意してください。それは、古い世代での解約を避けることです。
    • 多くの短中期のオブジェクトを生成しているため、プロモーションを避ける必要があります。割り当てを減らし、Edenを増やしてください。

のアプリについての任意の詳細などは、間違いなく、爪それをよりよく役立つだろう。それが少し助けてくれることを願っています

1

ログには、通常の若いGCは表示されません。 CMS Stop-the-Worldのフェーズは、若いスペースコレクションを有効にするためにピギーバックするように設計されています。

3519727.480: [GC [1 CMS-initial-mark: 8617522K(12582912K)] 17107229K(23907584K), 4.9378950 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 

ここでCMS-initial-markは、1つのスレッドで8.6 GiBの空き領域をスキャンする必要があります。それが若いGCの若い宇宙占領直後に呼び出されるのであれば、それは一桁小さい。

CMS-remarkと同じです。

若者は大きな若い空間を持っているので、あなたは古い空間が若い空間よりも頻繁に収集されるようになります。ここで

  • -XX:CMSWaitDuration=3600000ことを改善するために、いくつかのオプションがありCMS-initial-markは、次の若いGCまで一時間まで待ってみましょう。
  • -XX:+CMSScavengeBeforeRemarkCMS-remarkを強制的に若いコレクションに予測可能な休止時間を生成させます。パラレルCMS-initial-mark

詳細を持っている

  • 使用最新のJava 7/8はthis articleでご利用いただけます。