G1 long young GC time when initiating concurrent marking cycle
<p>JDK version:</p>

<pre><code>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)
</code></pre>

<p>GC/Mem parameters: </p>

<pre><code>-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
</code></pre>

<p>Occasionally, I see long young gc pauses longer than 1 minute. I checked the GC log and found they are all appear with a concurrent marking cycle initialization for a mixed gc event. Since the estimation pause of the young gc is very quick, my guess is that the concurrent marking cycle is impacting the normal young gc performance. How can I reduce the impact? I check through the gc log. Most of the concurrent marking cycle has no impact on the young gc, only very few of them has big impact.
The gc log is like this:</p>

<pre><code>   [Eden: 10.8G(10.8G)-&gt;0.0B(10.3G) Survivors: 160.0M-&gt;432.0M Heap: 21.3G(24.0G)-&gt;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)-&gt;0.0B(128.0M) Survivors: 432.0M-&gt;1376.0M Heap: 21.2G(24.0G)-&gt;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)-&gt;0.0B(1024.0M) Survivors: 1376.0M-&gt;192.0M Heap: 12.8G(24.0G)-&gt;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-&gt;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)-&gt;0.0B(1056.0M) Survivors: 192.0M-&gt;160.0M Heap: 13.7G(24.0G)-&gt;12.9G(24.0G)]
 [Times: user=1.56 sys=0.23, real=0.12 secs] 
</code></pre>