G1長い若いGC時間同時マーキングサイクルに

JDKのバージョン開始時に時折G1長い若いGC時間同時マーキングサイクルに

-Xms24g -Xmx24g -Xss256k -Djava.awt.headless=true -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:MaxGCPauseMillis=10000 -XX:InitiatingHeapOccupancyPercent=30 -XX:+ParallelRefProcEnabled -XX:G1HeapWastePercent=5 -XX:G1OldCSetRegionThresholdPercent=20 -XX:G1HeapRegionSize=16m -XX:G1MixedGCLiveThresholdPercent=80 -XX:+PrintFlagsFinal -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+PrintAdaptiveSizePolicy

を、私は長い若いGCが1分以上休止します参照してください。私はGCのログをチェックし、それらがすべて混合GCイベントのための並行マーキング・サイクルの初期化と共に現れることを発見しました。若いGCの見積もりの一時停止は非常に速いので、私の推測では、同時のマーキングサイクルが通常の若年GCのパフォーマンスに影響を与えていると思います。どのように影響を減らすことができますか？私はgcログをチェックします。並行マーキングサイクルのほとんどは、若いGCには影響を与えませんが、ごくわずかしか影響がありません。 GCログはこのようなものです：

[Eden: 10.8G(10.8G)->0.0B(10.3G) Survivors: 160.0M->432.0M Heap: 21.3G(24.0G)->10.9G(24.0G)] 
[Times: user=3.61 sys=0.76, real=0.35 secs] 
505008.424: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested] 
505008.424: [GC pause (young) (initial-mark) 505008.425: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 151866, predicted base time: 65.35 ms, remaining time: 9934.65 ms, target pause time: 10000.00 ms] 
505008.425: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 659 regions, survivors: 27 regions, predicted young region time: 206.46 ms] 
505008.425: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 659 regions, survivors: 27 regions, old: 0 regions, predicted pause time: 271.81 ms, target pause time: 10000.00 ms] 
, 90.8122050 secs] 
    [Parallel Time: 90688.1 ms, GC Workers: 23] 
     [GC Worker Start (ms): Min: 505008426.7, Avg: 505008427.4, Max: 505008427.9, Diff: 1.2] 
     [Ext Root Scanning (ms): Min: 2.7, Avg: 7.8, Max: 18.4, Diff: 15.7, Sum: 179.8] 
     [Code Root Marking (ms): Min: 0.0, Avg: 0.3, Max: 4.2, Diff: 4.2, Sum: 7.2] 
     [Update RS (ms): Min: 33.8, Avg: 47.4, Max: 61.1, Diff: 27.3, Sum: 1090.1] 
     [Processed Buffers: Min: 22, Avg: 40.2, Max: 107, Diff: 85, Sum: 924] 
     [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.6, Diff: 0.5, Sum: 5.1] 
     [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] 
     [Object Copy (ms): Min: 85537.6, Avg: 87188.8, Max: 90638.2, Diff: 5100.6, Sum: 2005342.7] 
     [Termination (ms): Min: 0.0, Avg: 3441.6, Max: 5092.4, Diff: 5092.4, Sum: 79155.8] 
     [GC Worker Other (ms): Min: 0.0, Avg: 0.4, Max: 0.8, Diff: 0.8, Sum: 10.1] 
     [GC Worker Total (ms): Min: 90685.8, Avg: 90686.6, Max: 90687.3, Diff: 1.5, Sum: 2085790.9] 
     [GC Worker End (ms): Min: 505099113.5, Avg: 505099113.9, Max: 505099114.3, Diff: 0.8] 
    [Code Root Fixup: 0.2 ms] 
    [Code Root Migration: 0.3 ms] 
    [Clear CT: 1.6 ms] 
    [Other: 122.0 ms] 
     [Choose CSet: 0.0 ms] 
     [Ref Proc: 105.3 ms] 
     [Ref Enq: 4.8 ms] 
     [Free CSet: 3.0 ms] 
    [Eden: 10.3G(10.3G)->0.0B(128.0M) Survivors: 432.0M->1376.0M Heap: 21.2G(24.0G)->12.7G(24.0G)] 
