JEP 271: Unified GC Logging - First pre-review

[Kirk Pepperdine]

Hi Benqt,

Looks like a great start but I think it will take some time to fully understand the impact of the new format. I think there is some noise that can be removed. For example, the start/end tags don’t seem necessary and it seems like it might be useful to combine some lines unless there was a run time reason to split the writes but this feels like it could be interpreted as bike shedding. That said, combining things would ease the parsing task, single event single line. However, we’d also have to consider the effects of adding even more details that generally get added in such as PrintAdaptiveSizePolicy or RSet refinement logging.

It’s great that some timestamps have been included because I’m not sure I’d want to rely on the time stamp provided by the logging framework. In the G1 example the #0 record as per below, doesn’t indicate a start time, [0.256s][info   ][start,gc] GC#0 GC young (G1 Evacuation Pause) start. My guess is in your tests it would be 0.234s. Based on my experience with app logging in general, I fully expect that given the verbosity of this logging framework combined with the downstream processing of entries (by UL),  there will be conditions under which UL will not be able to maintain the pace. For example, the danger of line by line processing of many short lines by UL would introduce both high overheads for logging and a very high noise to signal ratio in the logs. This would introduce a gap between when this event starts and when UL would tag it. FWIW, I don’t believe it should be UL’s responsibility to provide time stamps.

Kind regards,
Kirk



> On Oct 26, 2015, at 5:26 AM, Bengt Rutisson <bengt.rutisson at oracle.com> wrote:
> 
> 
> Hi again everyone,
> 
> An update on the work for JEP 271 Unified GC Logging.
> 
> I now have a working prototype that covers all GCs. Here are some examples comparing the old format (using -XX:+PrintGC and -XX:+PrintGCDetails) with the new format (using -Xlog):
> 
> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/compare.html
> 
> The new logging format, using -Xlog, is much more flexible than the old format. So, the comparison table on the above page is by no means complete. I hope it will give a good overview, but to get a real feel for how the new logging works I think it is necessary to run locally and play around with the logging options.
> 
> Here is a webrev of the changes so far:
> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.00/webrev.00/
> 
> There is still work to do and I have some known issues with the code changes. So, I am currently not asking for too much feedback on the actual code changes. I am more looking for feedback on the logging behavior. The webrev can be useful to get a feel for what the code changes will look like but mostly I think it can be used to apply the patch and build your own HotSpot to try out the new logging.
> 
> Some changes based on the initial feedback:
> - Start and end timestamps for the GC included on the GC log line.
> - Printing the unit of a value without a space. I.e. "10.345ms" instead of "10.345 ms". (Still working on fixing this in all places as well as trying to use milliseconds instead of seconds in as many places as possible.)
> - Printing heap change information with a fixed unit. I am now using M for overall heap transition and K for detailed information on the debug level.
> - Removed the "summary" tag. Instead the end logging for a GC includes all relevant information.
> 
> All feedback is very welcome!
> 
> Thanks,
> Bengt