RFR (S): 8151614: Improve logging in concurrent mark code

[Thomas Schatzl]

Hi Bengt,

  thanks for your review.

On Fri, 2016-03-11 at 15:19 +0100, Bengt Rutisson wrote:
> Hi Thomas,
> 
> On 2016-03-10 18:02, Thomas Schatzl wrote:
> > Hi all,
> > 
> >    can I have reviews for this change that improves the logging 
> > code for concurrent mark by:
> > 
> > - removes the need to have two scoped objects, one for logging, one 
> > for JFR for every phase
> > - tries to make the phase names correspond to method names
> > - add a "marking" tag to marking related log messages
> 
> I don't really like the addition of the "marking" tag. It means that 
> if you run with -Xlog:gc you don't get any logging about the 
> concurrent cycle. This log configuration is supposed to be similar to 
> the old -XX:+PrintGC, which I think should give at least some 
> relevant information about each GC - including the concurrent cycle.

I agree with you that we need to have some kind of information about
concurrent phases when using -XX:+PrintGC.

So I took a step back and analyzed what log output we get from
concurrent phases today: there is actual marking ("Mark From Roots"
now), and concurrent cleanup.

These two do not represent the entirety of the concurrent mark at all,
further these are just two (although significant) parts of the
concurrent cycle.

Trying to second-guess what a user that only uses PrintGC wants to see,
I believe that at this level there is no need for detail, although we
should be fairly correct in what we show. I came up with a new, single
log message that covers the whole marking cycle called "Concurrent
Cycle" that is printed at Info/gc level.

That seems much better to me than trying to decide what of the existing
message should be taken as representative for the concurrent phase.

With -XX:+PrintGCDetails, the messages tagged with "gc, marking" are
printed already, so no loss of information there (actually, due to
being complete, there is some gain by this change).

> > - removes a duplicate log message ("Restart for overflow") at 
> > different levels
> > 
> > CR:
> > https://bugs.openjdk.java.net/browse/JDK-8151614
> > Webrev:
> > http://cr.openjdk.java.net/~tschatzl/8151614/webrev/
> 
> In the G1ConcPhaseTimer class you can use the LOG_TAGS macro to get a
> bit more readable code. Chaning:
> 
>       GCTraceConcTimeImpl<LogLevel::Info,  LogTag::_gc, 
> LogTag::_marking>(title),
> 
> to:
> 
>       GCTraceConcTimeImpl<LogLevel::Info,  LOG_TAGS(gc,
> marking)>(title),

Thanks a lot, fixed.

New webrevs at:
http://cr.openjdk.java.net/~tschatzl/8151614/webrev.1/ (full)
http://cr.openjdk.java.net/~tschatzl/8151614/webrev.0_to_1/ (diff)

I think this solution is quite nice now.

Thanks a lot,
  Thomas