JEP 271: Unified GC Logging - Second pre-review

Mon Nov 9 08:59:08 UTC 2015

Hi Kirk,

On 2015-11-07 12:24, Kirk Pepperdine wrote:
> Hi Bengt,
>
> A couple of comments aimed at bulk and/or frequency trade-offs.
>
> [11.247s][info   ][gc          ] GC#265 GC young (G1 Evacuation Pause) 109M->71M(128M) (11.228s, 11.247s) 19.208ms
> with the exception of the pause time, this line seems redundant.

I may be misunderstanding your comment here, but this is the single line 
that is printed for a GC if you just run with the "gc" tag at info 
level, which I think will be the most common use case. I think we want 
to know what type of GC it is (young), what the GC cause was (G1 
Evacuation Pause), what the heap change was and what the duration was. 
You also wanted the start and stop timestamps. So, I don't see the 
redundancy in this line.

Maybe you mean that the information is redundant in the context of other 
logging? Can you in that case provide some more context?

>
> [11.247s][info   ][gc,heap     ] GC#265 Eden: 38912K->0K(2048K)
> [11.247s][info   ][gc,heap     ] GC#265 Survivor: 4096K->4096K(6144K)
> [11.247s][info   ][gc,heap     ] GC#265 Old: 68990K->73147K(131072K)
> [11.247s][info   ][gc,metaspace] GC#265 Metaspace: 2993K->2993K(1056768K)
> can these 4 lines be combined?

Technically they could be combined. I realize it would save some space 
due to the decorations, but other than that I think it is mostly  a 
matter of taste if they should be on one line or separate lines. 
Personally I find it easier to read them on separate lines. Especially 
if I just want to follow one of them closely.

>
> [11.726s][info   ][gc,start    ] GC#269 GC remark (11.726s)
> [11.740s][info   ][gc          ] GC#269 GC remark 76M->76M(128M) (11.726s, 11.740s) 14.211ms
> the paired timing seems redundant (as it does for all the other phases).

Since you can opt out of the "start" logging I think it is nice to have 
the start timestamp in the "end" logging. I guess we can remove the 
start timestamp from the "start" line, but I would prefer to have it 
there. It kind of makes sense to have it there to make it easier to 
detect discrepancies between the "GC" timestamp and the timestamp 
provided by the logging framwork in the decoration.

> From the other examples follows the same theme that there is frequent 
> logging of very small records that look like they should be combined. 
> From this example, could the reference processing be collapsed into a 
> single entry?
> [1.118s][trace  ][gc,start    ] GC#2 DefNew (Allocation Failure) (1.118s)
> [1.189s][debug  ][gc,ref,start] GC#2 SoftReference (1.189s)
> [1.189s][debug  ][gc,ref      ] GC#2 SoftReference (1.189s, 1.189s) 0.038ms
> [1.189s][debug  ][gc,ref,start] GC#2 WeakReference (1.189s)
> [1.189s][debug  ][gc,ref      ] GC#2 WeakReference (1.189s, 1.189s) 0.009ms
> [1.189s][debug  ][gc,ref,start] GC#2 FinalReference (1.189s)
> [1.189s][debug  ][gc,ref      ] GC#2 FinalReference (1.189s, 1.189s) 0.007ms
> [1.189s][debug  ][gc,ref,start] GC#2 PhantomReference (1.189s)
> [1.189s][debug  ][gc,ref      ] GC#2 PhantomReference (1.189s, 1.189s) 0.007ms
> [1.189s][debug  ][gc,ref,start] GC#2 JNI Weak Reference (1.189s)
> [1.189s][debug  ][gc,ref      ] GC#2 JNI Weak Reference (1.189s, 1.189s) 0.008ms
> [1.189s][debug  ][gc,ref      ] GC#2 Ref Counts: Soft 0 Weak: 0 Final: 0 Phantom: 0
> [1.195s][debug  ][gc,age      ] GC#2 Desired survivor size 2228224 bytes, new threshold 15 (max threshold 15)
> [1.195s][trace  ][gc,age      ] GC#2 - age   1:    1936136 bytes,    1936136 total
> [1.195s][trace  ][gc          ] GC#2 DefNew (Allocation Failure) (1.118s, 1.195s) 76.775ms
> [1.195s][debug  ][gc          ] GC#2 Collect gen: DefNew (1.118s, 1.195s) 76.822ms
> [1.195s][info   ][gc,heap     ] GC#2 DefNew: 39296K->1890K(39296K)
> [1.195s][info   ][gc,heap     ] GC#2 Tenured: 54815K->58866K(87424K)
> [1.195s][info   ][gc,metaspace] GC#2 Metaspace: 2987K->2987K(1056768K)
> [1.195s][info   ][gc          ] GC#2 GC pause, DefNew (Allocation Failure) 91M->59M(123M) (1.118s, 1.195s) 77.046ms
> [1.195s][info   ][gc,cpu      ] GC#2 User=0.08s Sys=0.00s Real=0.08s

Again, maybe I am missunderstanding. But the idea with the "start" tag 
is that you can easily turn it off. If you don't want the start line 
just disable that part of the logging. For example by doing 
"-Xlog:start*=off". That way you get a single entry for each timing phase.

Thanks for your feedback!
Bengt

> Regards,
> Kirk
>
>> On Nov 6, 2015, at 5:08 PM, Bengt Rutisson <bengt.rutisson at oracle.com 
>> <mailto:bengt.rutisson at oracle.com>> wrote:
>>
>>
>> Hi everyone,
>>
>> Here is an updated pre-review for the work for JEP 271 Unified GC 
>> Logging.
>>
>> I've converted most of the GC logging now. Some of the CMS logging is 
>> still left to convert. In particular I've converted the 
>> PrintAdaptiveSizePolicy loggging. I turned that into logging on the 
>> "ergo" tag in combination with some other tags to give more fine 
>> grain control over the logging.
>>
>> Here are examples from the latest prototype:
>> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/compare.html 
>> <http://cr.openjdk.java.net/%7Ebrutisso/JEP-271/pre-review.01/compare.html>
>>
>> The webrev for the changes is available here:
>> http://cr.openjdk.java.net/~brutisso/JEP-271/pre-review.01/webrev.01/
>>
>> i haven't had a chance to address all comments from the last 
>> pre-review. CMS is still not completed, so the comments regarding the 
>> concurrent cycle logging have not been addressed. This is the next 
>> thing on my todo-list.
>>
>> Some of the thing that have changed since last time:
>>
>> - Added a timestamp in the "start" line for GC timing
>> - Removed "start" and "end" words from the GC timing
>> - Dropped "CPU Time" from the CPU time line
>> - Converted most of the logging in the GC code base
>>
>> Thanks,
>> Bengt
>>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20151109/af4ed7e2/attachment.htm>