RFR (L): 8046148: JEP 158 Unified JVM Logging

[Kirk Pepperdine]

> On Sep 14, 2015, at 6:01 PM, Ioi Lam <ioi.lam at oracle.com> wrote:
> 
> 
> 
> On 9/14/15 6:18 AM, Marcus Larsson wrote:
>> 
>> On 2015-09-11 15:51, Coleen Phillimore wrote:
>>> 
>>> I'm not a big fan of having these blanks in the logging lines. I don't think making the line length longer is going to be helpful and what people are looking for is the message at the end, not which tag and level they used.  I think they look kind of strange.
>>> 
>>> Coleen
>> 
>> While it might look a bit weird, I think it can help readers to quickly find the start of the actual log message. Maybe we could leave it as it is for now, deferring the decision if we want the padding or not until we have some real logs to look at. If we find the padding inconvenient at that point we can just remove it in a follow-up RFE.
>> 
> I agree. Eliminating the extra spaces is quite easy with a sed script. It's harder to use a script to add the spaces back to align the output.


This is a mess that I just finished dealing with.  I believe UL will solve the interleaving but not the internal formatting issues but it won’t solve a number of other existing issues.

100081.540: [Full GC100081.540: [GC concurrent-root-region-scan-start]
100081.540: [GC concurrent-root-region-scan-end, 0.0000080 secs]
100081.540: [GC concurrent-mark-start]
100084.860: [SoftReference, 22 refs, 0.0000340 secs]100084.860: [WeakReference, 169 refs, 0.0000180 secs]100084.860: [FinalReference, 18 refs, 0.0000050 secs]100084.860: [PhantomReference, 0 refs, 0.0000040 secs]100084.860: [JNI Weak Reference, 0.0000040 secs] 510M->510M(512M), 4.3335850 secs]
   [Eden: 0.0B(25.0M)->0.0B(25.0M) Survivors: 0.0B->0.0B Heap: 510.9M(512.0M)->510.9M(512.0M)]
 [Times: user=3.44 sys=1.62, real=4.34 secs] 

This is but 2.5 data points. To make any reasonable decisions I’m looking at several 1000s of these data points and there is no way you’re going to do that without tooling. In fact, there are behaviors that are simply not visible unless you run some analytics over the data. For that reason alone I advocate machine readable should be a top priority. One thing that helps is losing some of the arbitrary formatting. For example, the use of square brackets here look very reasonable. However you can see the GC logs also use square brackets (albeit inconsistently) so now you have potential collisions with the symbols which will increase the complexity of parsing. This is the primary reason there are very few reasonably good GC log analysis tools available for OpenJDK. Sure you can adjust for spaces and other things but over versions you end up with enough differences due to these small formatting changes that also increases the complexity of the parsing. The simplest logs and the most useful ones are produced by Azul and HP (derivative of OpenJDK). There are both simply CSV flat files with some header information. No fuss, no muss… Good for North America but not for the rest of the world...

Kind regards,
Kirk