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

[Ioi Lam]

On 9/14/15 2:55 PM, Kirk Pepperdine wrote:
>> 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...

(Kirk,

I am not sure if human readable text would necessarily mean unparsable 
text. I've written many many log parsing scripts using regexp matching.

In order to write a good parser, I need to understand what's in the log. 
It's much easier if the log is human readable, like

size = 1234 bytes, speed = 5678 ms

rather than

1234,5678

UL allows a mixture of several types of logs (e.g., GC and class 
loading). I don't know how this can be represented in a CSV file.

My criteria for a good log is:

+ human readable
+ consistent
+ easy to parse

The common UL code really just handles the stuff in the first 3 [][][] 
brackets:

    [0.655s][debug  ][safepoint] Safepoint synchronization initiated. (20)
    [0.656s][debug  ][safepoint, some_other_tag] Safepoint
    synchronization initiated. (20)
    [0.657s][debug  ][safepoint,               ] Safepoint
    synchronization initiated. (20)
    [10.657s][debug  ][safepoint,               ] Safepoint
    synchronization initiated. (20)

and they meet my 3 criteria. The rest of the log is the responsibility 
of the individual component, and is really not in the scope of the UL 
common code.

- Ioi
> Kind regards,
> Kirk
>