Fun With JBoss Performance

April 19, 2005 5:14 PM

So a while back, some of our customers were having problems running under JBoss. It turned out that the bug itself was my bad coding, but that's only the beginning of the story. The trigger for this bug was a piece of debug-level logging code in Hibernate. In debug mode, each time Hibernate's session is flushed it will log the session contents. It was this logging code that called back to my buggy getter method, that then tried to talk to Hibernate just when it was really in no mood to be talked to. Boom.

But why was debug logging enabled in the first place? It's certainly not the logging level we ship with. The customer didn't put it there... Ah, of course. JBoss.

JBoss ships by default with logging turned up to DEBUG level. Either by design, or just as a side-effect of JBoss's clever classloading arrangement, this configuration infects any application deployed in the server. And judging by the number of people who were effected by the aforementioned bug, either nobody notices this, or nobody knows how to turn it off properly.

Of course, this has some nasty side-effects beyond just dumping a load of crap to disk that nobody wants to read. One of the problems with logging is that it can be pretty expensive. Firstly there's all that I/O to write out the reams of useless debug information, but beyond that the application pays the price of assembling all those strings that need to be written out. For example, to assemble its debug message, Hibernate was having to run through every object in its session and convert that object's properties to loggable strings, every time the session was flushed.

This sort of thing isn't particularly cheap, which is why log4j has a guard method: isDebugEnabled(). By wrapping your expensive message-building code in this conditional, you can ensure you only pay the cost of debug-level logging if it's actually turned on. I've worked on applications that saw a tenfold performance improvement after the liberal application of isDebugEnabled().

So to combat this performance problem you can't just make sure that the messages aren't being written anywhere (by configuring a threshhold on the log4j Appender), you also have to modify the Category configuration so that the application's queries of isDebugEnabled() reflect what's truly ending up in the log files.

Which, based on this admittedly small sample, seems to be something that a lot of admins overlook. Across thousands of JBoss deployments, trillions of CPU cycles are being wasted generating strings that nobody cares about, and that might never see the light of day.

I suspect this is how JBoss Inc. consultants make their money. They can just go in, add one line to log4j.xml, demonstrate they've tuned the server to achieve ten times the throughput, and spend the rest of the day drinking coffee and looking smug.

1 TrackBacks

Listed below are links to blogs that reference this entry: Fun With JBoss Performance.

TrackBack URL for this entry: http://fishbowl.pastiche.org/mt-tb.cgi/631

Charles Miller writes in Fun with JBoss Performance: JBoss ships by default with logging turned up to DEBUG level. Either by design, or just as a side-effect of JBoss’s clever classloading arrangement, this configuration infects any application depl... Read More

4 Comments

I liked how you called JBoss classloading "clever"...

That's funny timing, Charles. We were just joking the other day how I had to decompile a library for which I had no source for just to remove an if (!condition) { throw } block which was disabling a feature that I needed, and how we continued about how we could go out for beers half the day if we just littered our code with Thread.sleep(), came in and spent 5 minutes removing a couple of them just to prove out how we'd gotten a performance increase. Apparently this sort of thing isn't so far fetched :).

Cheers,
/Nick

Jason: That level of inventiveness and sheer creativity compared to the more boring application servers must be recognised, don't you think?

You should mention the increase in start-up performance by turning off debug logging in JBoss, too. I've seen it startup 300% quicker...

Previously: Maciej on Dabblers and Blowhards

Next: Competition in a Nutshell