[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn updated LBCORE-97: -------------------------------- Attachment: AppenderBaseLock.patch Patch fixing the starvation problem using a fair ReentrantLock.

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

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu edited comment on LBCORE-97 at 5/29/09 4:39 PM: -----------------------------------------------------------

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.

Could you lease supply a test case which demonstrates your point, even if it is for a specific JDK? I would at least like to see an example. FYI, I have several multi-core PCs available running Linux and/or Windows. was (Author: noreply.ceki@qos.ch): > 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.

Could you supply a test case which demonstrates your point, even if it is for a specific JDK? I would at least like to see an example. FYI, I have several multi-core PCs available running Linux and/or Windows.

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

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- I could try to provide a sample program that shows the general problem of starvation. Would this have to be logback related or is it sufficient if I show that what the documenation says is correct? Or are you talking about a real JUnit testcase that's using logback? Would this be worth anything if it fails on some systems and works on others? As always, assumptions about absolute program execution are pretty hard to make when it comes to multi-threaded applications. The example attached to LBCORE-96 shows that the threads are "synchronized" with the patch in place, i.e. every pool gets the chance to log a message 2009-05-19 22:03:14,520 DEBUG [pool-1-thread-1] [EX1] 5936 2009-05-19 22:03:14,520 DEBUG [pool-3-thread-1] [MAIN] - [EX3] 5925 2009-05-19 22:03:14,520 DEBUG [pool-2-thread-1] [EX2] 5926 2009-05-19 22:03:14,520 DEBUG [pool-5-thread-1] [MAIN] - [EX5] 5900 2009-05-19 22:03:14,520 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 5925 2009-05-19 22:03:14,521 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 5937 2009-05-19 22:03:14,521 DEBUG [pool-3-thread-1] [EX3] 5926 2009-05-19 22:03:14,521 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 5927 2009-05-19 22:03:14,521 DEBUG [pool-5-thread-1] [EX5] 5901 2009-05-19 22:03:14,521 DEBUG [pool-4-thread-1] [EX4] 5926 I inserted newlines to better show the point. It's always executing 1-3-2-5-4. Without the patch, the threads are executed unevenly. This is solely caused by the non-fairness of synchronized as the rest of the code is untouched. The only thing that I could do is to write some program that shows this more drastically, e.g. letting 10 threads run for some time in an endless loop, each containing a synchronized(sameObject) block, counting the times they loop. After a specific time, e.g. 10 sec, I could interrupt all threads and they would certainly have quite different counter values (the amount of difference would vary from system to system and VM to VM). Running the same code with a fair ReentrantLock would generate results with (nearly, because of the interruption of the threads) identical numbers. That's the whole point of fair locks. I had the exact same wrong assumption about fairness in a wait()/notifyAll() situation in Lilith. A thread with the purpose of removing received events from an intermittent cyclic buffer just wouldn't get the chance to remove the events. This was caused by updating the used JRE to Java 1.6. It took me a while to understand the problem and I was quite baffled.

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

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- Here are my personal result: iMac 2.4GHz Intel Core 2 Duo i.e. multi-core Environment: java.runtime.name = Java(TM) SE Runtime Environment java.runtime.version = 1.6.0_07-b06-153 java.vendor = Apple Inc. java.version = 1.6.0_07 java.vm.name = Java HotSpot(TM) 64-Bit Server VM java.vm.info = mixed mode os.name = Mac OS X os.version = 10.5.7 os.arch = x86_64 ########################################## About to execute usingSynchronized... Results for usingSynchronized: runnables[0]: SynchronizedRunnable[counter=394, running=false] runnables[1]: SynchronizedRunnable[counter=1, running=false] runnables[2]: SynchronizedRunnable[counter=1, running=false] runnables[3]: SynchronizedRunnable[counter=1, running=false] runnables[4]: SynchronizedRunnable[counter=1, running=false] runnables[5]: SynchronizedRunnable[counter=1, running=false] runnables[6]: SynchronizedRunnable[counter=1, running=false] runnables[7]: SynchronizedRunnable[counter=1, running=false] runnables[8]: SynchronizedRunnable[counter=1, running=false] runnables[9]: SynchronizedRunnable[counter=605, running=false] ########################################## About to execute usingUnfairLock... Results for usingUnfairLock: runnables[0]: LockRunnable[counter=997, running=false] runnables[1]: LockRunnable[counter=1, running=false] runnables[2]: LockRunnable[counter=1, running=false] runnables[3]: LockRunnable[counter=1, running=false] runnables[4]: LockRunnable[counter=1, running=false] runnables[5]: LockRunnable[counter=1, running=false] runnables[6]: LockRunnable[counter=1, running=false] runnables[7]: LockRunnable[counter=1, running=false] runnables[8]: LockRunnable[counter=1, running=false] runnables[9]: LockRunnable[counter=1, running=false] ########################################## About to execute usingFairLock... Results for usingFairLock: runnables[0]: LockRunnable[counter=101, running=false] runnables[1]: LockRunnable[counter=101, running=false] runnables[2]: LockRunnable[counter=101, running=false] runnables[3]: LockRunnable[counter=101, running=false] runnables[4]: LockRunnable[counter=100, running=false] runnables[5]: LockRunnable[counter=100, running=false] runnables[6]: LockRunnable[counter=100, running=false] runnables[7]: LockRunnable[counter=100, running=false] runnables[8]: LockRunnable[counter=100, running=false] runnables[9]: LockRunnable[counter=100, running=false] ########################################## Environment: java.runtime.name = Java(TM) 2 Runtime Environment, Standard Edition java.runtime.version = 1.5.0_16-b06-284 java.vendor = Apple Inc. java.version = 1.5.0_16 java.vm.name = Java HotSpot(TM) Client VM java.vm.info = mixed mode, sharing os.name = Mac OS X os.version = 10.5.7 os.arch = i386 ########################################## About to execute usingSynchronized... Results for usingSynchronized: runnables[0]: SynchronizedRunnable[counter=101, running=false] runnables[1]: SynchronizedRunnable[counter=101, running=false] runnables[2]: SynchronizedRunnable[counter=101, running=false] runnables[3]: SynchronizedRunnable[counter=101, running=false] runnables[4]: SynchronizedRunnable[counter=101, running=false] runnables[5]: SynchronizedRunnable[counter=101, running=false] runnables[6]: SynchronizedRunnable[counter=100, running=false] runnables[7]: SynchronizedRunnable[counter=100, running=false] runnables[8]: SynchronizedRunnable[counter=100, running=false] runnables[9]: SynchronizedRunnable[counter=100, running=false] ########################################## About to execute usingUnfairLock... Results for usingUnfairLock: runnables[0]: LockRunnable[counter=485, running=false] runnables[1]: LockRunnable[counter=495, running=false] runnables[2]: LockRunnable[counter=19, running=false] runnables[3]: LockRunnable[counter=1, running=false] runnables[4]: LockRunnable[counter=1, running=false] runnables[5]: LockRunnable[counter=1, running=false] runnables[6]: LockRunnable[counter=1, running=false] runnables[7]: LockRunnable[counter=1, running=false] runnables[8]: LockRunnable[counter=1, running=false] runnables[9]: LockRunnable[counter=1, running=false] ########################################## About to execute usingFairLock... Results for usingFairLock: runnables[0]: LockRunnable[counter=101, running=false] runnables[1]: LockRunnable[counter=101, running=false] runnables[2]: LockRunnable[counter=101, running=false] runnables[3]: LockRunnable[counter=101, running=false] runnables[4]: LockRunnable[counter=101, running=false] runnables[5]: LockRunnable[counter=100, running=false] runnables[6]: LockRunnable[counter=100, running=false] runnables[7]: LockRunnable[counter=100, running=false] runnables[8]: LockRunnable[counter=100, running=false] runnables[9]: LockRunnable[counter=100, running=false] ########################################## #################################################################################### IBM ThinkPad Intel Pentium M processor 1.86GHz i.e. single-core Environment: java.runtime.name = Java(TM) 2 Runtime Environment, Standard Edition java.runtime.version = 1.5.0_13-b05 java.vendor = Sun Microsystems Inc. java.version = 1.5.0_13 java.vm.name = Java HotSpot(TM) Client VM java.vm.info = mixed mode, sharing os.name = Windows XP os.version = 5.1 os.arch = x86 ########################################## About to execute usingSynchronized... Results for usingSynchronized: runnables[0]: SynchronizedRunnable[counter=65, running=false] runnables[1]: SynchronizedRunnable[counter=65, running=false] runnables[2]: SynchronizedRunnable[counter=65, running=false] runnables[3]: SynchronizedRunnable[counter=65, running=false] runnables[4]: SynchronizedRunnable[counter=65, running=false] runnables[5]: SynchronizedRunnable[counter=65, running=false] runnables[6]: SynchronizedRunnable[counter=65, running=false] runnables[7]: SynchronizedRunnable[counter=64, running=false] runnables[8]: SynchronizedRunnable[counter=64, running=false] runnables[9]: SynchronizedRunnable[counter=64, running=false] ########################################## About to execute usingUnfairLock... Results for usingUnfairLock: runnables[0]: LockRunnable[counter=50, running=false] runnables[1]: LockRunnable[counter=86, running=false] runnables[2]: LockRunnable[counter=63, running=false] runnables[3]: LockRunnable[counter=54, running=false] runnables[4]: LockRunnable[counter=72, running=false] runnables[5]: LockRunnable[counter=72, running=false] runnables[6]: LockRunnable[counter=54, running=false] runnables[7]: LockRunnable[counter=72, running=false] runnables[8]: LockRunnable[counter=70, running=false] runnables[9]: LockRunnable[counter=57, running=false] ########################################## About to execute usingFairLock... Results for usingFairLock: runnables[0]: LockRunnable[counter=65, running=false] runnables[1]: LockRunnable[counter=65, running=false] runnables[2]: LockRunnable[counter=65, running=false] runnables[3]: LockRunnable[counter=65, running=false] runnables[4]: LockRunnable[counter=64, running=false] runnables[5]: LockRunnable[counter=64, running=false] runnables[6]: LockRunnable[counter=64, running=false] runnables[7]: LockRunnable[counter=64, running=false] runnables[8]: LockRunnable[counter=64, running=false] runnables[9]: LockRunnable[counter=64, running=false] ########################################## Environment: java.runtime.name = Java(TM) SE Runtime Environment java.runtime.version = 1.6.0_13-b03 java.vendor = Sun Microsystems Inc. java.version = 1.6.0_13 java.vm.name = Java HotSpot(TM) Client VM java.vm.info = mixed mode, sharing os.name = Windows XP os.version = 5.1 os.arch = x86 ########################################## About to execute usingSynchronized... Results for usingSynchronized: runnables[0]: SynchronizedRunnable[counter=6, running=false] runnables[1]: SynchronizedRunnable[counter=11, running=false] runnables[2]: SynchronizedRunnable[counter=85, running=false] runnables[3]: SynchronizedRunnable[counter=70, running=false] runnables[4]: SynchronizedRunnable[counter=75, running=false] runnables[5]: SynchronizedRunnable[counter=73, running=false] runnables[6]: SynchronizedRunnable[counter=74, running=false] runnables[7]: SynchronizedRunnable[counter=88, running=false] runnables[8]: SynchronizedRunnable[counter=72, running=false] runnables[9]: SynchronizedRunnable[counter=90, running=false] ########################################## About to execute usingUnfairLock... Results for usingUnfairLock: runnables[0]: LockRunnable[counter=64, running=false] runnables[1]: LockRunnable[counter=87, running=false] runnables[2]: LockRunnable[counter=60, running=false] runnables[3]: LockRunnable[counter=60, running=false] runnables[4]: LockRunnable[counter=76, running=false] runnables[5]: LockRunnable[counter=54, running=false] runnables[6]: LockRunnable[counter=54, running=false] runnables[7]: LockRunnable[counter=71, running=false] runnables[8]: LockRunnable[counter=56, running=false] runnables[9]: LockRunnable[counter=67, running=false] ########################################## About to execute usingFairLock... Results for usingFairLock: runnables[0]: LockRunnable[counter=65, running=false] runnables[1]: LockRunnable[counter=65, running=false] runnables[2]: LockRunnable[counter=65, running=false] runnables[3]: LockRunnable[counter=65, running=false] runnables[4]: LockRunnable[counter=65, running=false] runnables[5]: LockRunnable[counter=65, running=false] runnables[6]: LockRunnable[counter=65, running=false] runnables[7]: LockRunnable[counter=64, running=false] runnables[8]: LockRunnable[counter=64, running=false] runnables[9]: LockRunnable[counter=64, running=false] ##########################################

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- Conclusion: synchronized was fair on 1.5, is a bit unfair on 1.6 single-core and very unfair on 1.6 multi-core. Please apply my patch, thanks ;)

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- This problem is not at all related to my appender but bites *every* appender that extends AppenderBase, i.e. console, file and socket appender. On a side-note, the Lilith appender is semi-asynchronous and has a buffer of 1000 already serialized events so it's possible to handle bursts of events gracefully. It blocks only after that buffer has been filled. The buffer content is attached to async sub-appenders that are either sending the bytes or discarding them in case of no connection. Since the events are already serialized all sub-appenders receive the exact same byte arrays to send. Take a look at http://apps.sourceforge.net/trac/lilith/wiki/MultiplexAppenderBackground if you are interested. On another side-note, I still consider UnsynchronizedAppenderBase downright dangerous because I firmly (read: religiously) believe that async handling of LoggingEvent instances will introduce problems like http://www.nabble.com/Best-practices-to-avoid-deadlocks-while-logging-td2363... reloaded, i.e. on a whole new level. Serialization (or, more generally, evaluation) *must* be handled synchronously because it's impossible to predict how objects in the MDC and message arguments will behave if converted to a string asynchronously. Even if no deadlock will occur, they *might* have changed in the meantime, essentially producing "lying" log statements in the end. But all this is really 100% unrelated to this bug report. This is a general problem that was introduced in Java 1.6. It's only showing up badly in case of real multi-core systems which made it a bit hard for me to analyze on my terribly outdated 3-year old laptop at work... I guess that's the price a company has to pay if their developers are forced to work with flint stone devices. Are you reading this, IT department?? :p

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] 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. 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. 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".

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- I replied on the dev list because this discussion is unrelated to the bug.

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn updated LBCORE-97: -------------------------------- Attachment: (was: AppenderBaseLock.patch)

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- I've written an article about this problem in the Lilith wiki: http://apps.sourceforge.net/trac/lilith/wiki/SynchronizedVsFairLock

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- Have you done any benchmarking concerning the performance impact of the fair ReentrantLock? I guess you have logback benchmarks at your fingertips, I'd be quite interested in the numbers. Concerning the "bug in the Sun JDK" part: It's the same way in case of the Mac version of Java 6. I highly doubt that Sun will come to it's senses ;) and I'm not even sure that it can be validly called a bug since it doesn't breach any documented behavior. This might really be a valid performance enhancement because switching threads means degrading performance. I'd be really grateful if this patch could be applied before the next release. We are suffering quite bad because of it. In our case it's - as mentioned - a Solaris and we can't just switch the VM or the OS as we like because of customer rules.

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Philippe Marschall 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. However I don't see why this is a problem unless logging is your bottleneck because there is no real ordering in multi thread applications anyway. If logging is your bottleneck I see this as a serious issue because synchronous logging will in this case turn your application into a single threaded one and you're effectively producing logging events faster than you can log them. 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. Sure it doesn't work out of the box with MDCs but there are ways to solve that. Either copy the MDC or format the message in the calling thread (without aquiring a lock) and adding the formatted instead of the unformatted string to the queue.

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- FYI, I changed MultiplexSocketAppenderBase to extend UnsynchronizedAppenderBase instead of AppenderBase to circumvent this problem. Locking is now solely handled by a fair (!!) BlockingQueue. This issue is still valid, though, since it's also apparent - to a lesser degree - if only file or console appender is used. In addition to applying my patch I'd also strongly suggest that a comment is added to UnsynchronizedAppenderBase stating that any locking performed by an extending class *must* be fair to prevent starvation. This is really the case, please believe me. If this comment is added to UnsynchronizedAppenderBase, an extending class is effectively breaching contract if locking differently. A logging system is, in fact, a prime example where locking just *has* to be fair to prevent starvation since multiple threads *are* trying to access the same resource (Logger/Appender) all the time. http://java.sun.com/docs/books/tutorial/essential/concurrency/starvelive.htm...

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-97: ---------------------------------- Have you noticed that the starvation issue arises 1) only if the sleep duration is 3 milliseconds and over (on Linux) 2) with JDK 1.5 as well ? I had a long exchange with Dave Dice on the topic of <a href="http://ceki.blogspot.com/2009/06/biased-locking-in-java-se-60.html">biased locking</a> in my blog. Apparently, the issue is not JDK 1.6 specific and was present in older JVMs as well. Given that logback usually does not hold the lock (on itself) for more than 10 microseconds, there starvation condition should not occur in practice. (This assertion applies to tests on Linux and Windows). I'd apprecite if the 3 millisecond threshold could be confirmed for OS X and Solaris. To set a lower sleep duration, within the run() method of SynchronizedRunnable modify Thread.sleep(10); to Thread.sleep(1); or even a smaller value: Thread.sleep(0, 10*1000); // 10 microseconds

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu edited comment on LBCORE-97 at 6/8/09 9:39 PM: ---------------------------------------------------------- Have you noticed that the starvation issue arises 1) only if the sleep duration is 3 milliseconds and over (on Linux) 2) with JDK 1.5 as well ? I had a long exchange with Dave Dice on the topic of biased locking [1] in my blog. Apparently, the issue is not JDK 1.6 specific and was present in older JVMs as well. Given that logback usually does not hold the lock (on itself) for more than 10 microseconds, the starvation condition should not occur in practice. (This assertion is based on experimentation done on Linux and Windows). I'd appreciate if the 3 millisecond threshold could be confirmed for OS X and Solaris. To set a lower sleep duration, within the run() method of SynchronizedRunnable modify Thread.sleep(10); to Thread.sleep(1); or even a smaller value: Thread.sleep(0, 10*1000); // 10 microseconds [1] http://ceki.blogspot.com/2009/06/biased-locking-in-java-se-60.html was (Author: noreply.ceki@qos.ch): Have you noticed that the starvation issue arises 1) only if the sleep duration is 3 milliseconds and over (on Linux) 2) with JDK 1.5 as well ? I had a long exchange with Dave Dice on the topic of biased locking [1] in my blog. Apparently, the issue is not JDK 1.6 specific and was present in older JVMs as well. Given that logback usually does not hold the lock (on itself) for more than 10 microseconds, there starvation condition should not occur in practice. (This assertion applies to tests on Linux and Windows). I'd apprecite if the 3 millisecond threshold could be confirmed for OS X and Solaris. To set a lower sleep duration, within the run() method of SynchronizedRunnable modify Thread.sleep(10); to Thread.sleep(1); or even a smaller value: Thread.sleep(0, 10*1000); // 10 microseconds [1] http://ceki.blogspot.com/2009/06/biased-locking-in-java-se-60.html

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn edited comment on LBCORE-97 at 6/9/09 8:41 AM: ------------------------------------------------------------- I was able to get the following results after several runs of my modified SynchronizedVsFairLock ( http://apps.sourceforge.net/trac/lilith/browser/trunk/misc/synchronized-lock... ). In other cases, locking wasn't as unfair as the numbers below. The starvation behavior isn't as reproducible as before but it's still there. The chance of starvation increases with the amount of delay. 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. We should really aim to switch over to a "locking as needed" strategy, as Ralph suggested. Changing more and more appenders to extend UnsynchronizedAppenderBase and handling locking - in a fair way - as needed by the respective implementation. Depending on unfair locking is IMO a risk that is way to high and is, essentially, wrong. Concerning "real life experience", leaving my proof of problem aside, I can tell you that the starvation effect is still happening with a RollingFileAppender in place, it's just not as bad as with a SocketAppender. Taking into account LBCORE-62 and LBCORE-96, I think it's save to assume that this is a general problem. My results for Mac OS are below. I can't test on Solaris right now because I'm on vacation. Environment: delay = 3 java.runtime.name = Java(TM) SE Runtime Environment java.runtime.version = 1.6.0_07-b06-153 java.vendor = Apple Inc. java.version = 1.6.0_07 java.vm.name = Java HotSpot(TM) 64-Bit Server VM java.vm.info = mixed mode os.name = Mac OS X os.version = 10.5.7 os.arch = x86_64 ########################################## About to execute usingSynchronized... Results for usingSynchronized: runnables[0]: SynchronizedRunnable[counter=967, running=false, delay=3] runnables[1]: SynchronizedRunnable[counter=155, running=false, delay=3] runnables[2]: SynchronizedRunnable[counter=753, running=false, delay=3] runnables[3]: SynchronizedRunnable[counter=583, running=false, delay=3] runnables[4]: SynchronizedRunnable[counter=471, running=false, delay=3] runnables[5]: SynchronizedRunnable[counter=367, running=false, delay=3] runnables[6]: SynchronizedRunnable[counter=1, running=false, delay=3] runnables[7]: SynchronizedRunnable[counter=1, running=false, delay=3] runnables[8]: SynchronizedRunnable[counter=1, running=false, delay=3] runnables[9]: SynchronizedRunnable[counter=2, running=false, delay=3] ########################################## About to execute usingUnfairLock... Results for usingUnfairLock: runnables[0]: LockRunnable[counter=375, running=false, delay=3] runnables[1]: LockRunnable[counter=51, running=false, delay=3] runnables[2]: LockRunnable[counter=1154, running=false, delay=3] runnables[3]: LockRunnable[counter=38, running=false, delay=3] runnables[4]: LockRunnable[counter=1583, running=false, delay=3] runnables[5]: LockRunnable[counter=91, running=false, delay=3] runnables[6]: LockRunnable[counter=1, running=false, delay=3] runnables[7]: LockRunnable[counter=1, running=false, delay=3] runnables[8]: LockRunnable[counter=1, running=false, delay=3] runnables[9]: LockRunnable[counter=1, running=false, delay=3] ########################################## About to execute usingFairLock... Results for usingFairLock: runnables[0]: LockRunnable[counter=328, running=false, delay=3] runnables[1]: LockRunnable[counter=328, running=false, delay=3] runnables[2]: LockRunnable[counter=328, running=false, delay=3] runnables[3]: LockRunnable[counter=328, running=false, delay=3] runnables[4]: LockRunnable[counter=328, running=false, delay=3] runnables[5]: LockRunnable[counter=328, running=false, delay=3] runnables[6]: LockRunnable[counter=328, running=false, delay=3] runnables[7]: LockRunnable[counter=328, running=false, delay=3] runnables[8]: LockRunnable[counter=328, running=false, delay=3] runnables[9]: LockRunnable[counter=328, running=false, delay=3] ########################################## was (Author: jhuxhorn): I was able to get the following results after several runs of my modified SynchronizedVsFairLock ( http://apps.sourceforge.net/trac/lilith/browser/trunk/misc/synchronized-lock... ). In other cases, locking wasn't as unfair as the numbers below. The starvation behavior isn't as reproducible as before but it's still there. The chance of starvation increases with the amount of delay. 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. Why should really aim to switch over to a "locking as needed" strategy, as Ralph suggested. Changing more and more appenders to extend UnsynchronizedAppenderBase and handling locking - in a fair way - as needed by the respective implementation. Depending on unfair locking is IMO a risk that is way to high and is, essentially, wrong. Concerning "real life experience", leaving my proof of problem aside, I can tell you that the starvation effect is still happening with a RollingFileAppender in place, it's just not as bad as with a SocketAppender. Taking into account LBCORE-62 and LBCORE-96, I think it's save to assume that this is a general problem. My results for Mac OS are below. I can't test on Solaris right now because I'm on vacation. Environment: delay = 3 java.runtime.name = Java(TM) SE Runtime Environment java.runtime.version = 1.6.0_07-b06-153 java.vendor = Apple Inc. java.version = 1.6.0_07 java.vm.name = Java HotSpot(TM) 64-Bit Server VM java.vm.info = mixed mode os.name = Mac OS X os.version = 10.5.7 os.arch = x86_64 ########################################## About to execute usingSynchronized... Results for usingSynchronized: runnables[0]: SynchronizedRunnable[counter=967, running=false, delay=3] runnables[1]: SynchronizedRunnable[counter=155, running=false, delay=3] runnables[2]: SynchronizedRunnable[counter=753, running=false, delay=3] runnables[3]: SynchronizedRunnable[counter=583, running=false, delay=3] runnables[4]: SynchronizedRunnable[counter=471, running=false, delay=3] runnables[5]: SynchronizedRunnable[counter=367, running=false, delay=3] runnables[6]: SynchronizedRunnable[counter=1, running=false, delay=3] runnables[7]: SynchronizedRunnable[counter=1, running=false, delay=3] runnables[8]: SynchronizedRunnable[counter=1, running=false, delay=3] runnables[9]: SynchronizedRunnable[counter=2, running=false, delay=3] ########################################## About to execute usingUnfairLock... Results for usingUnfairLock: runnables[0]: LockRunnable[counter=375, running=false, delay=3] runnables[1]: LockRunnable[counter=51, running=false, delay=3] runnables[2]: LockRunnable[counter=1154, running=false, delay=3] runnables[3]: LockRunnable[counter=38, running=false, delay=3] runnables[4]: LockRunnable[counter=1583, running=false, delay=3] runnables[5]: LockRunnable[counter=91, running=false, delay=3] runnables[6]: LockRunnable[counter=1, running=false, delay=3] runnables[7]: LockRunnable[counter=1, running=false, delay=3] runnables[8]: LockRunnable[counter=1, running=false, delay=3] runnables[9]: LockRunnable[counter=1, running=false, delay=3] ########################################## About to execute usingFairLock... Results for usingFairLock: runnables[0]: LockRunnable[counter=328, running=false, delay=3] runnables[1]: LockRunnable[counter=328, running=false, delay=3] runnables[2]: LockRunnable[counter=328, running=false, delay=3] runnables[3]: LockRunnable[counter=328, running=false, delay=3] runnables[4]: LockRunnable[counter=328, running=false, delay=3] runnables[5]: LockRunnable[counter=328, running=false, delay=3] runnables[6]: LockRunnable[counter=328, running=false, delay=3] runnables[7]: LockRunnable[counter=328, running=false, delay=3] runnables[8]: LockRunnable[counter=328, running=false, delay=3] runnables[9]: LockRunnable[counter=328, running=false, delay=3] ##########################################

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn updated LBCORE-97: -------------------------------- Attachment: Suggested_change_of_documentation.patch Quick try at improving documentation of UnsynchronizedAppenderBase.

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- It's definitely related to logging. We haven't replaced logback-classic with slf4j-nop,yet, but we have removed all appenders and the behavior of the app went back to normal. I'm really convinced that the problem described in this issue is the root cause since the problems started when we switched to a multi-core system. Concerning SocketAppender, I'm wondering about the use case where it's showing less than 50 microseconds latency. Are you running it against the loopback device? In our case it's running over a VPN so a certain slowdown is expected. The problem seems to be that: a) some delay is happening, either due to a slow client (SocketAppender will block if the client isn't reading fast enough), network latency, large bursts of log-messages or a combination of all that. b) this delay sends the logged application into "starvation mode" because the critical time, be it 1ms, 3ms or 10ms was reached. It's not acceptable that certain threads are starving because of any of the above. The app, as a whole, may slow down significantly but starvation must not happen. This is a prime-example of starvation where multiple threads are fighting over scarce resources, in this case just one, the appender. To prevent starvation, fairness must be established. Have you had the chance to do benchmarks about the impact of the fair ReentrantLock, yet? If the impact is negligible than this should be changed ASAP. Are we really in disagreement that logging mustn't impact the execution of an application in a way that can result in starvation?

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-97: ----------------------------------

I'm really convinced that the problem described in this issue is the root cause since the problems started when we switched to a multi-core system.

The multi-core system may exhibit a different time-slicing behavior, which does not necessarily implicate logback. There have been many instances where users have blamed log4j/logback for race-conditions or deadlocks in their application. In most, albeit not all cases, the culprit is the application itself, logging merely exposes an existing problem. I am not saying that there is no problem, let us just not jump to conclusions.

Concerning SocketAppender, I'm wondering about the use case where it's showing less than 50 microseconds latency. Are you running it against the loopback device?

No, just sending events to a nearby host via a 100Mb Ethernet connection. The records show an average latency of 42 microseconds. However, these records are somewhat old and the current figures may be higher (or lower).

This is a prime-example of starvation where multiple threads are fighting over scarce resources, in this case just one, the appender. To prevent starvation, fairness must be established.

You are assuming that starvation is caused by lack of fairness. It may also be caused becasue the shared resource is slow. Could it be that the VPN is the culprit?

Have you had the chance to do benchmarks about the impact of the fair ReentrantLock, yet? If the impact is negligible than this should be changed ASAP.

No I have not done any benchmarks about the impact of the fair ReentrantLock. However, I am still not convinced that the problem is related to the fairness of the appender lock. Have you tried applying your patch in production? And if you have, what have you observed? As far as I understood, thus far, disabling SocketAppender as well as other appenders, has improved your application's performance but this does not necessarily mean that the problem is related to fair time slicing. In this regards, Dave's last comment in my blog regarding the difference between spinning and blocking is quite informative. Let me remind you that lock fairness issue is not related to JDK 1.6. It was present in older JVMs as well. Anyway, I understand that you are under pressure to resolve this issue.

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-97: ----------------------------------

As I said before, this does happen with just a simple RollingFileAppender in place, too. This may be caused by some huge debug messages but this shouldn't be able to render the whole application unusable.

Writing a very large log message will obviously take time. Since RollingAppender writes only one message at a time, it is natural for other threads wishing to access RollingAppender to queue, regardless of the fairness policy.

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-97: ------------------------------------- The important point here is that the threads are always running in the same order 3-2-5-4-1 so no thread delays another one. But I'm repeating myself :p

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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn updated LBCORE-97: -------------------------------- Attachment: AppenderBaseLock3.patch - Replacing synchronized with fair ReentrantLock to prevent starvation. - Changing guard into ThreadLocal<Boolean> and checking guard before locking. (LBCORE-99) - Added documentation to UnsynchronizedAppenderBase to encourage the use of fair mechanisms in extending appenders.

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: AppenderBaseLock3.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn updated LBCORE-97: -------------------------------- Attachment: (was: AppenderBaseLock2.patch)

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: AppenderBaseLock3.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn updated LBCORE-97: -------------------------------- Attachment: TimeWasted.java The example we discussed on Skype. My results will be posted in an additional comment.

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: AppenderBaseLock3.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn edited comment on LBCORE-97 at 6/14/09 5:38 AM: -------------------------------------------------------------- Wasted time, taking arbitrary sample: 10ms delay: 9940592000 synchronized 9985104000 unfair lock 282952000 fair lock 1ms delay: 9988193000 synchronized 9974291000 unfair lock 1295582000 fair lock Even more relevant than the total amount of wasted time are the maxWasted values... they illustrate that a big amount of time is spent waiting in starvation instead of performing some work. 1ms delay: 2959018000 synchronized 2078606000 unfair lock 27691000 fair lock 10ms delay: 7592208000 synchronized 9756758000 unfair lock 12816000 fair lock As can be seen, much more actual "work" can be done in case of a fair lock. Work, in this case, would be the added up counter values of all threads. So the penalty of the fair lock isn't relevant anymore since the system, as a whole, is performing much better concerning concurrency. This is, of course, another pretty hardcore example... Nevertheless, it mimics the effect of a slow(ish) appender pretty well, I think/hope. was (Author: jhuxhorn): Wasted time, taking arbitrary sample: 10ms delay: 9940592000 synchronized 9985104000 unfair lock 282952000 fair lock 1ms delay: 9988193000 synchronized 9974291000 unfair lock 1295582000 fair lock As can be seen, much more actual "work" can be done in case of a fair lock. Work, in this case, would be the added up counter values. So the penalty of the fair lock isn't relevant anymore since the system, as a whole, is performing much better concerning concurrency. This is, of course, another pretty hardcore example... Nevertheless, it mimics the effect of a slow(ish) appender pretty well, I think/hope.

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: AppenderBaseLock3.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-97: ---------------------------------- If you run NoLockThroughput found in the ch.qos.logback.core.issue on Sun's JDK 1.6 on Linux. You get: === NoLockThroughput === java.runtime.version = 1.6.0_11-b03 java.vendor = Sun Microsystems Inc. java.version = 1.6.0_11 os.name = Linux os.version = 2.6.25-gentoo-r6 The application never returns. Translation: any single line of code with "for(;;) {}" will bring your application to its knees (on Sun's JDK on a multicore 64 bit Linux). The same test under IBM's JDK 1.6 yields: === NoLockThroughput === java.runtime.version = jvmxa6460-20081105_25433 java.vendor = IBM Corporation java.version = 1.6.0 os.name = Linux os.version = 2.6.25-gentoo-r6 SelectiveLockRunnable NOLOCK count=220890254 SelectiveLockRunnable NOLOCK count=244948022 SelectiveLockRunnable NOLOCK count=312806143 No lock: total of 778644419 operations, or 389322 operations per millisecond Thus, IBMs JDK does reasonable time slicing. Perhaps Sun's does not want Java to run well on 64bit Linux. As for the fair locks, I don't believe its logback's job to fix the JDK.

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: AppenderBaseLock3.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCORE-97?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-97: ---------------------------------- I filed a bug report on this a while ago. It just got accepted the link is: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6855216

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: AppenderBaseLock3.patch, NoLockThroughput.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCLASSIC-140?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu moved LBCORE-97 to LBCLASSIC-140: -------------------------------------------- Project: logback-classic (was: logback-core) Key: LBCLASSIC-140 (was: LBCORE-97)

