Minor question about logging

[Thomas Schatzl]

Hi,

On 09.03.20 11:32, Thomas Schatzl wrote:
> Hi,
> 
> On 08.03.20 06:01, Eugeniu Rabii wrote:
>> Hello,
>>
>> I have a very simple program that constantly allocates some byte 
>> arrays (of 2 MB) each (running with the latest jdk-13). I run it with :
>>
[...]
>>
>> So the next cycle will have 9 Eden Regions and 2 Survivor ones (at 
>> least this is how I read the source code of where this is logged)
> 
> The nine eden regions are estimates based on pause time and some factors 
> like estimated allocation rate. The two survivor ones are actually 
> survivor regions allowed in the current GC (allowed survivor region 
> length is always determined at the start of GC). It should probably read
> 
> Survivor regions: 0(2)->1
> 
> In this case the limit for entire young gen is G1MaxNewSizePercent, 
> which by default is 60%; 60% of 20M is 12M, which is distributed across 
> Survivor and Eden according to SurvivorRatio (=8).

Note that in my local runs I always get

Eden regions: 1->0(10)
Survivor regions: 0->0(2)

In the stable state, that is, after initial allocations in young gen by 
the runtime have been moved into old gen.

>> [0.076s][debug][gc,heap           ] GC(2) Heap before GC invocations=2 
>> (full 0): garbage-first heap   total 20480K, used 7148K 
>> [0x00000007fec00000, 0x0000000800000000)
>> [0.076s][debug][gc,heap           ] GC(2)   region size 1024K, 2 young 
>> (2048K), 1 survivors (1024K)
>>
>> How come 2 young, 1 survivors? When the previous cycle said 9 Eden, 2 
>> Survivor.
> 
> Humongous allocations can make initial estimations about young gen size 
> obsolete.
> 
> I.e. the humongous allocations (directly into old gen) made old gen 
> occupancy cross the current threshold to start old gen reclamation. 
> Otherwise the humongous objects would have filled up the entire heap, 
> causing full gc.
> 

And actually answering the question: The number of young regions at the 
time of GC (e.g. "2") depend on when these extra GCs occur, i.e. how 
full eden/survivor were at that time.

The GC log also tells you that the root cause for the GCs has been a 
humongous allocation, i.e.

[info][gc,start] GC(xyz) Pause Young (Concurrent Start) (G1 Humongous 
Allocation)

Other log output before that (with the settings you gave) told you that 
the reason for the "concurrent cycle request" (read: gc) has been old 
gen occupancy being higher than a threshold, e.g.

[...][gc,ergo,ihop] Request concurrent cycle initiation (occupancy 
higher than threshold) occupancy: ...B allocation request: ...B 
threshold ...B (45.00) source: concurrent humongous allocation
[...][gc,ergo] Request concurrent cycle initiation (requested by GC 
cause). GC cause: G1 Humongous Allocation

I.e. the humongous objects caused the gc in order to try to clean them 
out from old gen.

Thanks,
   Thomas