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

[Vitaly Davidovich]

>
> If you put this into the context of GC logging, what is a warning log
> level? IMHO, it makes no sense. I can’t even put a reliable warning metric
> into Censum that would be a warning in all circumstances.


There may not be a warning level for GC, I don't know.  But one warning I
could conceivably think of is a GC not meeting its pause time goal.  Other
types of warnings could be, e.g., JIT compilation bail outs, JIT
compilation failures, code cache usage approaching capacity, etc.  There
won't be a hard and fast rule on this, but as mentioned, I suspect it's
easier to decide whether something is error/warn/info/debug (or akin) than
what arbitrary tag to use.

Indeed, on the surface it looks like it can. However if you look at the
> current logging system in GC there are not that many flags that most people
> would be interested in. Certainly the amount isn’t unwieldy. Converting
> that to a tag system would be straight forward. Moving to levels… I
> wouldn’t even no where to start. So theory doesn’t really meet practice in
> my experience.


It's not just GC logging though, there are other components that are
loggable and this JEP is covering the entire JVM.  Overall, there are
*tons* of different flags in Hotspot as it is, and granted some of them
don't control logging, but the general issue of "too many knobs" is akin to
"too many tags".

Yes, performance is a different (yet some what related) issue. My apology
> for not clearly articulating that. The idea behind Chronicle is to not
> filter messages. In fact it drops them on disk in a raw format. If you want
> to filter and reformat you can do that out of band. When logging latencies
> are significant, which they quite often are, I first look to how to reduce
> volume and then I work to strip out all the decorators and filtering. In
> fact, I’ve been recommending and moving apps to use more compact,
> information dense binary formats. All of this gets particularly critical in
> virtualized environments where disk is typically NAS. In all cases the less
> you do, the better things get.


Sure, text logging is always going to be slower than proprietary binary
formats.  But Chronicle is meant for logging of data volumes much much
larger than what a JVM is logging, and not spitting out text is more
important in that case.  But if you move to binary format, now you need to
(a) write tools for reading it, (b) document the format so others can write
tools, (c) possibly version it, etc.  But ultimately, if you're logging so
much that it's becoming a performance bottleneck, then I suspect there are
other issues at play.  Even if you write to mmap'd files or write
asynchronously, if you outpace the i/o subsystem and/or hit memory
pressure, OS's such as linux will panic and the entire machine can stall
until all the writebacks complete.


On Thu, Sep 10, 2015 at 5:27 AM, Kirk Pepperdine <kirk at kodewerk.com> wrote:

> Hi Vitaly,
>
> I think it would be much better to go towards a digital logging system.
> However, as difficult as it is to talk a tag system, I think it would be
> more difficult to talk about a digital system.
>
> It sounds like you're proposing a hierarchical naming scheme for log
> statements; if anyone is familiar with the Graphite tool, it does something
> similar for metric names.  You can then wildcard certain parts of the path
> when using its query tools.  Is that what you have in mind?
>
> This is similar to what I have in mind.
>
> That's flexible but can lead to other issues.
>
> Agreed, there is no free lunch. The question now becomes, where do you
> want to pay the cost. Next how much of that cost is real? I try to answer
> that below by adding some context. As I mentioned before, if you don’t want
> to pay the cost you can simply define levels if that is what you like and
> that is how your taxonomy works. This isn’t about preventing people from
> using levels, it’s about not forcing them to use them. It’s also about the
> advantages that tags can cover situations that you’ve yet to imagine. In
> fact it seems as if tags are in because there were situations that were not
> imagined in the first spec. And thats ok, we can’t always imagine
> everything that could happen. All we can hope for is that when the
> unimagined happens, the system is flexible enough to cope with if.
>
> Every log line will need to know which path it's using, which can lead to
> an explosion of these paths as JVM devs will need to know what tags already
> exist for the (sub)component they're logging from.  It's much easier to
> quickly decide what level is appropriate.
>
> If you put this into the context of GC logging, what is a warning log
> level? IMHO, it makes no sense. I can’t even put a reliable warning metric
> into Censum that would be a warning in all circumstances.
>
> Consumers will still need to know what tags exist to get the right level
> of logging; wildcarding parts may be too much, fully specifying all desired
> tags can become unwieldy.
>
> Indeed, on the surface it looks like it can. However if you look at the
> current logging system in GC there are not that many flags that most people
> would be interested in. Certainly the amount isn’t unwieldy. Converting
> that to a tag system would be straight forward. Moving to levels… I
> wouldn’t even no where to start. So theory doesn’t really meet practice in
> my experience.
>
> I’m happy that we’re able to engage in this conversation though I’m not
> sure how useful it is. What I’m trying to impart here is my experiences
> tuning the very bad and broken logging that I often run into in many
> applications. It seems that my experiences are quite different than yours
> (as in the group that is implementing this JEP). FWIW, what I can say is
> the most successful engagements have been where I’ve been able to convince
> teams that logging should be an architectural level that involves
> conversations with operations and/or support groups to make sure that their
> needs are meet. Most of that work involves deriving a taxonomy or a way of
> categorizing the types of log messages that need to be produced. None of
> the current logging Java logging frameworks adequately support the outputs
> of this activity. Defining custom levels doesn’t work and with some
> frameworks leads to some very disastrous result *with no fault to the
> application developers*  As you can see, the shape of the name space and/or
> the names used to describe the categories of messages is, or should be
> beyond the scope of this JEP. Unfortunately it isn’t. IMHO, although this
> version of the JEP is much much better than the original version, it has
> still over reached. It’s over reached because from the start the wrong
> logging model was used to help define the JEP. If you absolutely disagree
> I’ll let you push on without interruption.
>
> Before going further, I'll stop to confirm that this is your gist.
>
> As for Chronicle, that seems like a separate issue altogether which is the
> mechanics of the logging.  I do agree that logging needs to be as efficient
> as possible as it's done synchronously.  This also implies the filtering
> scheme has to be efficient when the JVM decides whether the log should be
> emitted or not.
>
> Yes, performance is a different (yet some what related) issue. My apology
> for not clearly articulating that. The idea behind Chronicle is to not
> filter messages. In fact it drops them on disk in a raw format. If you want
> to filter and reformat you can do that out of band. When logging latencies
> are significant, which they quite often are, I first look to how to reduce
> volume and then I work to strip out all the decorators and filtering. In
> fact, I’ve been recommending and moving apps to use more compact,
> information dense binary formats. All of this gets particularly critical in
> virtualized environments where disk is typically NAS. In all cases the less
> you do, the better things get.
>
>
> Kind regards,
> Kirk Pepperdine
>
>