Starvation on AppenderBase.doAppend -----------------------------------

Key: LBCLASSIC-140 URL: http://jira.qos.ch/browse/LBCLASSIC-140 Project: logback-classic Issue Type: Sub-task Components: Appender Affects Versions: 0.9.15 Reporter: Joern Huxhorn Assignee: Logback dev list Priority: Critical Attachments: AppenderBaseLock3.patch, NoLockThroughput.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCLASSIC-140?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu commented on LBCLASSIC-140: -------------------------------------- Yes, you are right. However, it makes life easier for me (for testing purposes) if the bug is considered to be part of logback-classic

Starvation on AppenderBase.doAppend -----------------------------------

Key: LBCLASSIC-140 URL: http://jira.qos.ch/browse/LBCLASSIC-140 Project: logback-classic Issue Type: Sub-task Components: Appender Affects Versions: 0.9.15 Reporter: Joern Huxhorn Assignee: Logback dev list Priority: Critical Attachments: AppenderBaseLock3.patch, NoLockThroughput.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCLASSIC-140?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu resolved LBCLASSIC-140. ---------------------------------- Fix Version/s: unspecified Resolution: Won't Fix The issue relates to how Sun's JVM does time slicing more than anything else.

Starvation on AppenderBase.doAppend -----------------------------------

Key: LBCLASSIC-140 URL: http://jira.qos.ch/browse/LBCLASSIC-140 Project: logback-classic Issue Type: Sub-task Components: Appender Affects Versions: 0.9.15 Reporter: Joern Huxhorn Assignee: Logback dev list Priority: Critical Fix For: unspecified

Attachments: AppenderBaseLock3.patch, NoLockThroughput.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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

[ http://jira.qos.ch/browse/LBCLASSIC-140?page=com.atlassian.jira.plugin.syste... ] Joern Huxhorn commented on LBCLASSIC-140: ----------------------------------------- Since the behavior of the Sun JVM, while extreme, is correct anyway according to the documentation, I still think that this should be fixed in Logback. I'm not personally involved anymore because I switched my implementation over to UnsynchronizedAppenderBase + fair locks, though. My opinion is that a logging framework simply must not cause such a starvation effect even if will perform slower because of the counter measures. This will get a bigger and bigger problem with increasing amount of CPU cores so I'm pretty sure that this will show up again, anyway.

Starvation on AppenderBase.doAppend -----------------------------------

Key: LBCLASSIC-140 URL: http://jira.qos.ch/browse/LBCLASSIC-140 Project: logback-classic Issue Type: Sub-task Components: Appender Affects Versions: 0.9.15 Reporter: Joern Huxhorn Assignee: Logback dev list Priority: Critical Fix For: unspecified

Attachments: AppenderBaseLock3.patch, NoLockThroughput.patch, SynchronizedVsFairLock.java, TimeWasted.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/ReentrantLo... [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