Fwd: JEP 271: Unified GC Logging
Bengt Rutisson
bengt.rutisson at oracle.com
Fri Sep 25 09:19:18 UTC 2015
On 2015-09-24 18:14, Bernd wrote:
> forget to cc the list:
Hi Bernd,
On 2015-09-24 18:13, Bernd wrote:
> Are you planning to use different locales for the number rendering? In
> your example the comma is not only confusing but also makes it harder
> to parse.
If you are referring the logging of times in my example then they are
printed with the %f formating in C++. So, they will by locale dependent.
This is the same as in the existing GC logging. My locale is Swedish,
thus the commas as decimal separators.
> Will size numbers always printed with dynamic units?
Currently I use the same conversion as the existing GC logging.
Personally I don't like it when the unit for a repeated log record
changes dynamically. But I'll leave it the same way we have it now for
starters. In a second step we can review the unit formatting.
> is it
> possible to stick with one format for seperating units from numbers
> (i.e. "12 ms" vs. "12M")
Sorry, I'm not sure understand this question. Are you referring to the
space between the number and the unit? In that case, sure, we can try to
standardize on it. What do you prefer ? With or without space?
>
> The GC number in all lines which belong together and the different
> levels look good. How do you handle collectiopns which kick off other
> collections?
This will be the same as it is today with the GC number. The next
collection will get a new GC number.
Similarly concurrent collections. They will keep their GC number
throughout the concurrent cycle and young GCs that happen during the
cycle will have their own number.
> Personally I think we dont need xml, but we should have a simple
> pattern to parse those lines.
>
> <blank>*[Name: att1=123 Unit, att2=123 Unit, ...]
>
> This allows variable indention, variable number of attributes. And if
> you stick to "." decimal even the , has a function
Not sure we want to stick to "." as a decimal separator. I realize that
having it locale dependent can cause problems, but it is the standard
way of formating floating point numbers.
>
> Gruss
> Bernd
>
> PS: while you are at it, does the new logging framewor allow rolling
> logging and avoids overwriting the current log on restart (something
> the current log settings not allow without using %p).
I think all that is supported, but it is supported through the unfied
logging framework. So, it might be better to ask about that in that
email thread.
Cheers,
Bengt
>
>
>
>
>
> 2015-09-24 14:08 GMT+02:00 Bengt Rutisson <bengt.rutisson at oracle.com>:
>>
>> On 2015-09-24 04:24, mark.reinhold at oracle.com wrote:
>>> New JEP Candidate: http://openjdk.java.net/jeps/271
>>>
>>> - Mark
>>
>> Hi everyone,
>>
>> I've started implementing a prototype for this JEP and thought I'd
>> provide
>> some samples of what I have done so far. Below are a few examples.
>> There is
>> more to think about and discuss than what I have shown below, but I hope
>> this is a good start. I will post more updates as I move forward with
>> the
>> prototype.
>>
>> Running with -XX:+PrintGC in the current code will give logging like
>> this:
>>
>> #14: [GC pause (G1 Evacuation Pause) (young) 106M->63M(128M), 0,0089484
>> secs]
>>
>> This line is actually printed in several steps. At the start of the
>> GC the
>> first part is written, then at the end of the GC the second part is
>> written
>> (actually the last part is written in two steps, first the heap usage
>> information and then the timing information).
>>
>> The unified logging framework does not support logging partial lines
>> (for
>> good reasons), so I'm replacing this single line with two lines
>> logged on
>> the "gc" tag at "info" level. That is, in my prototype running with
>> -Xlog:gc
>> will give the following log lines:
>>
>> [0,743s][info][gc] GC#14 start [young, G1 Evacuation Pause]
>> [0,756s][info][gc] GC#14 end [111,1M->100,2M(128,0M)] [12,808 ms]
>>
>> The exact formatting of these lines is not set in stone yet, and I'm
>> happy
>> to hear some suggestions on how to format this nicely, but some
>> important
>> things I'd like to point out:
>>
>> - Splitting the single log line up into two lines makes sure that we
>> don't
>> get other logging interleaved inside the GC start/end log lines.
>> - The timestamp decorations allows for nicer tracking of GC times
>> than just
>> the duration and a single timestamp (as if you would run with
>> PrintGCTimestamps today).
>> - I'm logging the duration of the GC in milliseconds rather than
>> seconds.
>> Using seconds sets the wrong expectations IMHO.
>> - The GC number (GC#14 in the example above) is logged using the prefix
>> support in the unified logging framework. Thus it will be added to
>> all GC
>> logging automatically.
>>
>>
>> For those that really just want one line per GC, I've added a
>> "summary" tag.
>> Running with -Xlog:gc+summary will give one line per GC that looks like
>> this:
>>
>> [0,768s][info][gc,summary] GC#14 [young, G1 Evacuation Pause]
>> [112,5M->100,6M(128,0M)] [15,697 ms]
>>
>> This line is printed at the *end* of the the GC. It will be logged
>> with one
>> single log statement, so no other logging can be interleaved with it.
>>
>>
>>
>> Running with PrintGCDetails in the current code give some more
>> information
>> than with just PrintGC. In particular G1 is pretty verbose when run with
>> PrintGCDetails. A typical G1 log section for a GC when run with
>> PrintGCDetails looks like this:
>>
>> #14: [GC pause (G1 Evacuation Pause) (young), 0,0098534 secs]
>> [Parallel Time: 3,2 ms, GC Workers: 23]
>> [GC Worker Start (ms): Min: 530,9, Avg: 531,3, Max: 531,6,
>> Diff: 0,7]
>> [Ext Root Scanning (ms): Min: 0,0, Avg: 0,1, Max: 0,4, Diff:
>> 0,4, Sum:
>> 1,8]
>> [Update RS (ms): Min: 0,0, Avg: 0,2, Max: 1,8, Diff: 1,8, Sum:
>> 4,0]
>> [Processed Buffers: Min: 0, Avg: 1,0, Max: 3, Diff: 3, Sum:
>> 24]
>> [Scan RS (ms): Min: 0,0, Avg: 0,0, Max: 0,1, Diff: 0,1, Sum: 0,2]
>> [Code Root Scanning (ms): Min: 0,0, Avg: 0,0, Max: 0,0, Diff:
>> 0,0,
>> Sum: 0,0]
>> [Object Copy (ms): Min: 0,0, Avg: 1,1, Max: 1,3, Diff: 1,2,
>> Sum: 26,2]
>> [Termination (ms): Min: 0,0, Avg: 0,6, Max: 0,6, Diff: 0,6,
>> Sum: 13,1]
>> [Termination Attempts: Min: 1, Avg: 5,5, Max: 7, Diff: 6,
>> Sum: 127]
>> [GC Worker Other (ms): Min: 0,0, Avg: 0,0, Max: 0,2, Diff:
>> 0,2, Sum:
>> 1,1]
>> [GC Worker Total (ms): Min: 1,7, Avg: 2,0, Max: 2,4, Diff:
>> 0,8, Sum:
>> 46,5]
>> [GC Worker End (ms): Min: 533,3, Avg: 533,3, Max: 533,5, Diff:
>> 0,2]
>> [Code Root Fixup: 0,0 ms]
>> [Code Root Purge: 0,0 ms]
>> [Clear CT: 2,4 ms]
>> [Other: 4,3 ms]
>> [Choose CSet: 0,0 ms]
>> [Ref Proc: 2,4 ms]
>> [Ref Enq: 0,0 ms]
>> [Redirty Cards: 1,7 ms]
>> [Humongous Register: 0,0 ms]
>> [Humongous Reclaim: 0,0 ms]
>> [Free CSet: 0,1 ms]
>> [Eden: 44,0M(44,0M)->0,0B(45,0M) Survivors: 4096,0K->4096,0K Heap:
>> 107,6M(128,0M)->63,8M(128,0M)]
>> [Times: user=0,07 sys=0,00 real=0,01 secs]
>>
>>
>>
>> I've split this logging up a bit over a few different tags to give
>> the user
>> more control over the output. This can be seen by running with
>> -Xlog:gc*=debug. Here's what that looks like in my prototype today:
>>
>>
>> [0,782s][info ][gc ] GC#14 start [young, G1 Evacuation Pause]
>> [0,799s][debug ][gc,phases ] GC#14 Parallel Time: 5,4 ms
>> [0,799s][debug ][gc,phases ] GC#14 GC Worker Start: Min:
>> 782,6, Avg: 783,0, Max: 783,3, Diff: 0,7
>> [0,799s][debug ][gc,phases ] GC#14 Ext Root Scanning: Min:
>> 0,0, Avg: 0,1, Max: 0,4, Diff: 0,4, Sum: 2,8
>> [0,799s][debug ][gc,phases ] GC#14 Update RS: Min:
>> 0,0, Avg: 0,3, Max: 2,6, Diff: 2,6, Sum: 7,0
>> [0,799s][debug ][gc,phases ] GC#14 Processed
>> Buffers: Min:
>> 0, Avg: 1,1, Max: 3, Diff: 3, Sum: 25
>> [0,799s][debug ][gc,phases ] GC#14 Scan RS: Min:
>> 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,1
>> [0,799s][debug ][gc,phases ] GC#14 Code Root Scanning: Min:
>> 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
>> [0,799s][debug ][gc,phases ] GC#14 Object Copy: Min:
>> 1,1, Avg: 3,3, Max: 3,6, Diff: 2,5, Sum: 75,7
>> [0,799s][debug ][gc,phases ] GC#14 Termination: Min: 0,0,
>> Avg: 0,1, Max: 0,2, Diff: 0,2, Sum: 2,9
>> [0,799s][debug ][gc,phases ] GC#14 Termination
>> Attempts: Min:
>> 1, Avg: 1,0, Max: 1, Diff: 0, Sum: 23
>> [0,799s][debug ][gc,phases ] GC#14 GC Worker Other: Min:
>> 0,0, Avg: 0,1, Max: 0,4, Diff: 0,4, Sum: 3,1
>> [0,799s][debug ][gc,phases ] GC#14 GC Worker Total: Min:
>> 3,6, Avg: 4,0, Max: 4,3, Diff: 0,7, Sum: 91,7
>> [0,799s][debug ][gc,phases ] GC#14 GC Worker End: Min:
>> 786,9, Avg: 787,0, Max: 787,2, Diff: 0,4
>> [0,799s][debug ][gc,phases ] GC#14 Code Root Fixup: 0,0 ms
>> [0,799s][debug ][gc,phases ] GC#14 Code Root Purge: 0,0 ms
>> [0,799s][debug ][gc,phases ] GC#14 Clear CT: 2,7 ms
>> [0,799s][debug ][gc,phases ] GC#14 Other: 8,5 ms
>> [0,800s][debug ][gc,phases ] GC#14 Choose CSet: 0,0 ms
>> [0,800s][debug ][gc,phases ] GC#14 Ref Proc: 2,4 ms
>> [0,800s][debug ][gc,phases ] GC#14 Ref Enq: 0,0 ms
>> [0,800s][debug ][gc,phases ] GC#14 Redirty Cards: 2,0 ms
>> [0,800s][debug ][gc,phases ] GC#14 Humongous Register: 0,0 ms
>> [0,800s][debug ][gc,phases ] GC#14 Humongous Reclaim: 0,0 ms
>> [0,800s][debug ][gc,phases ] GC#14 Free CSet: 3,5 ms
>> [0,800s][debug ][gc,heap ] GC#14 Eden: Used before: 17,0M Used
>> after: 0,0B Capacity: 17,0M
>> [0,800s][debug ][gc,heap ] GC#14 Survivor: Used before: 3072,0K Used
>> after: 3072,0K Capacity: 3072,0K
>> [0,800s][debug ][gc,heap ] GC#14 Heap: Used before: 110,7M Used
>> after: 94,3M Capacity: 128,0M
>> [0,800s][info ][gc,summary] GC#14 [young, G1 Evacuation Pause]
>> [110,7M->94,3M(128,0M)] [16,562 ms]
>> [0,800s][info ][gc ] GC#14 end [110,7M->94,3M(128,0M)]
>> [16,562 ms]
>> [0,800s][debug ][gc ] GC#14 [Times: user=0,10 sys=0,00 real=0,02
>> secs]
>>
>>
>>
>> For example, if you are not interested in the timing of the different
>> phases, but still want to know the eden/survivor usage you can run with
>> -Xlog:gc,gc+heap=debug and you get this information for each GC:
>>
>> [0,771s][info ][gc ] GC#14 start [young, G1 Evacuation Pause]
>> [0,788s][debug ][gc,heap] GC#14 Eden: Used before: 15,0M Used
>> after:
>> 0,0B Capacity: 14,0M
>> [0,788s][debug ][gc,heap] GC#14 Survivor: Used before: 3072,0K Used
>> after:
>> 3072,0K Capacity: 3072,0K
>> [0,788s][debug ][gc,heap] GC#14 Heap: Used before: 111,2M Used
>> after:
>> 97,1M Capacity: 128,0M
>> [0,788s][info ][gc ] GC#14 end [111,2M->97,1M(128,0M)] [16,651 ms]
>>
>>
>>
>> My intent is to remove all Print*GC* and Trace*GC* flags that we
>> currently
>> have and replace them with tags for the unified logging framework. As
>> shown
>> with the PrintGCDetails example above it is not sure that there will
>> be a
>> simple mapping from one flag to one tag. But all information that is
>> currently logged will be logged in the new implementation too. Since the
>> decorations include the tags it is pretty easy to find out what tags
>> interesting information is logged on and configure your logging to
>> show that
>> information.
>>
>> I'm currently thinking that we should probably keep the PrintGC and
>> PrintGCDetails flags since they are very widely used. We could deprecate
>> them and just have them map to some -Xlog configuration. My
>> suggestion would
>> be to map PrintGC to -Xlog:gc and PrintGCDetails to -Xlog:gc*=debug.
>>
>> All the examples above are from my current prototype. This is work in
>> progress and may well change when it is time for the final review round.
>>
>> I'm happy to hear feedback now, but I will also try to post updates
>> on this
>> mailing list as I move forward with my prototype.
>>
>> Thanks,
>> Bengt
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20150925/27d3114c/attachment.htm>
More information about the hotspot-gc-dev
mailing list