JEP 271: Unified GC Logging

[Bengt Rutisson]

Hi Kirk,

On 2015-09-24 15:29, Kirk Pepperdine wrote:
> Hi Bengt,
>
>>
>> Yes, providing logging that is not interleaved with other logging is 
>> indeed one of the main reasons for moving over to the new logging 
>> framework. I agree that this should make things much easier for tools 
>> that parse the log files in the future.
>
> Well, I would argue for something a little stronger.
>
> For example we have this
>
> 10.099: [GC (Allocation Failure) 10.099: [ParNew10.100: [SoftReference, 0 refs, 0.0000141 secs]10.100: [WeakReference, 0 refs, 0.0000029 secs]10.100: [FinalReference, 0 refs, 0.0000026 secs]10.100: [PhantomReference, 0 refs, 0 refs, 0.0000033 secs]10.100: [JNI Weak Reference, 0.0000045 secs] (promotion failed): 72353K->71961K(78656K), 0.0009583 secs]10.100: [CMS10.100: [CMS-concurrent-abortable-preclean: 0.210/2.397 secs] [Times: user=15.12 sys=0.27, real=2.40 secs]
> which is really an ParNew allocation failure dropping into a concurrent mode failure which closes off the abortable-preclean phase and the record contains reference processing information. All good information.
> 10.099: [GC (Allocation Failure) 10.099: [ParNew (promotion failed): 72353K->71961K(78656K), 0.0009583 secs]
> 10.100: [CMS10.100: [CMS-concurrent-abortable-preclean: 0.210/2.397 secs] [Times: user=15.12 sys=0.27, real=2.40 secs]
> 10.100: [SoftReference, 0 refs, 0.0000141 secs]10.100: [WeakReference, 0 refs, 0.0000029 secs]10.100: [FinalReference, 0 refs, 0.0000026 secs]10.100: [PhantomReference, 0 refs, 0 refs, 0.0000033 secs]10.100: [JNI Weak Reference, 0.0000045 secs]
> Without reference processing (-XX:+PrintReferenceGC I think is the flag) you’ll get this
> 10.099: [GC (Allocation Failure) 10.099: [ParNew (promotion failed)10.100: [CMS10.100: [CMS-concurrent-abortable-preclean: 0.210/2.397 secs] [Times: user=15.12 sys=0.27, real=2.40 secs]
> : 72353K->71961K(78656K), 0.0009583 secs]
> Not so bad that the concurrent phase gets closed in the same line as the ParNew but that the Reference GC shifts it over is a bit of a pain.
> I would hope that this record would look the same irregardless if the equivalent of PrintReferenceGC was turned on or not.

I totally agree. My intent is that all log records should always look 
the same no matter what other logging is enabled. In particular I plan 
to use a "ref" tag for the reference processing and log that on separate 
lines. I think that will look pretty natural given the new start and end 
lines for the GC. I'll post an example of that when I have it implemented.

> I can root around for better example if you’re interested. Or, maybe there is a way I can make my DB of gc logs available.

Thanks, but I don't think that is necessary for this purpose. I think I 
understand the issues you describe. But for other reasons it would of 
course be interesting if you could make your DB of logs available. :)

> One point on date stamps. The can often get misaligned with the time stamp. So I’m inclined to pick up the first date as a reference point and then calculate dates using the time stamp from there on. It gets rid of most weird conditions that can happen when the values get misaligned and you think you’ve gone back in time when you haven’t.

I'm not quite sure I understand your issue here. But the absolute time 
and date stamps will all be provided by the decorations support in the 
unified logging framework. So, maybe this question is better discussed 
in that thread? The GC logging will only add duration timing.

Cheers,
Bengt
>
> Kind regards,
> Kirk

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