RFR (S): 8244815: Always log MMU information in G1

[stefan.johansson at oracle.com]

Hi,

On 2020-05-12 15:53, Thomas Schatzl wrote:
> Hi all,
> 
>    can I have reviews for this change that adds MMU logging for all 
> pauses, not only when it is violated?
> 
> This makes the logging similar to JFR events which are posted always too.
> 
> Ie. currently G1 prints
> 
> [95.616s][info ][gc,mmu        ] GC(2932) MMU target violated: 10.5ms 
> (10.0ms/11.0ms)
> 
> at info level if G1 did not keep MMU goals in the last pause.
> 
> This change adds the message
> 
> [82.315s][debug][gc,mmu        ] GC(2598) MMU target: 7.3ms (10.0ms/11.0ms)
> 
> at debug level even when MMU is kept. This helps with analyzing current 
> MMU.
> 
> There is some a bit ugly code to select the correct message level. Maybe 
> there is a better way. An alternative would be to move the message to 
> debug level always?
>
I would prefer a simple else clause doing the debug logging. Any problem 
with that? We could also split the logging into a helper, something like:
void G1MMUTrackerQueue::log_mmu(double slice_time) {
   double used_time = slice_time * 1000.0;
   double max_time = _max_gc_time * 1000.0;
   double interval = _time_slice * 1000;
   if (slice_time >= _max_gc_time) {
     log_info(gc, mmu)("MMU target violated: %.1lfms (%.1lfms/%.1lfms)",
                       used_time, max_time, interval);
   } else {
     log_debug(gc, mmu)("MMU: %.1lfms (%.1lfms/%.1lfms)",
                        used_time, max_time, interval);
   }
}

What do you think about that?

Thanks,
Stefan

> CR:
> https://bugs.openjdk.java.net/browse/JDK-8244815
> Webrev:
> http://cr.openjdk.java.net/~tschatzl/8244815/webrev/
> Testing:
> hs-tier1-3, eyeballing local logs
> 
> Thanks,
>    Thomas