BT

Apache Log4j 2.0 - Worth the Upgrade?

by Matt Raible on Jul 31, 2014 |

The Apache Software Foundation recently announced the General Availability of Log4j 2.0, containing many performance improvements over its predecessor Log4j 1.x. Years in the making, this release was written from scratch, and gained its inspiration from existing logging solutions such as Log4j 1.x and java.util.logging.

Log4j 2.0 introduces a new plugin system, support for properties, support for JSON-based configuration and automatic reloading of its configuration. It supports many existing logging frameworks, including SLF4J, Commons Logging, Apache Flume and Log4j 1.x, and provides a new programmer’s API.

Christian Grobmeier, Apache Logging PMC Member, first wrote about the new Log4j 2.0 in December 2012. He described the modern API:

In old days, people wrote things like this:

if (logger.isDebugEnabled()) {
   logger.debug("Hi, " + u.getA() + " " + u.getB());
}

The log4j 2.0 team thought about things like that and improved the API. Now you can write the same like that:

logger.debug("Hi, {} {}", u.getA(), u.getB());

Grobmeier goes on to describe more API improvements, including Markers and Flow Tracing. He also mentions the improved plugin architecture, enhanced configuration (with hot-reloading, JSON and properties) and how Log4j 2.0 addresses many deadlock issues from Log4j 1.x.

On Hacker News, many complained about the proliferation of logging frameworks for the JVM. Ceki Gülcü, author of many Java logging frameworks including Log4j, SLF4J and Logback, expressed his reasons for not liking the Apache model. Gülcü still remains a community member and continues on the PMC of Apache Logging.

In July of 2013, Grobmeier authored another post, titled Log4j 2: Performance close to insane. In it, he raves about how Remko Popma's "AsyncLoggers" were able to produce twelve times more logging throughput than other frameworks.

We speak of more than 18,000,000 messages per second, while others do around 1,500,000 or less in the same environment.

I saw the chart, but simply couldn't believe it. There must be something wrong. I rechecked. I ran the tests myself. It's like that: Log4j 2 is insanely fast.

async-throughput-comparison

More information can be found in Log4j's async documentation.

Not everyone, however, is impressed with Log4j's async features. Michael Rose, Senior Platform Engineer at FullContact, penned the blog Overengineering: Log4j2's AsyncAppender. He concludes using this feature is not worth it:

I've concluded that the Log4j2's AsyncAppender, while neat, is just a shiny toy and there's really no appreciable difference for any sane application. Greatest respect for the Log4j2 team, but I really wish they'd focused on building a single, cohesive, next-generation Java logging framework rather than adding yet another logging framework to the mix.

Logback , however, natively implements SLF4J (the de-facto standard for classpath-binding logging) and has more than acceptable performance (especially with locations turned on). It continues to be my logging framework of choice. It's easy to use and I've never run into any issues with it.

If nothing else, avoid Log4j 1.x (Or really anything but Log4j2 or Logback) like the plague. In any system with load, you'll eventually find it causing contention issues.

Migrating from Log4j 1.x to 2.0

I recently upgraded Log4j 1.x to 2.0 in my AppFuse application and found it difficult to get the Maven dependencies right. At the very least, you'll need the log4j-core JAR (which depends on log4j-api). If you're using it in a webapp, you'll also need log4j-web as a dependency. To get Velocity 1.7 to work with Log4j 2, I had to add log4j-1.2-api. To make Spring work, I had to add log4j-jcl (because it uses commons-logging). For libraries that relied on SLF4J, including log4j-slf4j-impl was a must. To get Hibernate to work with Log4j 2.0, I had to upgrade to upgrade to JBoss Logging 3.2.0.Beta1.

You may need to exclude older Log4j dependencies from some dependencies. If you're using Maven, the following command is a good way to display dependencies that you might need to exclude.

    mvn dependency:tree | grep log

The final step I needed to do was rename my log4j.xml files to log4j2.xml and refactor them to match its new configuration.

Summary

The new Log4j 2.0 release has many performance improvements, a new plugin system, and many improvements to its configuration settings. Some users may or may not find these enhancements compelling enough to upgrade, or move from an existing logging solution.

Hello stranger!

You need to Register an InfoQ account or or login to post comments. But there's so much more behind being registered.

Get the most out of the InfoQ experience.

Tell us what you think

Allowed html: a,b,br,blockquote,i,li,pre,u,ul,p

Email me replies to any of my messages in this thread

The modern api is an antipattern by Alex Blewitt

The issue of determining whether debugging is to be turned on or not is to avoid object creation or expensive method calling. This does both. In the right way, the call to u.getA() and u.getB() are never called; the wrong way calls them, then ignores the return values.

The other point is that using a varargs call in Java creates an on-the-fly array for the method call under the covers. So even if you're using constants (or local variables) this is actually creating a new array object, populating it with the values, and then GC'ing it when the value is subsequently thrown away.

