Wednesday, June 07, 2006

Is log4j causing a liveness issue?

Wow, this big word, "liveness"... A couple of weeks ago I had, again, forgotten what it means (and hope to forget again in a month, maybe). We're seeing this situation, when with increased number of requests, server's CPU usage can not exceed 1/4th of available resource (meaning, only 1 CPU out of available 4 gets pegged). Many man-days were spent trying to find the culprit. Today I just woke up with this thought, correlating that the issue manifested after all our application logging was converted to use commons-logging and log4j.

<rant&rt; (as if the prior part was not): there's a saying, roughly translated as "how you name a ship, so she will sail". There might be some truth, after all, to commons-logging being christened as "Clogging" by our fearless Hani.</rant&rt;

And there it was: synchronization on logger category in org.apache.log4j.Category.java

/**
Call the appenders in the hierrachy starting at
this. If no appenders could be found, emit a
warning.

This method calls all the appenders inherited from the
hierarchy circumventing any evaluation of whether to log or not
to log the particular log request.
@param event the event to log. */
public
void callAppenders(LoggingEvent event) {
int writes = 0;

for(Category c = this; c != null; c=c.parent) {
// Protected against simultaneous call to addAppender, removeAppender,...
synchronized(c) {
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}

if(writes == 0) {
repository.emitNoAppenderWarning(this);
}
}


So, for the duration that this event gets logged (most likely, including the time while data is written to a file on disk), the lock prevents other events to be logged in the same category. It's true that we're logging a lot :) But it's not an excuse for this. This synchronization is here for the sake of changing the set of appenders at runtime. Now, how often should THAT happen? (never!) IMO, letting the underlying collection to throw a ConcurrentModificationException in such unlikely case when set of appenders is being changed while events are being logged would be much preferred outcome. More elegant workaround is possible, too, but I'm probably too bad a person to submit this to Apache. I feel much better bitching about it here :)

0 Comments:

Post a Comment

<< Home