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

[Ron Reynolds]

yes, 2 of them (apparently it was so bad it had to be logged twice):

2017-11-14T12:15:44.868+0000: [GC concurrent-root-region-scan-start]
2017-11-14T12:15:44.976+0000: [GC concurrent-root-region-scan-end,
0.1078258 secs]
2017-11-14T12:15:44.976+0000: [GC concurrent-mark-start]
2017-11-14T12:15:46.812+0000: [GC concurrent-mark-reset-for-overflow]
2017-11-14T12:15:51.555+0000: [GC concurrent-mark-reset-for-overflow]

getting Java9 into production will take a lot of effort but i'll start
putting that idea into the proper heads...

during the almost 2 days in the GC log i'm currently working with the GC
concurrent-mark-end times start at ~2ms then, after running for 6 hours
it starts jumping around a lot - range is roughly 0.5 seconds to 10.1
seconds.

we have minimum cmd-line args (well, "minimum" is relative):
-XX:InitialHeapSize=64298680320 -XX:MaxHeapSize=64298680320 -XX:+UseG1GC
-XX:MaxGCPauseMillis=200 -XX:-OmitStackTraceInFastThrow
-XX:+PrintAdaptiveSizePolicy -XX:+PrintClassHistogramAfterFullGC
-XX:+PrintClassHistogramBeforeFullGC
-XX:GCLogFileSize=10485760 -XX:NumberOfGCLogFiles=10  -XX:+PrintGC
-XX:+PrintGCDateStamps -XX:-PrintGCDetails -XX:-PrintGCTimeStamps
-XX:+UseGCLogFileRotation

these boxes only have 8 cores, btw.
i'll get the -XX:MarkStackSize arg out there ASAP.  it's not even mentioned
in the "Java Perf Companion" or Scott Oaks book - and i thought Java had an
insane number of undocumented options before...
thanks!  (do you really think it needs to be 512M?  that appears to be the
default max possible value...)

On Thu, Nov 16, 2017 at 3:12 PM, Thomas Schatzl <thomas.schatzl at oracle.com>
wrote:

> 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.
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20171116/dfa65757/attachment.html>