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

[Bengt Rutisson]

Hi Thomas,

I like the "Concurrent Cycle" logging.

The change looks good to me.

Bengt

On 2016-03-14 13:19, Thomas Schatzl wrote:
> 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
>