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

[ralph.goers @dslextreme.com]

On Mon, Jun 1, 2009 at 6:51 AM, Joern Huxhorn <jhuxhorn at googlemail.com>wrote:

> But locking will occur at some point and has to be done fairly. Otherwise
> starvation will happen on multi-core systems.


Not if the synchronized blocks take a minimal amount of time. My
modification to your sample app demonstrated that.

>
> I can't imagine an appender that doesn't have to lock at *some* point. Do
> you have any use case for this?


Of course they will have to lock, possibly a few times. But if each lock is
for a very short duration the system will behave much better.


>
>
> It would be possible to generally use a fixed-size blocking queue (fair!)
> in case of UnsynchronizedAppenderBase, leaving the async handling of events
> put into the queue to the actual implementation. Assuming, of course,
> detached data objects again.
>
> What I really want is *one* correct way of handling/implementing async
> appenders so the possibility of failure is reduced as much as possible.
> Nothing is worse than a logging system that crashes the logged application.


We agree on that.

>
>
>
>>> 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/loader/WebappClassLoader.java.
>> I guarantee you this is being called far more often then logging is and it
>> doesn't exhibit these problems.
>>
>>
> The difference is that WebappClassLoader wouldn't suffer from the
> starvation effect because threads (at least if they are ordinary threads
> that don't perform manual classloading magic) will load all classes in a
> burst and then just execute. In that case, the optimization done in Java 6
> will even increase the performance and there is no point in using a fair
> lock.


Your assumption here is wrong. Every call to new calls the class loader. In
most applications objects are created far more than logging is called.


>
>
> Logging, however, is potentially executed all the time during the life of
> the thread(s), probably even in a tight loop. This is were starvation is
> kicking in @tight loop.


That is no surprise to me.


>
>
>  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.
>>
>
> See *.
>
>
>>
>> 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.
>>
>
> I don't understand this example. The whole point of the program is to show
> the starvation effect. The Thread.sleep is only included to be able to
> interrupt the thread and simulate some work.


Yes. And my point was to show that if your program logic is even somewhat
substantial compared to the synchronized block that the starvation effect
goes away. So changing Appenders to not have a single lock held for a long
time to several locks held for short durations would minimize or eliminate
this effect.


>
>
>
>>
>> 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.
>>
>
> See *.
>
>
>>
>>>
>>> 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.
>>
>
> See * ;)
>
> That's correct. And yes, it's some kind of a band-aid, albeit a very
> important one.
> Async logging has other downsides, though, as it will be unable to make
> sure that events are actually appended before the VM exits/crashes, for
> example. This *can* be a real downside.


I'm not talking about synchronous vs asynchronous logging. All appenders
should be modified to use UnsynchronizedAppenderBase. This is a fair amount
of work but will eliminate most, if not all, of these problems.

>
>
> So in some cases, e.g. file appender, you'll *want* synchronous logging, no
> matter what the costs are. Moving the synchronization to a lower level
> wouldn't help much, IMO, since it would simply move the congestion and I
> don't really care if it happens while converting events or while actually
> writing the data to a file if writing has the performance impact. The
> application wouldn't be able to handle other logging, anyway.
> Unless I miss some important point, feel free to prove me wrong.


In the case of file appenders, the congestion will end up occuring in
java.io somewhere. This is a good thing. It avoids deadlocks and any
performance analysis  will show the bottleneck as being there instead of in
Logback.


>
>
> Take a look at
> http://apps.sourceforge.net/trac/lilith/wiki/AppenderPitfalls if you
> haven't already and let me know if you find any mistakes, please.


Sure, when I get a chance this evening.

>
>
> My big pain-point with UnsynchronizedAppenderBase is also it's main
> feature: It's leaving all the locking to the respective implementation.
> All I'm trying to say is that it's very easy to do that part wrong and that
> it won't be apparent if it *is* done wrong.


You'd be surprised how little locking is actually required. Before
condemning this approach I would suggest you take a look at what it would
actually require.


Ralph
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://qos.ch/pipermail/logback-dev/attachments/20090601/d3d2bc32/attachment.htm>