[Times: user=82.22 sys=7.54, real=90.81 secs] 
505099.236: [GC concurrent-root-region-scan-start] 
505099.311: [GC pause (young)505099.331: [GC concurrent-root-region-scan-end, 0.0943260 secs] 
505099.331: [GC concurrent-mark-start] 
505099.331: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 322026, predicted base time: 159.64 ms, remaining time: 9840.36 ms, target pause time: 10000.00 ms] 
505099.331: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 8 regions, survivors: 86 regions, predicted young region time: 6030.20 ms] 
505099.331: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 8 regions, survivors: 86 regions, old: 0 regions, predicted pause time: 6189.84 ms, target pause time: 10000.00 ms] 
505101.745: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 28.00 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)] 
, 2.4339110 secs] 
    [Root Region Scan Waiting: 19.4 ms] 
    [Parallel Time: 2385.4 ms, GC Workers: 23] 
     [GC Worker Start (ms): Min: 505099330.9, Avg: 505099331.2, Max: 505099331.4, Diff: 0.4] 
     [Ext Root Scanning (ms): Min: 3.5, Avg: 12.8, Max: 17.0, Diff: 13.5, Sum: 295.5] 
     [SATB Filtering (ms): Min: 0.0, Avg: 0.1, Max: 1.7, Diff: 1.7, Sum: 1.7] 
     [Update RS (ms): Min: 2222.6, Avg: 2229.1, Max: 2266.2, Diff: 43.5, Sum: 51268.7] 
     [Processed Buffers: Min: 41, Avg: 65.8, Max: 120, Diff: 79, Sum: 1514] 
     [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.1, Sum: 0.9] 
     [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
     [Object Copy (ms): Min: 104.2, Avg: 141.5, Max: 147.9, Diff: 43.7, Sum: 3254.6] 
     [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 3.6] 
     [GC Worker Other (ms): Min: 0.0, Avg: 0.5, Max: 9.7, Diff: 9.7, Sum: 12.6] 
     [GC Worker Total (ms): Min: 2383.9, Avg: 2384.3, Max: 2384.8, Diff: 0.8, Sum: 54837.8] 
     [GC Worker End (ms): Min: 505101715.3, Avg: 505101715.4, Max: 505101715.7, Diff: 0.4] 
    [Code Root Fixup: 0.3 ms] 
    [Code Root Migration: 0.0 ms] 
    [Clear CT: 0.4 ms] 
    [Other: 28.4 ms] 
     [Choose CSet: 0.0 ms] 
     [Ref Proc: 19.7 ms] 
     [Ref Enq: 0.3 ms] 
     [Free CSet: 4.6 ms] 
    [Eden: 128.0M(128.0M)->0.0B(1024.0M) Survivors: 1376.0M->192.0M Heap: 12.8G(24.0G)->12.9G(24.0G)] 
[Times: user=3.79 sys=1.10, real=2.43 secs] 
505103.032: [GC concurrent-mark-end, 3.7007580 secs] 
505103.176: [GC remark 505103.181: [GC ref-proc, 0.0819490 secs], 0.0989750 secs] 
[Times: user=1.10 sys=0.15, real=0.10 secs] 
505103.278: [GC cleanup 13G->13G(24G), 0.0293890 secs] 
[Times: user=0.21 sys=0.14, real=0.03 secs] 
505103.308: [GC concurrent-cleanup-start] 
505103.308: [GC concurrent-cleanup-end, 0.0001760 secs] 
505104.534: [GC pause (young) 505104.538: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 623522, predicted base time: 2265.93 ms, remaining time: 7734.07 ms, target pause time: 10000.00 ms] 
505104.538: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 64 regions, survivors: 12 regions, predicted young region time: 5414.13 ms] 
505104.538: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 64 regions, survivors: 12 regions, old: 0 regions, predicted pause time: 7680.06 ms, target pause time: 10000.00 ms] 
505104.660: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 31.31 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)] 
505104.660: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 13706985472 bytes, allocation request: 0 bytes, threshold: 7730941110 bytes (30.00 %), source: end of GC] 
505104.660: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 290 regions, reclaimable: 1891629432 bytes (7.34 %), threshold: 5.00 %] 
, 0.1258480 secs] 
    [Parallel Time: 86.7 ms, GC Workers: 23] 
     [GC Worker Start (ms): Min: 505104538.0, Avg: 505104538.4, Max: 505104538.5, Diff: 0.5] 
     [Ext Root Scanning (ms): Min: 3.3, Avg: 7.6, Max: 19.2, Diff: 15.9, Sum: 175.1] 
     [Update RS (ms): Min: 53.4, Avg: 64.9, Max: 69.0, Diff: 15.6, Sum: 1491.9] 
     [Processed Buffers: Min: 76, Avg: 120.3, Max: 149, Diff: 73, Sum: 2766] 
     [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.5] 
     [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] 
     [Object Copy (ms): Min: 9.8, Avg: 13.5, Max: 14.1, Diff: 4.3, Sum: 310.1] 
     [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.8] 
     [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.4] 
     [GC Worker Total (ms): Min: 85.9, Avg: 86.1, Max: 86.4, Diff: 0.5, Sum: 1979.9] 
     [GC Worker End (ms): Min: 505104624.4, Avg: 505104624.4, Max: 505104624.5, Diff: 0.1] 
    [Code Root Fixup: 0.1 ms] 
    [Code Root Migration: 0.0 ms] 
    [Clear CT: 0.7 ms] 
    [Other: 38.4 ms] 
     [Choose CSet: 0.0 ms] 
     [Ref Proc: 32.0 ms] 
     [Ref Enq: 0.6 ms] 
     [Free CSet: 0.6 ms] 
    [Eden: 1024.0M(1024.0M)->0.0B(1056.0M) Survivors: 192.0M->160.0M Heap: 13.7G(24.0G)->12.9G(24.0G)] 
