Minor question about logging

[Stefan Johansson]

Hi Eugeniu,

The second GC is most likely also caused by having many humongous 
allocations. This was the cause GC(0) as well, and since your 
application only allocates large (humongous) objects it will not use a 
lot of space for other objects.

If you are not familiar with the concept of humongous objects in G1, 
these are objects that are to large to be allocated in the normal fast 
path. They are instead allocated in separate regions. This requires some 
special handling and that's the reason we trigger GCs more quickly if a 
lot of such objects are allocated. In your setup the region size will be 
1MB so all objects larger than 500KB will be considered humongous.

Hope this helps,
StefanJ


On 2020-03-08 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 :
> 
> -Xms20M
> -Xmx20M
> -Xmn10M
> "-Xlog:heap*=debug" "-Xlog:gc*=debug" "-Xlog:ergo*=debug"
> 
> 
> For example:
> 
>      public static void main(String[] args) {
>          while (true) {
>              System.out.println(invokeMe());
>          }
>      }
> 
>      public static int invokeMe() {
>          int x = 1024;
>          int factor = 2;
>          byte[] allocation1 = new byte[factor * x * x];
>          allocation1[2] = 3;
>          byte[] allocation2 = new byte[factor * x * x];
>          byte[] allocation3 = new byte[factor * x * x];
>          byte[] allocation4 = new byte[factor * x * x];
> 
>          return Arrays.hashCode(allocation1) ^ Arrays.hashCode(allocation2)
>              ^ Arrays.hashCode(allocation3) ^ Arrays.hashCode(allocation4);
>      }
> 
> In logs, I see something that is puzzling me:
> 
> 
> [0.066s][debug][gc,ergo       ] Request concurrent cycle initiation 
> (requested by GC cause). GC cause: G1 Humongous Allocation
> [0.066s][debug][gc,heap       ] GC(0) Heap before GC invocations=0 (full 
> 0): garbage-first heap   total 20480K, used 6908K [0x00000007fec00000, 
> 0x0000000800000000)
> [0.066s][debug][gc,heap       ] GC(0)   region size 1024K, 1 young 
> (1024K), 0 survivors (0K)
> 
> OK, so Heap Before: 1 young, 0 survivors.
> 
> Then:
> 
> [0.071s][info ][gc,heap        ] GC(0) Eden regions: 1->0(9)
> [0.071s][info ][gc,heap        ] GC(0) Survivor regions: 0->1(2)
> [0.071s][info ][gc,heap        ] GC(0) Old regions: 0->0
> 
> 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)
> 
> Then a GC(1) concurrent cycle happens:
> 
> [0.071s][info ][gc             ] GC(1) Concurrent Cycle
> 
> And the next cycle is where I fail to understand the logging:
> 
> [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.
> 
> Thank you,
> Eugene.
> 
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>