G1 GC - 非常に長い終了時間

Question

G1 GCは終了フェーズで多くの時間を費やすことがあります。あなたが見ることができるように、GCワーカーの平均時間は442.9であり、終了時間は327.3です。 これは、多くのメッセージを処理する高性能の低遅延アプリケーションです。イベント処理データはyong gcによって収集されなければなりません。通常、イベント処理には150ミリ秒を要しません。

HW：X24のIntel（R）Xeonプロセッサ（R）CPU 2.40GHz @ E5-2620 v3は、32ギガバイトMEMは、8GBのMEMは、遊離 JVMオプションがある：-server -XX：+ UseG1GC -XX：MaxGCPauseMillis = 60 -XX ：ParallelGCThreads = 24 -Xmx12g -Xms12g -Xss256k Linuxの2.6.32-696.6.3.el6.x86_64 Javaバージョン "1.8.0_102"

は通常、G1は終了、若いGCポーズが50msので、7GBに新しいサイズを設定します時間はちょうど6msであり、収集間隔は3秒である。

アプリケーションで長寿命のオブジェクトが多数生成された場合、若いポーズが増加し、若いGCサイズが減少することもあります。しかし、その場合、終了時間は同じままです。そして私はなぜ終了時間が非常に劇的に増加するのだろうかと思います。

この一時停止のための大きなシステム時間にも注意してください。通常、GC停止のシステム時間は0〜10msです。これは1秒です。

2017-08-23T13:21:37.690-0400: 1509.022: [GC pause (G1 Evacuation Pause) (young), 0.4474119 secs] 
    [Parallel Time: 443.2 ms, GC Workers: 24] 
     [GC Worker Start (ms): Min: 1509022.9, Avg: 1509023.0, Max: 1509023.4, Diff: 0.4] 
     [Ext Root Scanning (ms): Min: 2.1, Avg: 22.5, Max: 90.4, Diff: 88.3, Sum: 539.7] 
     [Update RS (ms): Min: 0.0, Avg: 2.2, Max: 5.0, Diff: 5.0, Sum: 54.0] 
     [Processed Buffers: Min: 0, Avg: 24.7, Max: 67, Diff: 67, Sum: 592] 
     [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.7] 
     [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
     [Object Copy (ms): Min: 26.1, Avg: 106.1, Max: 435.6, Diff: 409.6, Sum: 2545.3] 
     [Termination (ms): Min: 0.0, Avg: 312.0, Max: 327.3, Diff: 327.3, Sum: 7488.6] 
     [Termination Attempts: Min: 1, Avg: 1.5, Max: 4, Diff: 3, Sum: 36] 
     [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.6] 
     [GC Worker Total (ms): Min: 442.5, Avg: 442.9, Max: 443.0, Diff: 0.5, Sum: 10628.9] 
     [GC Worker End (ms): Min: 1509465.9, Avg: 1509465.9, Max: 1509465.9, Diff: 0.1] 
    [Code Root Fixup: 0.4 ms] 
    [Code Root Purge: 0.0 ms] 
    [Clear CT: 0.3 ms] 
    [Other: 3.6 ms] 
     [Choose CSet: 0.0 ms] 
     [Ref Proc: 1.5 ms] 
     [Ref Enq: 0.0 ms] 
     [Redirty Cards: 0.4 ms] 
     [Humongous Register: 0.2 ms] 
     [Humongous Reclaim: 0.1 ms] 
     [Free CSet: 0.3 ms] 
    [Eden: 476.0M(476.0M)->0.0B(556.0M) Survivors: 136.0M->56.0M Heap: 4480.6M(12.0G)->4016.3M(12.0G)] 
[Times: user=4.23 sys=1.08, real=0.45 secs] 

Answer 1

私は提案があります。システム上で実行中の他のプロセスがあると、Java GCワーカーと競合することがあります。

[オブジェクトコピー（MS）：最小：26.1、平均：106.1、最大：435.6、差分：409.6、合計：2545.3] [EXTルートスキャン（MS）：最小：2.1、平均：22.5、マックス：90.4、Diff：88.3、Sum：539.7]

上記のログから、GCワーカーは相当量の作業を行っているようです。これは、ほとんどのGCスレッドが早く終了し、それらのうちのいくつかがまだ動作していることを意味します。これが起こると、完成したスレッドは他のスレッドから作業を奪ってしまいます。これは終了時刻に反映されます。その結果、終了時刻は原因ではなく、単なる副作用です。

[終了（MS）：最小：0.0、平均：312.0、最大：327.3、差分：327.3、合計：7488.6]

あなたは24コアのマシンを有し、24個のGCワーカースレッドを有しています。 CPUリソースを必要とする他のプロセスやシステムアクティビティがある場合、競合のために一部のGCワーカーが遅延する可能性があります。

あなたのスレッド数を18に減らして、それを試してみる価値があります。

gcログレベルを上げることもできます。これを行うと、各スレッドの開始時刻が印刷されます。これは、アプリケーションをデバッグするのに役立ちます。