Logging in Java - example in Morphium

veröffentlicht am : Mi, 02. 03. 2016 geändert am: Mi, 02. 03. 2016

Kategorie: Java --> Programmierung --> Computer

Schlagworte:


Whatever programming language you use, the first thing you learn is how to write something to the console - you create a log output in a sense. This is very important, as you need to read through your logs in order to find out what exactly went wrong when you encounter problems.

Since a couple of JDK-Versions ago, java did not offer a real, configurable way of creating log output. So, everybody created their own logging mechanism. That worked fine to an extent...

Someone came to the conclusion, that logging is so fundamental, we need a framework for it! For creating a line of text on the console, you need a framework... And that's when things get ugly.

Right now, there are several logging frameworks available, all of those behave totally differently.

There is the jdk standard in the package java.util.logging (the cool kids say JUL), then there's log4j (or logback as it is called now) which is kind of a quasi standard right now, and there is slf4j which is more or less kind of a meta framework for logging frameworks. That can configure most of the other logging frameworks out there.

All fine, choose the framework that suits you most...NOT

You might think "cool, I go for JUL" but then you start configuring it, start up your application, use some libraries and you will learn quite fast, that those libraries use their own favorite logging framework, probably different from your choice. This is causing so much trouble in some cases, as things get mixed up and in bigger application you end up needing to configure just every logging framework out there.

The "best" libraries are the ones like the mongodb java diver. These tiny little thingies use some kind of logging gate! The code checks, if log4j is available, than use that. And if not, use JUL. So, if you want to have everything using JUL, you will end up having problems with the mongodb driver, as soon as for some reason you end up with log4j being in your classpath.

Thanks to problems like this, you need to configure at least two logging frameworks in order to be able to get rid of unwanted output or get it to produce the correct output you want. And to be honest: We did not manage to get rid of the annoying debug output of the mongodb java driver yet.

one word about log4j and performance

Just to mention something. We were using log4j originally. But we endet up with huge performance problems.

Usually, when using log4j you create a static logger instance in your class and use it. This one stays in Memory as long as the class is in Memory.

Problem is: the access has to be synchronized in some way as several therads access the same instance of a logger. This was killing us. In our tests we saw that when getting a bit load on the machines, log4j was blocking most of the threads in order to be able to do its job.

This was inacceptable. We were thinking about a solution, especially as morphium was using log4j as well.

As all other frameworks were kind of having similar issues (or at least could have) and we had the configuration issues, we decided to create our own, simple logger. We also included it in Morphium, because we wanted morphium to have as few dependencies as possible.

So, morphium now uses a simple logger, called logger...

logging in morphium

The logger class is called de.caluga.morphium.Logger and needs to be instanciated with new. The logger is not threadsafe, that means it should not be used by many threads simultaneously (although that should not be a problem, as the logger does not have much logic in it, but it might cause things to become mixed up in your logfile).

The configuration is also rather simple, you have several options:

  • add an option to your jvm, like -Dmorphium.log.level=2
  • add some environment variable, like morphium_log_file=/var/log/morphium.log
  • or set it in your logger instance, like Logger l=new Logger(this.getClass().getName()); l.setLevel(5);

alls configurations can be prefixed, that means if you want to change the setting for a specific class or package, you just need to add the setting to the name of the option, like -Dmorphium.log.level.de.caluga.morphium.driver=4

Available settings are:

  • log.level: well, self explanatory. level can be between 0 (no logging) and 5 (debugging)
  • log.file: define a log file, can also be STDERR, STDOUT or - . The dash is a synonym for STDOUT
  • log.synced: do a synced write. If set to false, log output will be buffered (recommended for production environment)
  • log.delegate: can be either jul, log4j or an own classname (FQN). If not set, it will use morphiums own logger implementation. IF you want to use your own logger implementation, you need to implement the LoggerDelegate-Interface.

Since we used the simple morphium implementation of the logger, we increased performance by about 50%! Just for the logging output.

Logging is more important than most engineers think, and it may have a bigger impact on performance than people realize. This way presented above of including a simple logger might not be the best solution for everybody (especially when you need to be able to configure the output or more complex output rules e.g. to several destinations), but it certainly was a very good solution in our case.

erstellt Stephan Bösebeck (stephan)