[logback-dev] [JIRA] Commented: (LBCORE-97) Starvation on AppenderBase.doAppend

[Ralph Goers]

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.issuetabpanels:comment-tabpanel&focusedCommentId=11134#action_11134 
>>  ]
>>
>> 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-td23639031.html 
>  ...
>
> 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