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

[Joern Huxhorn]

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

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

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.

Regards,
Joern.

>> Starvation on AppenderBase.doAppend
>> -----------------------------------
>>
>>                Key: LBCORE-97
>>                URL: http://jira.qos.ch/browse/LBCORE-97
>>            Project: logback-core
>>         Issue Type: Bug
>>         Components: Appender
>>   Affects Versions: 0.9.15
>>           Reporter: Joern Huxhorn
>>           Assignee: Logback dev list
>>           Priority: Critical
>>        Attachments: AppenderBaseLock.patch,  
>> SynchronizedVsFairLock.java
>>
>>
>> The problem we are facing here is that several threads are trying  
>> to obtain the object monitor of the exact same resource, namely the  
>> Appender.
>> The assumption that multiple threads waiting for ownership of a  
>> monitor would receive the monitor in the order that they tried to  
>> acquire it is simply incorrect. This is documented behavior.
>> See the last paragraph of [1]:
>> "Likewise, no assumptions should be made about the order in which  
>> threads are granted ownership of a monitor or the order in which  
>> threads wake in response to the notify or notifyAll method. An  
>> excellent reference for these topics is Chapter 9, "Threads," in  
>> Joshua Bloch's book Effective Java Programming Language Guide. "
>> The documentation of Object.notifyAll() [2] states the following:
>> "[..] The awakened threads will compete in the usual manner with  
>> any other threads that might be actively competing to synchronize  
>> on this object; for example, the awakened threads enjoy no reliable  
>> privilege or disadvantage in being the next thread to lock this  
>> object."
>> The documentation in [5] also lists the following as a weak-spot of  
>> Built-in Synchronization in J2SE 1.4.x:
>> "No way to alter the semantics of a lock, for example, with respect  
>> to reentrancy, read versus write protection, or fairness."
>> In LBCORE-96 Ceki stated the following:
>> "Logback is using the standard synchronization mechanism found in  
>> the JDK. You are saying that that mechanism is unsuitable which,  
>> truth be told, sounds quite suspicious."
>> Yes, it's unsuitable in this situation because obtaining the object  
>> monitor is not guaranteed to be fair. It's not working in a "first  
>> come, first serve" manner. I assumed that, too, but it isn't the  
>> case. I had the exact same problem in Lilith some time ago because  
>> I made exactly this very same wrong assumption.
>> Fairness of object monitor lock acquisition seems to be logical and  
>> a "good thing" but it's not specified that way, and for good reasons.
>> Without fairness in place, the VM can optimize the execution of an  
>> application much better. A context switch is a costly operation for  
>> a CPU so performance is increased significantly if such a switch  
>> can be omitted.
>> Concerning a test-case, this would be pretty hardcore to implement  
>> since it's 100% implementation dependent. One implementation *may*  
>> handle the locking of object monitors fairly while others don't.
>> Therefore I'll try the following first:
>> I assume I could convince you that object monitor acquisition (OMA)  
>> is not fair.
>> If we take that for granted the following scenario should show my  
>> point:
>> There are 4 Threads (e.g. 4 Threads handling concurrent webapp- 
>> requests) that have one single chokepoint, the appender.
>> Since OMA isn't fair, it's possible that only some of those threads  
>> can work at all (see [3]). Exactly that is happening right now in  
>> our webapp running on a 4-core Solaris on JDK6.
>> My next assumption is that we both agree that this isn't acceptable  
>> behavior.
>> Logging should be handled "first come, first served" so that if  
>> Thread A is waiting to append an event and Thread B is waiting to  
>> append an event subsequently, the actual appending order should be  
>> A, then B.
>> This is currently not the case. It *may* be the case but there is  
>> no guarantee of it.
>> One could even argue that the logging system is working incorrectly  
>> (aside from the starvation problem) because events are appended in  
>> a different order than the actual execution of the logger call.
>> The only way to prevent this is the introduction of fairness into  
>> the locking process. The way to do this is to use ReentrantLock [4].
>> From the ReentrantLock javadoc:
>> "The constructor for this class accepts an optional fairness  
>> parameter. When set true, under contention, locks favor granting  
>> access to the longest-waiting thread. Otherwise this lock does not  
>> guarantee any particular access order. Programs using fair locks  
>> accessed by many threads may display lower overall throughput  
>> (i.e., are slower; often much slower) than those using the default  
>> setting, but have smaller variances in times to obtain locks and  
>> guarantee lack of starvation."
>> This is exactly what is absolutely necessary for a logging framework.
>> Logging must *NOT* be able to introduce a starvation problem into a  
>> multi-threaded application! And it does exactly that right now.
>> I doubt that the performance will decrease in a significant manner  
>> due to the use of a fair ReentrantLock but even if this would be  
>> the case it would be necessary anyway.
>> Otherwise, appending simply isn't working correctly.
>> [1] http://java.sun.com/j2se/1.5.0/docs/guide/vm/thread-priorities.html
>> [2] http://java.sun.com/javase/6/docs/api/java/lang/Object.html#notifyAll()
>> [3] http://en.wikipedia.org/wiki/Starvation_(computing)
>> [4] http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantLock.html
>> [5] http://java.sun.com/developer/technicalArticles/J2SE/concurrency/
>
> -- 
> This message is automatically generated by JIRA.
> -
> If you think it was sent incorrectly contact one of the  
> administrators: http://jira.qos.ch/secure/Administrators.jspa
> -
> For more information on JIRA, see: http://www.atlassian.com/software/jira
>
>
> _______________________________________________
> logback-dev mailing list
> logback-dev at qos.ch
> http://qos.ch/mailman/listinfo/logback-dev