JEP 271: Unified GC Logging - First pre-review

Wed Oct 28 09:17:21 UTC 2015

Hi Staffan,

These are really good suggestions and in fact I was discussing this with 
Per yesterday. He had similar comments.

What I did for pauses was to make the start logging optional by adding a 
start tag to that logging.

The GC cause change that you suggest in your example. Using "Occupancy 
limit hit" seems good, but I would prefer to not change the GC causes 
right now. This can be done for JDK 9 but I think it should be done as a 
separate change.

I'll try to work most of your suggestions in to my prototype to see what 
it looks like.

Thanks,
Bengt

On 2015-10-27 16:43, Staffan Friberg wrote:
> 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
>>>>
>>>
>>
>