JEP 271: Unified GC Logging

[Kirk Pepperdine]

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 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.

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.

Kind regards,
Kirk

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20150924/f0af94f1/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 496 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20150924/f0af94f1/signature.asc>