<div dir="ltr">increasing the max-pause-time from 100ms to 200ms has certainly made our young-collections less frequent (before they were about every 5-10 seconds; now they're 30-60+ seconds apart). unfortunately our Full-GC woes continue.  <div><br></div><div>one thing i noticed is that once the JVM is warmed up only humongous-allocations seem to trigger concurrent-mark/mixed-GC cycles (not counting the first failed young-collection that heralds the soon-to-follow full-GC). </div><div>this is the last healthy young-collection:</div><div><pre style="color:rgb(0,0,0);word-wrap:break-word;white-space:pre-wrap">2017-12-01T15:08:07.619+0000: [GC pause (G1 Evacuation Pause) (young)
302437.685: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 153647, predicted base time: 60.27 ms, remaining time: 139.73 ms, target pause time: 200.00 ms]
302437.685: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2293 regions, survivors: 6 regions, predicted young region time: 108.96 ms]
302437.685: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2293 regions, survivors: 6 regions, old: 0 regions, predicted pause time: 169.23 ms, target pause time: 200.00 ms]
<b>54G->17G(59G)</b>, 0.1609184 secs]</pre><pre style="word-wrap:break-word"><font face="arial, helvetica, sans-serif">since it left 17G of the 59G heap (28.8%) allocated which would seem to indicate an IHOP of 25 should trigger mixed-collections more frequently, however, given these next 2 less-than-healthy young-collections i'm not sure mixed-collections will prevent what we're experiencing.</font></pre><pre style="word-wrap:break-word"><font face="arial, helvetica, sans-serif">in other words, if the above young-collection had been followed by mixed-collections it would have only collected perhaps another 10GB of old.</font></pre><pre style="word-wrap:break-word"><font face="arial, helvetica, sans-serif">this is the next YC which is the first failed collection.</font></pre><pre style="word-wrap:break-word"><font color="#000000"><span style="white-space:pre-wrap">2017-12-01T15:08:40.241+0000: [GC pause (G1 Evacuation Pause) (young)<br></span></font></pre></div><div><pre style="color:rgb(0,0,0);word-wrap:break-word;white-space:pre-wrap"> 302470.307: [G1Ergonomics (CSet Construction) start choosing CSet, <b>_pending_cards: 133537</b>, predicted base time: 86.00 ms, remaining time: 114.00 ms, target pause time: 200.00 ms]
302470.307: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2283 regions, survivors: 16 regions, predicted young region time: 85.78 ms]
302470.307: [G1Ergonomics (CSet Construction) finish choosing CSet, <b>eden: 2283 regions, survivors: 16 regions</b>, old: 0 regions, predicted pause time: 171.77 ms, target pause time: 200.00 ms]
302472.204: [G1Ergonomics (Heap Sizing) <b>attempt heap expansion, reason: region allocation request failed</b>, allocation request: 57512 bytes]
302472.204: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 57512 bytes, attempted expansion amount: 16777216 bytes]
302472.204: [G1Ergonomics (Heap Sizing) did not expand the heap, reason: <b>heap already fully expanded</b>]
302480.689: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 55851352064 bytes, allocation request: 0 bytes, threshold: 28938181005 bytes (45.00 %), source: end of GC]
<b>-- 53G->56G(59G), 10.3817795 secs</b>]</pre><div>the above Young-Collection CSet contained 2283 eden and 16 survivor regions but then it tried to allocate more heap? due to lack of space for promotion? due to heap fragmentation by humongous objects? (the JVM is using 16M regions so it should have ~3833 regions which means it's 60% young-generation at this point).</div><div>and why would it try to expand the heap-size at all when -Xmx and -Xms are fixed to the same value and thus the attempt is guaranteed to fail? and since the YC is a STW event how did it go from 2283 eden + 16 survivor to 1 eden + 288 survivor and still not recover any heap(based on before/after sizes of 53G->56G)?  also there's a 2 second gap between finishing the CSet and the failed attempted heap-increase and the whole thing take 10 seconds. i've asked for more verbose GC logging from ops to hopefully clarify where all those seconds got wasted.</div><div><br></div>the next Young-Collection found over 6.5M pending cards and only 1 eden and 288 survivors (presumably created by the previous young-collection).<pre style="color:rgb(0,0,0);word-wrap:break-word;white-space:pre-wrap"> 302480.710: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
2017-12-01T15:08:50.644+0000: [GC pause (G1 Evacuation Pause) (young) (initial-mark)
302480.711: [G1Ergonomics (CSet Construction) start choosing CSet, <b>_pending_cards: 6533165</b>, predicted base time: 1123.81 ms, remaining time: 0.00 ms, target pause time: 200.00 ms]
302480.711: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1 regions, survivors: 288 regions, predicted young region time: 160.18 ms]
302480.711: [G1Ergonomics (CSet Construction) finish choosing CSet, <b>eden: 1 regions, survivors: 288 regions</b>, old: 0 regions, predicted pause time: 1283.99 ms, target pause time: 200.00 ms]
302482.600: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: region allocation request failed, allocation request: 8388600 bytes]
302482.600: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 8388600 bytes, attempted expansion amount: 16777216 bytes]
302482.600: [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap already fully expanded]
-- 56G->56G(59G), 10.2031695 secs]
2017-12-01T15:09:00.848+0000: [GC concurrent-root-region-scan-start]
</pre></div><div>so, does it seem that decreasing IHOP and increasing the concurrent-mark heap and thread-count will address this since it didn't even try to start a concurrent-mark cycle until it was basically too late? all subsequent young-collections failed with 0 eden, 0 survivor and even 0 pending-cards and then the Full-GC occurs at 15:09:08 (28 seconds later) and recovers <span style="color:rgb(0,0,0);white-space:pre-wrap">59G->6766M. </span></div><div><span style="color:rgb(0,0,0);white-space:pre-wrap"><br></span></div><div><span style="color:rgb(0,0,0);white-space:pre-wrap">this is all from a 8-core VM running "</span><span style="color:rgb(0,0,0);white-space:pre-wrap">Java HotSpot(TM) 64-Bit Server VM (25.131-b11)" (i couldn't find any mention of GC improvements between build 131 and the current build, 151, so selling Ops on increasing the JVM version is going to be a difficult sell and moving to Java 9 will, of course, require a lot more preparations). note, one thing about these JVMs is that they do not have exclusive use of these cores but share them with at least 1 Apache server (which is fronting the Tomcat that generated these GC logs).</span></div><div><span style="color:rgb(0,0,0);white-space:pre-wrap"><br></span></div><div><span style="color:rgb(0,0,0);white-space:pre-wrap">sorry if this is a variation on a previous question but sometimes this mailing list feels like the only place to get answers.</span></div><div><span style="color:rgb(0,0,0);white-space:pre-wrap"><br></span></div><div><span style="color:rgb(0,0,0);white-space:pre-wrap">thanks.</span></div><div><span style="color:rgb(0,0,0);white-space:pre-wrap">....................ron.</span></div><div><br></div></div>