On May 31, 2009, at 6:11 AM, Joern Huxhorn wrote:
The sledgehammer synchronization using synchronized on the instance itself is definitely a mistake as I've shown in the bug report. A first (and absolutely necessary step!!) is to replace it with a fair ReentrantLock so Logback isn't responsible for starvation situations anymore.
While that may be true of AppenderBase, the point I've been making is that since UnsynchronizedAppenderBase doesn't lock the issue is avoided completely (at least at this level).
Thread 1 can call logger.info() and before the appender even gets a chance to lock Thread 2 can call logger.info(). The CPU might give conrol to Thread 2 and let it finish ahead of thread 1. Even if you have multiple CPUs, as long as you have more threads hitting the same logic than there are CPUs you will run into this issue. This is just a fact of life when dealing with multithreaded applications. If you look at a standard debug log with a fair amount of logging you will see this all the time. It isn't readily apparent because the granularity of the time is usually a millisecond, but occasionally you will see log records that appear to be out of order.
I'm talking about the following situation in case of JDK 1.6 on multi-core systems: Results for usingSynchronized: runnables[0]: SynchronizedRunnable[counter=394, running=false] runnables[1]: SynchronizedRunnable[counter=1, running=false] runnables[2]: SynchronizedRunnable[counter=1, running=false] runnables[3]: SynchronizedRunnable[counter=1, running=false] runnables[4]: SynchronizedRunnable[counter=1, running=false] runnables[5]: SynchronizedRunnable[counter=1, running=false] runnables[6]: SynchronizedRunnable[counter=1, running=false] runnables[7]: SynchronizedRunnable[counter=1, running=false] runnables[8]: SynchronizedRunnable[counter=1, running=false] runnables[9]: SynchronizedRunnable[counter=605, running=false]
This is the result of the app appended to http://jira.qos.ch/browse/LBCORE-97 in that case. Please take a look at the code. All 10 threads are executing the same Runnable: public static class SynchronizedRunnable implements Runnable { private final Object lockObject; private int counter; private boolean running;
public SynchronizedRunnable(Object lockObject) { this.lockObject=lockObject; this.counter=0; this.running=false; }
public void run() { running=true; for(;;) { synchronized(lockObject) { counter++; try { Thread.sleep(10); } catch(InterruptedException ex) { break; } } } running=false; }
public String toString() { return "SynchronizedRunnable[counter="+counter+", running="+running +"]"; } }
I'm simulating the AppenderBase situation here, lots of threads are trying to access the very same resource. With Java 1.6 on multi-core systems, only <number of cores> threads will ever get the chance to obtain the object monitor. All other threads are starving. And this is a valid simplification because it shows exactly what's happening in our webapp right now. We had to disable logging to get it back into a usable state.
Using a fair ReentrantLock fixes this. It makes sure that threads are handled fairly concerning the shared resource, i.e. they are served in a "first come, first served" order.
The issue here isn't really that there is a problem with how synchronized locks work. If there were Tomcat would fall on its face. Take a look at https://svn.apache.org/repos/asf/tomcat/trunk/java/org/apache/catalina/loade... . I guarantee you this is being called far more often then logging is and it doesn't exhibit these problems. The real culprit here is how much time is being spent inside the synchronized block. When you look at the WebappClassLoader you will see that locks are held for very short periods of time. This is contrasted with Appenders that hold the lock for an extremely long period of time. To prove this I simply added for (int i=0; i < 100000; ++i) { if lock == null { throw new NullPointerException(); } } before the synchronized or locked block (using lockObject instead of lock for the synchronzied block). While the counters don't come out equal they are very close. This shows that the problem is really how much time is spent in the synchronized block vs the actual application. The significance of this is that even when you "fix" the locking so it is fair your application performance is still going to suck because it is spending so much time in the Appender vs doing actual work.
I assume you hadn't understood the point of LBCORE-97 until now... and please don't take that as an insult ;)
I the understanding of it. I just don't think it is the right way to fix the problem.
I wrote code under the assumption that synchronized would be at least sufficiently semi-fair, Ceki did in both LOG4J and Logback, and reality up until Java 1.6 on multi-core seemed to indicate that it's ok to assume that total fairness isn't necessary... but all this changed because synchronized is absolutely unfair now - and the documentation shows that the fault is on our side. We were simply working with wrong assumptions.
This just proves my point that locking should be handled by the logging system in a correct, i.e. fair, way. It is "downright dangerous" to assume that every person that implements an appender is aware of this situation and the problem will only show up on Java 1.6 multi-core systems. This is a *very* big risk.
But I agree 100% that the transformation/evaluation of the logging event can and should be handled outside of whatever fair locking mechanism is used. This would solve some issues and seems very logical. We should definitely aim for this in the future... Ideally, AppenderBase would be changed to support this, IMHO.
It would probably be a better idea to use a
protected final ReentrantReadWriteLock readWriteLock=new ReentrantReadWriteLock(true);
fair ReentrantReadWriteLock in AppenderBase instead. doAppend would then use the write lock while actual implementations would have the freedom of using either read or write lock, as needed. This would remove the need of synchronizing the worker queue you mentioned earlier. I'm not sure if we really need a ReadWriteLock, though, as removal from the queue would be a write, too. But *some* appender implementation could have a use case for read-only-access...
One way to handle transformation of the event outside the lock is what I suggested in http://jira.qos.ch/browse/LBCLASSIC-45. Just dumb down LoggingEvent enough so that it already is detached from the rest of the system after it's created. But someone, and I honestly can't remember but I think it was you, said that it would be bad if the MDC was already transformed into Map<String,String> at that point...
I've just changed my patch to make lock protected instead of private. Seems to be a much better idea :p
And just to get my point straight once more: A logging system MUST NOT be a point of starvation! It will naturally always be a chokepoint but it MUST NEVER be a point of starvation!
On this we agree. If switching to a ReentrantReadWriteLock fixes the problem for AppenderBase then I certainly don't have a problem with that. Personally, I see it as sort of a band-aid though. I'd like to go through and deal with all the code that isn't thread-safe and move the locking down to just those areas where it can't be avoided. Every reference you can find on multithreaded programming will tell you to hold locks for as short a duration as possible. Logback and Log4j don't do that which opens them up to these kinds of issues. Again, even if you make it "fair" the amount of time the lock is being held means AppenderBase will almost certainly still be the biggest bottleneck in your system when logging is enabled. Ralph