"--" at the beginning of a end-collection line and best region count when it's not 2048

[Thomas Schatzl]

Hi,

On Thu, 2017-11-16 at 14:08 -0800, Ron Reynolds wrote:
> JVM - Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for linux-amd64
> JRE (1.8.0_131-b11)
> 

  please at least try to update to latest jdk8u to have all fixes in.
Strongly consider trying jdk9, because...

> the lines are intermixed because we have -XX:+PrintAdaptiveSizePolicy 
> and the G1Ergo lines get logged between the start-pause and end-pause 
> lines.  e.g.
> 
> 2017-11-15T22:46:45.141+0000: [GC pause (G1 Evacuation Pause) (young)
> 167392.984: [G1Ergonomics (CSet Construction) start choosing CSet,
> _pending_cards: 1876696, predicted base time: 435.30 ms, remaining
> time: 0.00 ms, target pause time: 200.00 ms]
>  167392.984: [G1Ergonomics (CSet Construction) add young regions to
> CSet, eden: 41 regions, survivors: 10 regions, predicted young region
> time: 64.16 ms]
>  167392.984: [G1Ergonomics (CSet Construction) finish choosing CSet,
> eden: 41 regions, survivors: 10 regions, old: 0 regions, predicted
> pause time: 499.46 ms, target pause time: 200.00 ms]
>  167392.985: [G1Ergonomics (Heap Sizing) attempt heap expansion,
> reason: region allocation request failed, allocation request: 8388600
> bytes]
>  167392.985: [G1Ergonomics (Heap Sizing) expand the heap, requested
> expansion amount: 8388600 bytes, attempted expansion amount: 16777216
> bytes]
>  167392.985: [G1Ergonomics (Heap Sizing) did not expand the heap,
> reason: heap already fully expanded]
> -- 59G->59G(59G), 2.0932801 secs]
> 
>  167395.085: [G1Ergonomics (Heap Sizing) attempt heap expansion,
> reason: allocation request failed, allocation request: 8216 bytes]
>  167395.085: [G1Ergonomics (Heap Sizing) expand the heap, requested
> expansion amount: 16777216 bytes, attempted expansion amount:
> 16777216 bytes]
>  167395.085: [G1Ergonomics (Heap Sizing) did not expand the heap,
> reason: heap already fully expanded]
> 
> 2017-11-15T22:46:47.242+0000: [Full GC (Allocation Failure) 
> ...class-histogram here...
>  59G->5071M(59G), 32.4098427 secs]
> 
> we do have a few humongous objects (typically one every few hours;
> rarely more often than once per hour).  some of them are quite
> humongous (the largest i've seen so far is 161M) so increasing the
> region size won't solve them all but it will reduce the count a
> bit.  

Don't bother if you did not see an issue and these objects are few.

> the amazing thing (to me) is how much heap is recovered when the
> Full-GC occurs; still working out how things could have gotten so
> sideways (i.e., so many dead objects laying around not being cleaned
> up).  wondering if 200ms still isn't enough time (it was 100ms
> before)...

... because marking apparently could not keep up with your allocation
rate, which at first has nothing to do with the pause time. Because if
G1 can't finish determining liveness, it won't start recovering space
in the old gen.

Can you check for "GC concurrent-mark-*" messages, maybe you are seeing
"GC concurrent-mark-reset-for-overflow" ones. If so, increase
MarkStackSize (default 4M to something much higher, like 512M; there is
no way to really determine what value you need in jdk8, just that these
reset-for-overflow hopefully go away) - or update to jdk9. It often
needs much less memory.

It would also be nice to see the time marking takes (the value printed
with the "GC concurrent-mark-end" message) to see whether they are
long/or there are large variations. JDK9 would also be much better with
marking, faster and much more scalable; specifically see the
presentation "JDK9 The quest for very large heaps" from JavaOne 2016
about changes to marking that allow really good performance [0].

Other than that hunch about MarkStackSize it is hard to tell what's
going on without some larger part of the logs and options used (maybe
starting marking to late because of a too high
InitiatingHeapOccupancyPercent setting).

Thanks,
  Thomas

[0] https://www.youtube.com/watch?v=LppgqvKOUKs at 32:04; quoting from
the video: "marking runs 50x faster". It also shows other jdk9
improvements particularly applicable to running larger heaps.