<div dir="ltr">Hi Thomas,<div> Thanks for the explanation.</div><div><br></div><div><br></div><div>I was trying to debug why it is not including some old region even though it had ~100ms (though Ergo logs say it has accommodated all regions to cover given 500ms).</div><div><br></div><div>Adding some log snippets here and attaching entire logs in case if that helps.</div><div><br class="gmail-Apple-interchange-newline">Running app with 31G<br></div><div><br></div><div>CommandLine flags: -XX:GCLogFileSize=20971520 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=out-of-memory-heap-dump -XX:InitialHeapSize=33285996544 -XX:MaxGCPauseMillis=500 -XX:MaxHeapSize=33285996544 -XX:MetaspaceSize=536870912 -XX:NumberOfGCLogFiles=20 -XX:+ParallelRefProcEnabled -XX:+PrintAdaptiveSizePolicy -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:+UseStringDeduplication<br></div><div><br></div><div>...</div><div><div>2017-06-19T22:54:05.488+0000: 9345.322: [GC pause (G1 Evacuation Pause) (mixed)</div><div>Desired survivor size 104857600 bytes, new threshold 1 (max 15)</div><div>- age 1: 131296848 bytes, 131296848 total</div><div>- age 2: 237559952 bytes, 368856800 total</div><div>- age 3: 137259376 bytes, 506116176 total</div><div> 9345.322: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 130042, predicted base time: 171.58 ms, remaining time: 328.42 ms, target pause time: 500.00 ms]</div><div> 9345.322: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 121 regions, survivors: 77 regions, predicted young region time: 249.33 ms]</div><div><b> 9345.322: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 0.44 ms, remaining time: 0.00 ms, old: 204 regions, min: 204 regions]</b></div><div> 9345.322: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 204 regions, expensive: 11 regions, min: 204 regions, remaining time: 0.00 ms]</div><div> 9345.322: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 121 regions, survivors: 77 regions, old: 204 regions, predicted pause time: 504.35 ms, target pause time: 500.00 ms]</div><div> 9345.691: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 1425 regions, reclaimable: 11364516952 bytes (34.14 %), threshold: 5.00 %]</div><div>, 0.3691404 secs]</div><div> [Parallel Time: 301.4 ms, GC Workers: 13]</div><div> [GC Worker Start (ms): Min: 9345323.0, Avg: 9345323.3, Max: 9345323.6, Diff: 0.6]</div><div> [Ext Root Scanning (ms): Min: 0.9, Avg: 1.2, Max: 1.6, Diff: 0.6, Sum: 15.9]</div><div> [Update RS (ms): Min: 62.1, Avg: 62.3, Max: 63.0, Diff: 0.9, Sum: 809.4]</div><div> [Processed Buffers: Min: 35, Avg: 51.8, Max: 91, Diff: 56, Sum: 674]</div><div> [Scan RS (ms): Min: 11.3, Avg: 12.1, Max: 14.8, Diff: 3.6, Sum: 157.5]</div><div> [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div><div> [Object Copy (ms): Min: 222.2, Avg: 224.8, Max: 225.3, Diff: 3.1, Sum: 2922.8]</div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]</div><div> [Termination Attempts: Min: 1, Avg: 15.6, Max: 24, Diff: 23, Sum: 203]</div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]</div><div> [GC Worker Total (ms): Min: 300.3, Avg: 300.6, Max: 300.8, Diff: 0.5, Sum: 3907.2]</div><div> [GC Worker End (ms): Min: 9345623.8, Avg: 9345623.9, Max: 9345624.0, Diff: 0.2]</div><div> [Code Root Fixup: 0.1 ms]</div><div> [Code Root Purge: 0.0 ms]</div><div> [String Dedup Fixup: 43.9 ms, GC Workers: 13]</div><div> [Queue Fixup (ms): Min: 0.4, Avg: 2.2, Max: 3.7, Diff: 3.3, Sum: 28.6]</div><div> [Table Fixup (ms): Min: 39.8, Avg: 41.2, Max: 42.9, Diff: 3.2, Sum: 535.8]</div><div> [Clear CT: 3.4 ms]</div><div> [Other: 20.2 ms]</div><div> [Choose CSet: 0.3 ms]</div><div> [Ref Proc: 13.4 ms]</div><div> [Ref Enq: 1.0 ms]</div><div> [Redirty Cards: 2.0 ms]</div><div> [Humongous Register: 0.2 ms]</div><div> [Humongous Reclaim: 0.1 ms]</div><div> [Free CSet: 2.1 ms]</div><div> [Eden: 968.0M(968.0M)->0.0B(1472.0M) Survivors: 616.0M->112.0M Heap: 15.6G(31.0G)->13.1G(31.0G)]</div><div><b> [Times: user=4.53 sys=0.00, real=0.36 secs]</b></div></div><div>....</div><div><div>2017-06-19T22:54:47.655+0000: 9387.489: [GC pause (G1 Evacuation Pause) (mixed)</div><div>Desired survivor size 104857600 bytes, new threshold 15 (max 15)</div><div>- age 1: 31749256 bytes, 31749256 total</div><div> 9387.489: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 127449, predicted base time: 168.88 ms, remaining time: 331.12 ms, target pause time: 500.00 ms]</div><div> 9387.489: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 184 regions, survivors: 14 regions, predicted young region time: 62.79 ms]</div><div><b> 9387.490: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: old CSet region num reached max, old: 397 regions, max: 397 regions]</b></div><div> 9387.490: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 184 regions, survivors: 14 regions, old: 397 regions, predicted pause time: 390.18 ms, target pause time: 500.00 ms]</div><div><b> 9387.659: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 1028 regions, reclaimable: 8047410104 bytes (24.18 %), threshold: 5.00 %]</b></div><div><b>, 0.1700662 secs]</b></div><div> [Parallel Time: 101.4 ms, GC Workers: 13]</div><div> [GC Worker Start (ms): Min: 9387490.4, Avg: 9387490.8, Max: 9387491.1, Diff: 0.6]</div><div> [Ext Root Scanning (ms): Min: 0.7, Avg: 1.1, Max: 1.6, Diff: 0.9, Sum: 14.3]</div><div> [Update RS (ms): Min: 27.0, Avg: 27.8, Max: 28.9, Diff: 1.8, Sum: 361.9]</div><div> [Processed Buffers: Min: 34, Avg: 51.4, Max: 88, Diff: 54, Sum: 668]</div><div> [Scan RS (ms): Min: 25.8, Avg: 27.1, Max: 27.4, Diff: 1.6, Sum: 352.2]</div><div> [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]</div><div> [Object Copy (ms): Min: 42.8, Avg: 43.8, Max: 44.5, Diff: 1.8, Sum: 569.9]</div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div><div> [Termination Attempts: Min: 1, Avg: 9.5, Max: 14, Diff: 13, Sum: 124]</div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 2.3]</div><div> [GC Worker Total (ms): Min: 99.7, Avg: 100.1, Max: 100.6, Diff: 0.9, Sum: 1301.4]</div><div> [GC Worker End (ms): Min: 9387590.7, Avg: 9387590.9, Max: 9387591.1, Diff: 0.4]</div><div> [Code Root Fixup: 0.3 ms]</div><div> [Code Root Purge: 0.0 ms]</div><div> [String Dedup Fixup: 43.5 ms, GC Workers: 13]</div><div> [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]</div><div> [Table Fixup (ms): Min: 43.0, Avg: 43.2, Max: 43.4, Diff: 0.3, Sum: 561.3]</div><div> [Clear CT: 3.9 ms]</div><div> [Other: 21.1 ms]</div><div> [Choose CSet: 0.8 ms]</div><div> [Ref Proc: 12.8 ms]</div><div> [Ref Enq: 0.9 ms]</div><div> [Redirty Cards: 0.9 ms]</div><div> [Humongous Register: 0.2 ms]</div><div> [Humongous Reclaim: 0.1 ms]</div><div> [Free CSet: 4.2 ms]</div><div> [Eden: 1472.0M(1472.0M)->0.0B(1424.0M) Survivors: 112.0M->160.0M Heap: 14.5G(31.0G)->10.1G(31.0G)]</div><div><b> [Times: user=1.93 sys=0.00, real=0.17 secs]</b></div></div><div>.....</div><div><div>2017-06-19T22:55:29.656+0000: 9429.490: [GC pause (G1 Evacuation Pause) (mixed)</div><div>Desired survivor size 104857600 bytes, new threshold 15 (max 15)</div><div>- age 1: 44204040 bytes, 44204040 total</div><div>- age 2: 31422896 bytes, 75626936 total</div><div> 9429.490: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 64391, predicted base time: 130.82 ms, remaining time: 369.18 ms, target pause time: 500.00 ms]</div><div> 9429.490: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 178 regions, survivors: 20 regions, predicted young region time: 69.26 ms]</div><div><b> 9429.491: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 2.12 ms, remaining time: 0.00 ms, old: 204 regions, min: 204 regions]</b></div><div> 9429.491: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 204 regions, expensive: 72 regions, min: 204 regions, remaining time: 0.00 ms]</div><div> 9429.491: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 178 regions, survivors: 20 regions, old: 204 regions, predicted pause time: 684.25 ms, target pause time: 500.00 ms]</div><div> 9429.663: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 824 regions, reclaimable: 6351099672 bytes (19.08 %), threshold: 5.00 %]</div><div>, 0.1729571 secs]</div><div> [Parallel Time: 102.6 ms, GC Workers: 13]</div><div> [GC Worker Start (ms): Min: 9429491.3, Avg: 9429491.6, Max: 9429491.9, Diff: 0.6]</div><div> [Ext Root Scanning (ms): Min: 0.9, Avg: 1.3, Max: 1.8, Diff: 0.9, Sum: 16.9]</div><div> [Update RS (ms): Min: 18.7, Avg: 19.1, Max: 20.9, Diff: 2.2, Sum: 248.9]</div><div> [Processed Buffers: Min: 18, Avg: 32.6, Max: 58, Diff: 40, Sum: 424]</div><div> [Scan RS (ms): Min: 15.5, Avg: 17.1, Max: 18.5, Diff: 2.9, Sum: 222.8]</div><div> [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]</div><div> [Object Copy (ms): Min: 62.3, Avg: 63.9, Max: 64.4, Diff: 2.2, Sum: 831.3]</div><div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]</div><div> [Termination Attempts: Min: 1, Avg: 2.6, Max: 5, Diff: 4, Sum: 34]</div><div> [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 2.2]</div><div> [GC Worker Total (ms): Min: 101.4, Avg: 101.7, Max: 102.1, Diff: 0.7, Sum: 1322.7]</div><div> [GC Worker End (ms): Min: 9429593.3, Avg: 9429593.4, Max: 9429593.6, Diff: 0.4]</div><div> [Code Root Fixup: 0.2 ms]</div><div> [Code Root Purge: 0.0 ms]</div><div> [String Dedup Fixup: 45.4 ms, GC Workers: 13]</div><div> [Queue Fixup (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.5]</div><div> [Table Fixup (ms): Min: 43.9, Avg: 44.1, Max: 44.2, Diff: 0.4, Sum: 573.4]</div><div> [Clear CT: 4.3 ms]</div><div> [Other: 20.5 ms]</div><div> [Choose CSet: 0.5 ms]</div><div> [Ref Proc: 14.3 ms]</div><div> [Ref Enq: 1.2 ms]</div><div> [Redirty Cards: 0.7 ms]</div><div> [Humongous Register: 0.2 ms]</div><div> [Humongous Reclaim: 0.1 ms]</div><div> [Free CSet: 2.4 ms]</div><div> [Eden: 1424.0M(1424.0M)->0.0B(1392.0M) Survivors: 160.0M->192.0M Heap: 11.5G(31.0G)->8796.0M(31.0G)]</div><div><b> [Times: user=1.95 sys=0.00, real=0.17 secs]</b></div></div><div><br></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, Jun 22, 2017 at 3:18 AM, Thomas Schatzl <span dir="ltr"><<a href="mailto:thomas.schatzl@oracle.com" target="_blank">thomas.schatzl@oracle.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi,<br>
<span class=""><br>
On Tue, 2017-06-20 at 23:45 -0700, Sundara Mohan M wrote:<br>
> Hi,<br>
> Can someone shed more light on why <wbr>G1OldCSetRegionThresholdPercen<wbr>t<br>
> flag is under experimental (Need to add -<br>
> XX:+<wbr>UnlockExperimentalVMOptions to modify it.)<br>
<br>
</span> in my view -XX:+<wbr>UnlockExperimentalVMOptions mostly serves mostly as a<br>
"I really want to do that and I know what I am doing" confirmation from<br>
the user that he is aware that using this (in this case) option to<br>
influence the set of regions taken in during mixed gc you might get<br>
surprising behavior.<br>
<br>
Also, I think there has been no official documentation for it - also<br>
because it should be very rarely needed.<br>
In particular, I am curious about the case when it would be useful to<br>
change it. Could you give some log files showing that there is an issue<br>
with the upper bound for the number of old gen regions to take during<br>
GC? (i.e. the amount of old gen regions taken is too small and there is<br>
ample pause time left and it matters to clean up more regions in a<br>
single mixed gc?)<br>
<br>
Sometimes there are problems with the lower bound that is controlled by<br>
the -XX:G1MixedGCCountTarget (product level) option.<br>
<br>
Hth,<br>
Thomas<br>
<br>
</blockquote></div><br></div>