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

Vitaly Davidovich vitalyd at gmail.com
Thu Sep 10 15:15:55 UTC 2015

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

More information about the hotspot-dev mailing list