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
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.