RRF: JEP-271: Unified GC Logging

Mon Nov 23 15:51:17 UTC 2015

Hi David,

On 2015-11-20 18:12, David Lindholm wrote:
> Hi Bengt,
>
> This is great work. The code becomes much cleaner in many places. So 
> far I have reviewed cms, g1 and parallel.
>
> However, I have some comments:
>
> First, a general comment, I would like to remove the stats tag. I 
> think most of what we log is statistics, and I don't think this tag 
> adds value.

I see your point and I went through all usage of the stats tag.

(gc, freelist, stats)

I removed some, but kept the ones that call "statistics" methods. I 
think we can rename this in the future, but for now it seemed reasonable 
to keep the "stats" tag for controlling the output from methods called 
something with statistics.

(gc, stats)

I removed all usages of this except for in G1 concurrentMark.cpp where 
it is again used for methods called something with statistics.

(gc, marking, stats, exit)

Removed both stats and exit from these calls.

(gc, task, stats)

Kept these since they refer to "statistics" methods.

(gc, survivor, stats)

Removed the stats tag and moved to trace level logging.

>
> concurrentMarkSweepGeneration.cpp:
>
> 1443, printout talks about foreground collector. I thought the 
> foreground collector was gone?

The CMS foreground collector is gone, so the comment refers to that CMS 
is falling back to a full GC. I think you are right that the message 
could be changed now to more clearly state that. However, I would prefer 
to do that as a separate change later.

> 2129, indentation.

Done.

> CMSCollector::is_cms_reachable() seems to be dead code, this could be 
> removed in a separate patch.

Sent this out as a separate patch.

> CMSPhaseAccounting::wallclock_millis() seems to have a different 
> implementation than before, with different functionality.

This is really pretty ugly code. After some thinking and discussion with 
David we came to the conclusion that the new implementation is actually 
providing the same functionality as the old one.

> CMSCollector::markFromRoots() also talks about the foreground collector.

Same as above. I'd like to change that later.

> 4058, indentation
> 4066, "Scavenge Before Remark" should probably be "Pause Scavenge 
> Before Remark"
> 4166, indentation
> 4175, indentation
> 4181, indentation
> 4185, indentation

Fixed.

>
> concurrentMarkSweepGeneration.hpp:
>
> timerValue() has changed implementation to now return millis. Maybe 
> _timer.milliSeconds() could be used instead.

Unfortunately _timer.milliSeconds() truncates the returned value, so we 
loose precision. Instead I changed to that timerValue() returns the raw 
elapsed counter value and then I convert it to seconds in 
CMSPhaseAccounting, where it is used for a log message.

>
> parNewGeneration.cpp:
>
> 1184, "Queue overflow" -> "Queue Overflow"

Fixed.

>
> collectionSetChooser.cpp:
>
> 138, if (Log<LOG_TAGS(gc, liveness)>::is_trace()) should be 
> log_is_ebabled instead.
>
> concurrentMark.cpp:
>
> 1754, Log<LOG_TAGS(gc, liveness)>::is_trace() should be log_is_ebabled 
> instead.

I changed these and found a few more places where I had used that old 
pattern too. Updated all of them.

>
> g1CollectedHeap.cpp:
>
> G1CollectedHeap::create_aux_memory_mapper(). TracePageSize is not 
> converted. Will this be done in a later change?

Yes, I would like to change TracePageSize in a later change since it is 
a bit more complex and not purely a GC flag.

> 2721, p2i() could be used instead.

Done.

> Verifying is now printed on the verify tag. I think that when you 
> enable verification this tag should be enabled.

Good idea. Again, I think I prefer to do that a separate change.

> 2951, indentation
> 3220, indentation
> 3674, tm5 seems like a strange name
> print_termination_stats_hdr(), I don't think you have to du the check 
> in the beginning of this function, it contains just 4 printouts.
> 5713 - should be 1 row, not 2.
> 5729 - should be 1 row, not 2.
> 5740 - should be 1 row, not 2.
> 5750 - should be 1 row, not 2.

Fixed.

>
> g1GCPhaseTimes.cpp:
>
> 289 - use log_is_enabled() instead
> 301 - use log_is_enabled() instead
> 357 - remove commented out code
> 365 - remove commented out code

Fixed.

>
> g1_globals.hpp:
>
> 49 - "gc,remset" -> "gc+remset"

Fixed.

>
> g1StringDedupQueue.cpp
>
> 158-159, indentation
>
> g1StringDedupThread.cpp
>
> 156 - use log_is_enabled() instead
> 158 - use log_is_enabled() instead

Fixed.

>
> youngList.cpp
>
> 117, indent

Fixed.

>
> adjoiningGenerations.cpp
>
> Please remove 4 comments inside a call. Rows 170, 186, 212 and 230

Fixed.

>
> gcTaskManager.cpp
>
> 470-473 indent

Fixed.

>
> gcTaskThread.cpp
>
> 81, use log_is_enabled() instead
> 138, use log_is_enabled() instead
> 154, use log_is_enabled() instead

Fixed.

>
> psAdaptiveSizePolicy.cpp
>
> 698-702, this could be on one line.
> 789-793, this could be on one line.

Fixed.

>
> psParallelCompact.cpp
>
> 356, indentation.

Fixed.

Thanks,
Bengt

>
>
> Thanks,
> David
>
> On 2015-11-19 16:29, Bengt Rutisson wrote:
>>
>> Hi everyone,
>>
>> After three pre-reviews it is time for the fist official review 
>> request for JEP-271 Unified GC Logging.
>>
>> http://openjdk.java.net/jeps/271
>>
>> Most code changes are in the hotspot code:
>> http://cr.openjdk.java.net/~brutisso/JEP-271/review.00/webrev.00/
>>
>> Some tests in the JDK repo have been updated:
>> http://cr.openjdk.java.net/~brutisso/JEP-271/review.00/jdk-webrev.00/
>>
>> As with the pre-reviews I have put togther some examples of what the 
>> new logging looks like:
>> http://cr.openjdk.java.net/~brutisso/JEP-271/review.00/compare.html
>>
>> The intent is that this should cover the bulk of the logging changes. 
>> There will most definitely be some follow up changes where we fix 
>> details in the log messages etc.
>>
>> Among many other old logging flags this changeset removes the two 
>> flags PringGC and PrintGCDetails. These two will be added back with a 
>> follow up changeset, but when they are added back they will be marked 
>> as deprecated.
>>
>> The reason for first removing them and then adding them back is to 
>> get testing without these flags. That way we will know that we clean 
>> out all usages of these flags from our testing.
>>
>> Thanks,
>> Bengt
>