JEP 271: Unified GC Logging

[Kirk Pepperdine]

Hi Tao,

My concerns regarding these types of text formats is that they have poor information densities. One of the problems with the current logging frameworks that I consistently run into is that the use of highly verbose logging formats where the rate of information is very low. Simply put, you have to log a lot of bytes to get a bit of information. These quite quickly become the source of performance problems in many applications especially in cloud environments when logging is likely to happen on a non-local disk. In fact the only time I’ve seen GC logging affect performance is when it was being written to a NAS and the network was already taxed.

I always recommend that 1) people prefer more dense formats even if it comes with the pain of having to parse it, 2) stay out of the way which implies no reformatting and avoid adding extra decorations, and 3) differentiate between operational and debug logs. I personally don’t care what the JVM developers decide to put into logs they’d use for debugging. The value of these messages tends to be transient and they should be able to come and go as needed. However, operational logging should first meet the requirements of operations and consequently should be more stable. Most of the discourse regarding logging is that it has grown organically and operationally we have come to rely on it which means we end up interfering with the JVM developers needs. Another part of the Devops discourse is that developers often don’t completely understand what operations needs unless they are involved in operations themselves. So, a conversation with operations to gather requirements for logs that would be used in operations is always a good thing.

The current PS and ParNew/CMS logs with details and age table information strikes a reasonable balance between readability and information density. These records not difficult to parse. The only problem is that the records using the concurrent collectors do become interleaved. G1 is easier to parse and I’ve only occasionally run into situations where the concurrent phases have corrupted logging output but it still happens which has it own series of implications. So, sticking to the current formats with some minor tweaks seems like a sensible decision especially if UL will force single shot writes that cannot be interleaved. However that is only part of the difficulties. Additional to having the concurrent phases hijacking logging messages, we also have about 20-30 flags that will inject additional information into each log message. Consider PrintPromotionFailure with or without PrintReferenceGC and/or PrintAdaptiveSizePolicy. Each additional flag disturbs the PrintGCDetails format so that for these 3 additional flags 7 different formats. It would be nice to have this information be added to the end of the message in a concise format. PrintReferneceGC is an easy example as the output is well formed, it just shows up in the middle of the record. Life would be easier if it was added to the end (as CPU breakouts currently are). The only effect flags like PrintTenuringDistribution have are to split the main log record into two lines while they inject their information into the file. Again, not really an issue for parsing unless you do something like what PrintPLABS does by adding an extra tag to the end of the split main log record. PrintAdaptiveSizePolicy also does the same and when both sets of flags are turned on you start ending up in the combinatorial world. A consistent split of the main record is not an issue. However, the interjecting records should be completely self contained with on separate lines or in a self contain closure.

So I think JSON would help with the issues that I’ve seen in my experiences with parsing GC logs. However I don’t think we need to move to this verbose format to fix the current issues we are facing. If UL untangles that will be a significant win on it’s own.

Kind regards,
Kirk



> On Sep 25, 2015, at 1:37 AM, Tao Mao <yiyeguhu at gmail.com> wrote:
> 
> Ooops.. the link https://logentries.com/doc/json/ <https://logentries.com/doc/json/>
> 
> On Thu, Sep 24, 2015 at 4:36 PM, Tao Mao <yiyeguhu at gmail.com <mailto:yiyeguhu at gmail.com>> wrote:
> Regarding alternative log format, has JSON format been put on the table? It has human and machine readability as well as extensibility (i.e., not likely to break existing tools when new fields are added).
> 
> You can take a glance here for how JSON logs would look like in other field.
> 
> Thanks.
> Tao Mao
> 
> 
> 
> On Thu, Sep 24, 2015 at 8:33 AM, Kirk Pepperdine <kirk at kodewerk.com <mailto:kirk at kodewerk.com>> wrote:
> Hi Johann,
> 
> XML is far from my favorite format. It’s unnecessarily verbose. But then, I also don’t care that much about “human readable” either.
> 
> Kind regards,
> Kirk
> 
> > On Sep 24, 2015, at 3:17 PM, Bengt Rutisson <bengt.rutisson at oracle.com <mailto:bengt.rutisson at oracle.com>> wrote:
> >
> >
> >
> > Hi Johann,
> >
> > Thanks for looking at the JEP!
> >
> > On 24/09/15 14:40, Johann N. Loefflmann wrote:
> >> On 09/24/2015 02:08 PM, Bengt Rutisson wrote:
> >>> and I'm happy to hear some suggestions on how to format this nicely,
> >>
> >> Why not printing out xml on demand (resp. by default if -Xloggc is set) ?
> >> With xml any preferred/customized output format could be generated from the log (e.g. plain text).
> >
> > I think this has already been discussed in the discussions around the JEP for the unfied logging framework "JEP 158 Unified JVM Logging". Please see the discussions there.
> >
> > In short I think the main point is that it is good if the logging is easy for tools to parse but the main intent is still that they should be human readable. So, XML is not a desirable format.
> >
> > Thanks,
> > Bengt
> >
> >>
> >> just my 0.02 cents,
> >> -Johann
> >>
> >
> 
> 
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20150925/301ed3b1/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/20150925/301ed3b1/signature.asc>