In summary: don't use Log4J 2.0's varargs API without a guard. It does the wrong thing twice.

Nothing new by Tomasz Nurkiewicz

String placeholders and markers were available in SLF4J forever. Flow tracing is even older, coming from java.util.logging package.

Insanely fast asynchronous appending is not really that useful in normal circumstainces.

flow tracing by Aravind Yarram

Can you please point me to flow tracing documentation or article using java.until.logging.

Some other features by Ralph Goers

Matt,

There are a couple of other features in Log4j 2 that I think are worth noting.

The first is that Log4j logs Messages, not just Strings. This is the primary reason Log4j 2 does not use the SLF4J API. Messages provide an extremely flexible way to log almost anything you can think of.

In addition to the parameterized format Logback supports, Log4j also supports logging events using the MessageFormat and String.format() syntaxes. By no coincidence this is supported by using the Log4j API's Message interface.

However, what really inspired me to kick off the work on Log4j 2 was that I had a need to use a logging framework for auditing banking transactions and so losing logging events, as will likely happen when a reconfiguration occurs in Logback, was not acceptable. This is not easily fixed in either Log4j 1.x or Logback, which was originally largely based on Log4j 1.x, due to how they are designed. Log4j 2 will not lose logging events during a reconfiguration.

Michael Rose's article leaves me wondering how much he really investigated Log4j 2. As Remko pointed out in a response to his article, he continually refers to the AsyncAppener - which does not use the Disrpupter but uses a BlockingQueue. I can tell you from a very recent experience that with a fair amount of logging enabled the logging system can easily become a bottleneck for your application. I personally saw at least a 100% improvement in throughput in an application by switching to Log4j 2 due to contention in the previous logging framework.

Re: The modern api is an antipattern by Invest Psych

@Alex Blewitt: Please submit your suggestions to log4j v2.0 team.

Re: The modern api is an antipattern by Will Hartung

Well, allow me to disagree about it being an anti-pattern.

I will agree that in terms of absolutely perfect efficiency, the guard is cheaper. But I disagree that this is an anti-pattern.

The original drive for the guard was issues like this:

log.debug("I have to debug this thing: " + thing.getValue() + " and this " + thing.getOtherValue());


The primary cost here was the string concatenation, which is quite expensive. It's the dominant expense of this call outside of the logging itself.

Discarding results of simple getters is extremely cheap (assuming the getters themselves are correspondingly cheap). Building and tossing away the Object array is next up on the expense graph, but it, too, is quite cheap. Object allocation in modern JVMs, while not free, is also a very cheap operation.

But what you get in return for these costs, is a much more usable logging directive. It makes the code far more readable. It also makes the logging statements much safer for when they are slipped in without the guard.

As with everything, be conscious of time sensitive code. All abstractions have costs.

I've been using this pattern since we got varargs. I wrote my own simple logging wrapper around Java Util Logging and abandoned the frameworks almost 10 years ago, and never looked back.

Re: The modern api is an antipattern by Victor Grazi

@Alex Blewitt: The created array will only live momentarily, and will be collected with the eden gen. So it should not really slow down the gc in most cases. Also, assuming the getX() is just returning a pointer, then assuming the Log4j implementation tests internally before performing the string concatenation, it should do the right thing and not compose the string if it is not needed.

Re: Some other features by Michael Rose

@Ralph Goers

You're right, I didn't spend a lot of time with Log4j2. I didn't need to. When I refer to "AsyncAppender", I am speaking to their implementation of Async Logging on top of Disruptor.

Why did I not spend a lot of time on it? I've used logback in extremely high throughput systems. As long as you aren't trying to log a million times a second (which, you aren't right? Right?) there should be no applicable differences between Log4j2 and Logback. I've never seen Logback spend any time on my hot calls list. That's because I only log at debug locally, and only log sane amounts (a few thousand a second, tops) in production.

My article was asking the question, which I should have stated more clearly: "What do I need of a disruptor-backed logging system, when at peak capacity it would overwhelm anything but main memory?"

I also understand that disruptor-backed logging is optional. But if you're needing disruptor for logging, you probably needed disruptor somewhere else and didn't make the mistake of contending on your logging framework, and definitely don't want your version of disruptor held back by Log4j2's.

My conclusion is that Log4j2's "performance" is really not what you should be selling the framework on. Tall bar graphs look great, but it's the rest of the framework that counts.

Allowed html: a,b,br,blockquote,i,li,pre,u,ul,p

Email me replies to any of my messages in this thread

Allowed html: a,b,br,blockquote,i,li,pre,u,ul,p

Email me replies to any of my messages in this thread

8 Discuss

Educational Content

General Feedback
Bugs
Advertising
Editorial
InfoQ.com and all content copyright © 2006-2014 C4Media Inc. InfoQ.com hosted at Contegix, the best ISP we've ever worked with.
Privacy policy
BT