Monday, 25 February 2008

new logging experience



A new logging experience!

I've been using logback for a few months now, and I'm impressed!

With excellent documentation and support, neat logging features,

blazing performance and an innovating eclipse plugin, I've finally

found a good replacement for the good old log4j.

The first thing I really appreciate compared to log4j or the java

logging api is the documentation. The guide is well written, they have

a nice demo, and you are up to speed in a few minutes.

Neat logging features

There are some very simple features which makes the life so much

easier, such as the intelligent logger name reduction when it's too

long: instead of simply truncating the name, it put the first letter

of each package:

09:59:04.203 [main] INFO o.x.x.web.XoosentApplication - starting XooSent

The Mapped Diagnostic Context (MDC) is also a killing feature. It

allows to associate metadata to the current thread, to correlate

messages to their context. For instance in a web application with

authentication, you can associate the user name to the the thread and

add this user name to all log messages, without any change to your log

calls. For instance, you add this at user authentication time:

MDC.put("user", username);

Then in your logback configuration you can use %Xuser in your pattern,

and you will see the authenticated user name. It's that simple, and in

multithreaded environment where multiple traces overlap, it really

helps.

Updated: As Jorg pointed out, this isn't a feature introduced by

logback, as log4j already supports NDC and MDC.

Performance

The parametrized logging is a key feature of logback, which improves

performance by avoiding a toString() call when your message is not

logged:

logger.debug("Hello, my name is {}, I am {} years old", username, age);

Note that obviously the performance gain applies only if you don't

enclose your logging statements with if (logger.isDebugEnabled())

statements). But if you look at a benchmark run by Sebastien Pennec,

one the developers of logback, it's really impressive:

Log4j direct debug call: 442

Log4j tested (isDebugEnabled) debug call: 19

Logback direct debug call: 435

Logback tested (isDebugEnabled) debug call: 10

Logback parametrized debug call: 15

OK, we all know how we should consider benchmarks, especially when

written by someone biased as Sebastien obviously is, but these numbers

can't be completly wrong, and what's interesting is that a logback

parametrized call takes approximately the same time as a log4j

isDebugEnabled call. Really cool!

Still on the performance area, logback introduces TurboFilters, which

allows to filter logging before the logging event is actually

constructed, saving a lot of unnecessary time.

Beyond console and files

Beyond classical ways to track and configure your logs, you have very

interesting features with logback, such as a JMX configuration, and a

new Eclipse plugin which is really neat.

One of the thing I like the most with this plugin is the option to go

to the source which is at the origin of the log. Double click on the

log, and it will open your source editor at the line where the log

call is performed! Awesome! How many times did I use the search tool

to find where a particular log call is performed in a big application,

and waste time because the message was the result of a concatenation

and thus my search failed...

Another interesting thing is the option to change the pattern and

apply it to all the logs, including previous one.

And you have also a good filter option, where you can apply any

logback filter expressions. This still need to be improved IMO to be

able to apply the filter in real time to previous logs, but hey, it's

only the first version of this plugin!

Excellent support

Last but not least the support is amazing. There isn't much traffic on

the user mailing list for the moment (their documentation is so good

:-)), but very often developers take time to answer your questions

with a lot of details, trying to reproduce your environment, and


No comments: