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

[Ceki Gulcu (JIRA)]

    [ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11148#action_11148 ] 

Ceki Gulcu commented on LBCORE-97:
----------------------------------

Thank you for these new figures and I hope you enjoy your holidays.

> Given that there are Appenders that are candidates for a delay > 3ms,
> e.g. SocketAppender, DBAppender, SMTPAppender and even FileAppender
> (especially if the log file is located on a NAS), I'd still strongly
> suggest to change AppenderBase according to my suggestion.

Only DBAppender has a latency in the order of a millisecond. SMTPAppender causes delays in the order of a millisecond only when it sends email, which is rare and thus can be ignored. SocketAppender has a throughput of over 20'000 messages per second, translating to a latency of less than 50 microseconds. FileAppender, when writing to a local file, has a throughput of over 100'000 messages per second, corresponding to a latency of less than 10 microseconds. 

FileAppender writing on a networked file system is an interesting case because delays can be significantly larger. However, unless the network awfully slow, we would still be situated well below the millisecond range.  

By the way, 3 ms (milliseconds) is the threshold where things go awry, at least on Linux. At 2ms and lower, the time slicer distributes resources rather fairly.

> While this isn't as critical and as obvious as before, the difference
> between the lowest value 197 and the highest value 2587 is still very
> high. The values should be relatively equal, after all, especially
> since the only thing preventing this is, in reality, the logging
> system.

Yes, the ration between 2587 and 195, that is 13.13, is rather uneven. We could reasonably begin to talk about starvation. Nevertheless, one could also argue that, if you remove the two extreme  values, 195 and 2597, and if you draw a frequency distribution where the x-axis represents frequency groupings of width 300, starting at 0 ending at 1500, you get a graph looking like a nice bell curve. (I've actually done this.)

Note that if you reduce the delay Thread.sleep() to the range of 10 microseconds, which in my opinion is more representative, you will see that the numbers are distributed more smoothly.  Also note that, and this is quite important, a normal application would not spend all its time logging, it would have other activities which would cause the thread last holding the "appender" lock to lose it in favor of a competing thread.

You seem to be fairly convinced that the starvation problem observed in your application is due to logging. What makes you think this? Have you observed improved behavior when logging is disabled? You could replace logback-classic.jar with slf4j-nop.jar just to test.

As for a pluggable locking mechanism, it is an interesting idea. However, I would first like to establish that there is actually a problem in logback, especially as Java itself is not a real-time language. 

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