[Times: user=1.56 sys=0.23, real=0.12 secs]

出典

2016-08-10 Rural Hunter

ヒープサイズを縮小しようとしましたか？ GCが大量の地域を清掃したり、生きているオブジェクトを移動しようとしているときにのみ、永久（または長生き）のデータが約13GBあり、長いポーズが発生しているように見えます（Object Copyはほとんどすべての時間がかかります）。 Conc。マーキングサイクルは世界が止まるわけではなく、GCが混合モードに切り替えることを伝えるだけです。ヒープサイズを小さくすると、コレクションは頻繁になりますが、時間も短くなります。私は16GbとデフォルトのJavaオプションを試してみます。 –

あなたが提供したJavaオプションによれば、すでにさまざまな設定で遊んでいます。これまでに何を試しましたか？あなたはどのようにその価値観に来ましたか？ –

@AndrewLyginオブジェクトのコピーは完全にシングルスレッドと思われ、10GBのedenは1.3GBのサバイバーに圧倒される。私。若い世代には約1.3GBしか生まれませんでした（+古いものに昇進したもの）。以前の若いコレクションでも起こったことです。何かがここにあります – the8472

至急のJava 8にアップデート - G1はおそらくこの問題を含めたJava 7以降の修正や改善のTONがあった - 私はCSETの建設中に見たことの予測は持っています概して正確であった。何かがあれば、GCはそれよりも時間がかかります。さらにパフォーマンスの違いは、特にG1の場合、夜間と夜間です。

この時点で私が推奨するほとんどの設定がありますが、見るべきことがあります：-XX:G1NewSizePercent=10でedenサイズを増やすことを検討してください - 理論的には若いGCサイクルの時間が長くなりますが、反対に（古いセットのサイズを減らし、オブジェクトをより簡単に収集することによって）

また、これは私を心配します：

[タイムズ：ユーザー= 82.22 SYS = 7.54、リアル= 90.81秒] [タイムズ：ユーザー= 1.56 SYS = 0.23、リアル= 0.12秒]

これはシステム時間が非常に長いことです。おそらくページングが起こっているか、それと同様ですか？

出典

2016-11-14 23:32:31 BobMcGee

私は以前に-XX：G1NewSizePercent = 30を試しましたが、大きな違いはありませんでした。私はjdk 8にアップグレードし、ページングの問題もチェックしようとします。ありがとう！ –

G1長い若いGC時間同時マーキングサイクルに

答えて

関連する問題