On May 30, 2009, at 6:23 PM, Joern Huxhorn wrote:
Let's move this discussion over to the dev list to leave the bug alone...
On 30.05.2009, at 20:52, Ralph Goers (JIRA) wrote:
[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ]
Ralph Goers commented on LBCORE-97: -----------------------------------
Your notion that UnsynchronizedAppenderBase is "downright dangerous" is complete nonsense. That is like saying multithreaded programming is dangerous so don't do it.
I'd call "complete nonsense" a bit harsh. It's only one step away from bullshit ;)
Yes, I tried to think of a phrase that wasn't so harsh but came up short. I probably wouldn't have replied quite that way if it was on this list, but in a Jira issue where it will more easily be referenced I felt it appropriate to word it a bit more strongly and a bit less diplomatic.
What I would say, however, is that multi-threaded programming is more complex and dangerous than single-threaded, so use it with care.
The Appender that extends UnsynchronizedAppenderBase is called on the same thread that called the logger method. All UnsynchronizedAppenderBase does is leave whatever synchronization is necessary up to the actual Appender. If the appender is going to pass work of to some other thread then the work queue elements need to be fully populated with data on the thread creating the work elememnts, i.e. the same thread that called the logging method. Trying to have the worker thread call methods on objects in a logger event is a very poor design.
I agree 100%. The only thing that I don't like about UnsynchronizedAppenderBase is that it's more error prone because everything you mentioned in the last paragraph must be implemented by every developer that extends UnsynchronizedAB.
I know all the above, you know it, Ceki knows it, but lots of people won't have enough know how to know it.
Asynchronous appenders can be implemented using the synchronous AppenderBase. Just put the LoggingEvent => DataObject transformation in the doAppend call and handle all the rest in different threads.
Well, yes. But that introduces needless inefficiency. The Appender will be synchronized while adding the work to a queue. But the queue must also be synchronized so that the worker thread can remove it from the queue safely. The synchronization of AppenderBase is, IMO, a mistake. Log4j did it and they have plenty of bugs reported about deadlocks. Ceki has already had a couple here. They aren't actually caused by Logback of course, but they often appear to be which is almost as bad as if they were. Every Appender in Logback could be modified so that the synchronization could be moved to a smaller granularity. Unfortunately, some of the layout processing isn't thread-safe so there isn't much point in trying to do that until that is changed.
In many cases the only synchronization needed in an appender will be in the JDK itself when it performs some kind of I/O.
There have been many demonstrated examples where the synchronization that is occuring within logback has caused deadlocks because the application using logback was unaware that the locking would occur. UnsynchronizedAppenderBase actually helps with avoiding deadlocks since the locking moves down to where it is actually needed, not at some higher level "just in case".
I see your point. You want to perform the LE => DO transformation without a lock and lock afterwards while performing the actual appending. That's a *very* good idea and would indeed have the potential to solve issues like http://www.nabble.com/Best-practices-to-avoid-deadlocks-while-logging-td2363... ...
The only real problem I see is the one I showed in the bug.
It's absolutely crucial that appenders perform fair locking and most people (including Ceki and me) are/were absolutely unaware that synchronized can be very unfair - even though it *is* documented! Leaving the synchronization to the appender implementation is therefore somewhat dangerous :p and can result in starvation if done wrong. And it's easy to do it wrong.
I have news for you. In a multithreaded program you aren't going to be able to insure that log records ever occur in a particular order unless the application does the synchronization itself. For example, it is highly likely you will see logging like: Thread 1 - about to do action 1 Thread 2 - about to do action 1 Thread 1 - action 1 performed Thread 3 - about to do action 1 Thread 3 - action 1 performed Thread 2 - action 1 performed This is regardless of whatever locking is going on in Logback. And, of course, there is no assurance that the order of the log entries corresponds to the order in which the actions actually occurred.
It would probably be a good idea to write a base class that performs the LE => DO transformation (converting message arguments, transforming MDC to String, etc.) without a lock, handing the DO to a method that performs a fair lock which in turn executes an abstract method that performs the actual work? I'm just brainstorming here... My primary aim is just to prevent a situation like the one in the bug in lots of appenders that extend UnsynchronizedAppenderBase. We'd need dedicated Logback Logging(- and Access?)DOs in that case.
I'm not sure what "bug in lots of appenders that extend UnsynchronizedAppenderBase" you are talking about. In reading your opening remarks you discuss "fairness" in locking. But it doesn't really matter. 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. Ralph