<br><br><div class="gmail_quote">On Mon, Jun 1, 2009 at 6:51 AM, Joern Huxhorn <span dir="ltr"><<a href="mailto:jhuxhorn@googlemail.com">jhuxhorn@googlemail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
But locking will occur at some point and has to be done fairly. Otherwise starvation will happen on multi-core systems.</blockquote><div><br>Not if the synchronized blocks take a minimal amount of time. My modification to your sample app demonstrated that. <br>
</div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><br>
I can't imagine an appender that doesn't have to lock at *some* point. Do you have any use case for this?</blockquote><div><br>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.<br>
<br></div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><br>
<br>
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.<br>
<br>
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.</blockquote>
<div><br>We agree on that. <br></div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><div class="im"><br>
<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
I'm simulating the AppenderBase situation here, lots of threads are trying to access the very same resource.<br>
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.<br>
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.<br>
<br>
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.<br>
</blockquote>
<br>
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 <a href="https://svn.apache.org/repos/asf/tomcat/trunk/java/org/apache/catalina/loader/WebappClassLoader.java" target="_blank">https://svn.apache.org/repos/asf/tomcat/trunk/java/org/apache/catalina/loader/WebappClassLoader.java</a>. I guarantee you this is being called far more often then logging is and it doesn't exhibit these problems.<br>
<br>
</blockquote>
<br></div>
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.</blockquote>
<div><br>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.<br> <br></div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
<br>
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.</blockquote><div><br>That is no surprise to me.<br>
<br></div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><div class="im"><br>
<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
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.<br>
</blockquote>
<br></div>
See *.<div class="im"><br>
<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
<br>
To prove this I simply added<br>
<br>
for (int i=0; i < 100000; ++i) { if lock == null { throw new NullPointerException(); } }<br>
<br>
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.<br>
</blockquote>
<br></div>
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.</blockquote><div><br>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.<br>
<br></div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><div class="im"><br>
<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
<br>
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.<br>
</blockquote>
<br></div>
See *.<div class="im"><br>
<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
<br>
I assume you hadn't understood the point of LBCORE-97 until now... and please don't take that as an insult ;)<br>
</blockquote>
<br>
I the understanding of it. I just don't think it is the right way to fix the problem.<br>
<blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
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.<br>
<br>
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.<br>
<br>
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.<br>
<br>
It would probably be a better idea to use a<br>
<br>
protected final ReentrantReadWriteLock readWriteLock=new ReentrantReadWriteLock(true);<br>
<br>
fair ReentrantReadWriteLock in AppenderBase instead.<br>
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...<br>
<br>
One way to handle transformation of the event outside the lock is what I suggested in <a href="http://jira.qos.ch/browse/LBCLASSIC-45" target="_blank">http://jira.qos.ch/browse/LBCLASSIC-45</a>.<br>
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...<br>
<br>
I've just changed my patch to make lock protected instead of private. Seems to be a much better idea :p<br>
<br>
And just to get my point straight once more:<br>
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!<br>
<br>
</blockquote>
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.<br>
</blockquote>
<br></div>
See * ;)<br>
<br>
That's correct. And yes, it's some kind of a band-aid, albeit a very important one.<br>
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.</blockquote><div><br>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. <br>
</div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><br>
<br>
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.<br>
Unless I miss some important point, feel free to prove me wrong.</blockquote><div><br>In the case of file appenders, the congestion will end up occuring in <a href="http://java.io">java.io</a> somewhere. This is a good thing. It avoids deadlocks and any performance analysis will show the bottleneck as being there instead of in Logback.<br>
</div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><br>
<br>
Take a look at <a href="http://apps.sourceforge.net/trac/lilith/wiki/AppenderPitfalls" target="_blank">http://apps.sourceforge.net/trac/lilith/wiki/AppenderPitfalls</a> if you haven't already and let me know if you find any mistakes, please.</blockquote>
<div><br>Sure, when I get a chance this evening. <br></div><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;"><br>
<br>
My big pain-point with UnsynchronizedAppenderBase is also it's main feature: It's leaving all the locking to the respective implementation.<br>
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.</blockquote><div><br>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. <br>
<br><br>Ralph</div></div><br>