How to calculate object promotion rate from g1gc logs?

Question

I am using the below equation to calculate bytes promoted from parallel GC logs

promoted_bytes = (('younggen_used_before_gc') - ('younggen_used_after_gc')) - (('heap_used_before_gc') - ('heap_used_after_gc'))

How to calculate the same from G1GC logs?

The above equation works fine with parallel GC logs, but it is giving negative value(-147.6) for the below G1GC log event

2019-04-24T13:41:06.982+0000: 59627.940: [GC pause (G1 Evacuation Pause) (young), 0.1640632 secs]    
   [Parallel Time: 161.0 ms, GC Workers: 2]    
      [GC Worker Start (ms): Min: 59627940.0, Avg: 59627940.0, Max: 59627940.0, Diff: 0.0]    
      [Ext Root Scanning (ms): Min: 56.4, Avg: 57.5, Max: 58.6, Diff: 2.1, Sum: 115.0]    
      [Update RS (ms): Min: 7.1, Avg: 7.2, Max: 7.3, Diff: 0.3, Sum: 14.4]    
         [Processed Buffers: Min: 46, Avg: 58.5, Max: 71, Diff: 25, Sum: 117]    
      [Scan RS (ms): Min: 3.7, Avg: 3.8, Max: 3.9, Diff: 0.2, Sum: 7.7]    
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]    
      [Object Copy (ms): Min: 91.3, Avg: 92.4, Max: 93.4, Diff: 2.1, Sum: 184.8]    
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]    
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]    
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]    
      [GC Worker Total (ms): Min: 160.9, Avg: 160.9, Max: 160.9, Diff: 0.0, Sum: 321.9]    
      [GC Worker End (ms): Min: 59628100.9, Avg: 59628100.9, Max: 59628100.9, Diff: 0.0]    
   [Code Root Fixup: 0.1 ms]    
   [Code Root Purge: 0.0 ms]    
   [Clear CT: 0.6 ms]    
   [Other: 2.3 ms]    
      [Choose CSet: 0.0 ms]    
      [Ref Proc: 0.8 ms]    
      [Ref Enq: 0.1 ms]    
      [Redirty Cards: 0.4 ms]    
      [Humongous Register: 0.1 ms]    
      [Humongous Reclaim: 0.2 ms]    
      [Free CSet: 0.2 ms]    
   [Eden: 352.0M(352.0M)->0.0B(392.0M) Survivors: 56.0M->16.0M Heap: 5133.7M(8192.0M)->4594.1M(8192.0M)]    
 [Times: user=0.32 sys=0.00, real=0.17 secs]

This is the problem I am facing currently and from G1GC logs, the promoted bytes value is coming to negative value for most of the log events

Is there a different equation for promoted bytes calculation from G1GC logs? Am I missing anything here?

score 0 · Answer 1 · answered Aug 23 '19 at 03:55

Can be due to the Humongous Objects reclaim:

[Humongous Reclaim: 0.2 ms]  --> Time spent to free humongous regions

Humongous Objects are allocated directly in the old generation and were collected only at the end of the marking cycle or during Full GCs (refer here).

However, since JDK 8u40, by default, G1GC reclaims dead humongous objects objects at every young GCs (refer here).

Can try to turn off this feature and measure again:

-XX:-G1ReclaimDeadHumongousObjectsAtYoungGC

How to calculate object promotion rate from g1gc logs?

1 Answers1