[
http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11141#action_11141
]
Joern Huxhorn commented on LBCORE-97:
-------------------------------------
> Standard java synchronization was never guaranteed to be fair. Java 6 (or the
> OS scheduler) is simply doing more optimizations that it didn't do previously
> but was always allowed to do.
+1
> However I don't see why this is a problem unless logging is your bottleneck
Logging is, indeed, the bottleneck of our application at the moment, but this
is expected, "by design" and will change at a later time.
- We are rolling out a new version of our app so logging is still unusually high
- We are doing a proprietary CMS with XSLT as the template language. There are
several XSLT developers receiving compilation specific INFO, WARN and ERROR
events via my MulticastSocketAppender.
- The slowest receiver essentially dictates the overall speed of the application
> If this is the case I'd investigate why you're spending so much time in
> logging and if that's unfixable change to asynchronous logging.
The MultiplexAppender is already semi-asynchronous, meaning that it has a
buffer of fixed size that is filled before the appender blocks.
See http://apps.sourceforge.net/trac/lilith/wiki/AppenderPitfalls
We've done this "abusive" logging for over a year with *very* acceptable
performance.
Then we moved from a single-core Java 1.5 server to a multi-core Java 1.6
server and, suddenly, performance was extremely crappy. I narrowed the problem
down to the issue discussed here and never really expected any discussion
whether this patch should be applied or not because - honestly - I think I did
a pretty good job citing all relevant documentation, showing up that we all
worked with false presumptions - and this explicitly includes myself!
I *knew* that fairness wasn't guaranteed but I *assumed* that something like
nearly-fair or somewhat-unfair could be expected. This assumption was wrong.
> because synchronous logging will in this case turn your application into a
> single threaded one
There's some truth in this statement.;)
However, large amounts of code won't log anything while other parts log in
relatively big bursts so, theoretically, all CPUs should be able to work quite
a bit, anyway, even if parts of the application are running
semi-single-threaded.
> 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: AppenderBaseLock2.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
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
