1
JDK版本時：G1長年輕GC時間開始併發標記週期
java version "1.7.0_91"
OpenJDK Runtime Environment (IcedTea 2.6.3) (7u91-2.6.3-0ubuntu0.14.04.1)
OpenJDK 64-Bit Server VM (build 24.91-b01, mixed mode)
GC/MEM參數：
-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]
您是否嘗試減小堆大小？看起來你有大約13GB的永久（或長壽命）數據，而長時間停頓只發生在GC正試圖清理大量區域並移動周圍的活物（Object Copy幾乎一直都在使用）時。濃。標記循環不是一個停止世界，它只表示GC將切換到混合模式。如果你減小堆的大小，收集會更頻繁，但他們也會更短。我會嘗試16Gb和默認的Java選項。 –
根據你提供的Java選項，你已經玩過各種設置。你到目前爲止嘗試了什麼？你是如何得到這些價值的？ –
@AndrewLygin對象副本似乎完全是單線程的，10GB伊甸園設法將其擠壓成1.3GB的倖存者。即年輕人中只有大約1.3GB（+無論是否被提升爲老一代）。這也是以前的年輕系列中發生的事情。所以有些東西在這裏 – the8472