JEP 271: Unified GC Logging - First pre-review

Tue Oct 27 15:43:08 UTC 2015

Hi,

Looking at the CMS logs I was wondering if we could unify them and make 
them more similar to the ParNew. G1 could probably get a similar change.

Quick summary of changes
     Add reason
     Drop end
     Drop start printouts
     Add start and end to concurrent phases similar to pause phases

I can see part of the benefit of having a start and end printout for 
concurrent phases, you would know that it is running, but the same would 
hold true for pauses as well and since we only print a single line for 
pauses it might be OK for concurrent phases.
Could potentially be more critical for pauses since the application is 
stopped someone (or a script) might actually check the log for what is 
going on and find nothing, in a concurrent phase the application is most 
likely still execution.

[2.992s][info   ][gc] GC#6 GC (Allocation Failure) ParNew end 
91M->60M(123M) (2.982s, 2.992s) 10.072ms
[2.994s][info   ][gc] GC#7 GC (CMS Initial Mark) end (2.992s, 2.994s) 
1.658ms
[2.994s][info   ][gc] GC#7 CMS-concurrent-mark-start
[3.180s][info   ][gc] GC#7 CMS-concurrent-mark: 0.098/0.186 secs
[3.181s][info   ][gc] GC#7 CMS-concurrent-preclean-start
[3.513s][info   ][gc] GC#7 CMS-concurrent-preclean: 0.172/0.333 secs
[3.513s][info   ][gc] GC#7 CMS-concurrent-abortable-preclean-start
[3.545s][info   ][gc] GC#7 CMS-concurrent-abortable-preclean: 
0.019/0.032 secs
[3.551s][info   ][gc] GC#7 GC (CMS Final Remark) end (3.545s, 3.551s) 
5.768ms
[3.551s][info   ][gc] GC#7 CMS-concurrent-sweep-start
[5.023s][info   ][gc] GC#7 CMS-concurrent-sweep: 0.775/1.472 secs
[5.024s][info   ][gc] GC#7 CMS-concurrent-reset-start
[5.024s][info   ][gc] GC#7 CMS-concurrent-reset: 0.000/0.000 secs

[2.992s][info   ][gc] GC#6 GC (Allocation Failure) ParNew 91M->60M(123M) 
(2.982s, 2.992s) 10.072ms
[2.994s][info   ][gc] GC#7 GC (Occupancy Limit Hit) CMS-initial-mark 
(2.992s, 2.994s) 1.658ms
[3.180s][info   ][gc] GC#7 GC (Occupancy Limit Hit) CMS-concurrent-mark 
(2.994s, 3.180s) 0.098/0.186 secs
[3.513s][info   ][gc] GC#7 GC (Occupancy Limit Hit) 
CMS-concurrent-preclean (3.181s, 3.513s) 0.172/0.333 secs
[3.545s][info   ][gc] GC#7 GC (Occupancy Limit Hit) 
CMS-concurrent-abortable-preclean (3.513s, 3.545s) 0.019/0.032 secs
[3.551s][info   ][gc] GC#7 GC (Occupancy Limit Hit) CMS-final-remark 
(3.545s, 3.551s) 5.768ms
[5.023s][info   ][gc] GC#7 GC (Occupancy Limit Hit) CMS-concurrent-sweep 
(3.551s, 5.023) 0.775/1.472 secs
[5.024s][info   ][gc] GC#7 GC (Occupancy Limit Hit) CMS-concurrent-reset 
(5.024s, 5.024s) 0.000/0.000 secs

//Staffan

On 10/27/2015 08:23 AM, Staffan Friberg wrote:
> Ah, think I got confused by the GC id being printed. I guess that is 
> new in JDK 9 EA?
>
> //Staffan
>
> On 10/26/2015 11:13 PM, Bengt Rutisson wrote:
>>
>> Hi Staffan,
>>
>> Thanks for looking at this!
>>
>> On 2015-10-26 18:14, Staffan Friberg wrote:
>>> Just skimmed so far, will give it a more through look.
>>>
>>> Do we want to keep the space after the the Times output? Does it add 
>>> any value?
>>> Can bite you sometimes when you grep and look for line endings.
>>>
>>> "[Times: user=0.10 sys=0.00 real=0.02 secs] "
>>>
>>
>> Maybe I was unclear in my email. The logs for PrintGC and 
>> PrintGCDetails are the logs for the "old" logging. In the new logging 
>> the Times output looks like this:
>>
>> [1.165s][info   ][gc,cpu      ] GC#1 CPU Times: user=0.39s sys=0.00s 
>> real=0.40s
>>
>> Or am I misunderstanding the question?
>>
>> Bengt
>>
>>> //Staffan
>>>
>>> On 10/26/2015 05:26 AM, Bengt Rutisson 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
>>>
>>
>