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

[Ron Reynolds]

JVM - Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for linux-amd64 JRE
(1.8.0_131-b11)

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.
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)...
thanks for all your help thus far. :)

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

> Hi,
>
> On Thu, 2017-11-16 at 09:15 -0800, Ron Reynolds wrote:
> > -- 59G->59G(59G), 2.0932801 secs]
> > ^^ this "--" is entirely undocumented as far as i can tell; i believe
> > it indicates that the young collection (or any collection?) was
> > cancelled (i've always seen these in the last-ditch-attempt young-
> > collections before a full-GC).  is that correct?
>
> I do not remember ever seeing that output, can you tell which VM and
> which GC you are using? And maybe just a bit more of your log?
>
> Potentially this is some leftover from some other log message printed
> out concurrently, i.e. the log messages got intermixed.
>
> > also the various docs recommend 2048 regions but if you MUST have
> > more or less which should you choose and what are reasonable limits?
> >  e.g., i have a 59G heap with default 16MB regions (which means there
> > should be 3832 of them); in what cases (if any) would it make sense
> > to use 32MB regions instead?
>
> If you have lots of humongous (large) objects, or as an option to
> potentially decrease remembered set size (memory usage) and scan rs
> time use larger regions. Another reason to increase heap region size
> could be that 32M regions allow larger TLABs (for applications that
> really burn through memory).
>
> In most cases it does not matter.
>
> See https://docs.oracle.com/javase/9/gctuning/garbage-first-garbage-col
> lector-tuning.htm for some discussion. While this is for jdk9, almost
> all of it applies to earlier versions too.
>
> > most docs say to size your regions based on max-heap size rather than
> > starting-heap size, which would seem to indicate <2048 regions is
>
> This changed in some 8 update or 9. Now defaults base the number of
> regions based on both initial and max size.
>
> > better than >2048, since at the start that hypothetical JVM would
>
> +-10% (or even more) generally do not make a difference. There are two
> boundaries: since regions are units of evacuation, if the region is too
> large the selection might impact the flexibility in selecting which
> regions to evacuate (i.e. if any single region G1 may evacuate blows
> the pause time goal).
>
> I *think* 2048 is just a random number far larger than maybe a (low)
> few hundred where G1 might get into trouble with finding consecutive
> free regions for large objects easily. However at the same time with
> larger regions there will be less objects that qualify as large, so it
> depends.
>
> G1 needs at least one eden, one survivor and one old region to operate.
>
> > certainly have fewer than 2048 regions until it grew into its max-
> > heap size.
>
> Thanks,
>   Thomas
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20171116/c4ae1ae4/attachment.html>