Joern Huxhorn wrote:
Joern,
The numbers regarding *wasted* time above do not bring any new information. Assuming there is thread starvation, those starving threads will sit by idly. There is no new information there. It is just stating the obvious.
Even if there is no starvation that completely prevents access of any other threads, there is still an impact of logging on the execution of multiple threads.
Threads are waiting longer than necessary in case of unfair locks. And that's my whole point.
1ms delay: 2959018000 synchronized 2078606000 unfair lock 27691000 fair lock
10ms delay: 7592208000 synchronized 9756758000 unfair lock 12816000 fair lock
With all due respect, as I see things, the figures given by TimeWasted application attached to LBCLASSIC-140 [1] are essentially meaningless because TimeWasted measures the time spent (or wasted) waiting to access a lock. Here is the relevant code code: public static class WastedTimeSynchronizedRunnable implements Runnable { public void run() { for(;;) { ... long wasted=System.nanoTime(); synchronized(lockObject) { counter++; } wasted=System.nanoTime()-wasted; } } } public static class WastedTimeSynchronizedRunnable implements Runnable { public void run() for(;;) { ... omitted code lock.lock(); try { counter++; } finally { lock.unlock(); } wasted=System.nanoTime()-wasted; } } } We all agree that when a single thread grabs the CPU while others threads starve, the other threads get nothing or very little done, but that is just the definition of thread starvation. Zero surprise = zero new information. [1] http://jira.qos.ch/browse/LBCLASSIC-140
"Wasted time" means that a processor core isn't working. The higher this value is the less optimal an application is scaling on n-core-systems. And this is *only* caused by unfair locking of the logging system. I'm honestly baffled that nobody else seems to care.
I estimate that I've already spent over 3 man days on this question. I would not have spent this time if I did not care. Other participants also seem quite interested, some of them might even silently agree with you. :-)
Beside all that, I have the opinion that logging should happen in the order that an application would like to log.
Thread A tries to log "A". Thread B tries to log "B". Thread C tries to log "C". Thread A tries to log "A2".
Should always log A,B,C,A2 and not A,A2,C,B, which can be the case with unfair locking. I'd consider this a bug.
Come on. You can't just ignore the way the JVM handles time-slicing.
That's not true, the only monitor that needs to be acquired is the one on (or inside) the appender.
A real-world application, contrary to the small test applications such as TimeWasted, SynchronizedVsFairLock and others, is likely to have dependencies on resources other than logging, e.g. a data base, network connection etc. Thus, under "normal" conditions, thread starvation is much less likely to occur. The thread hogging a logging-related lock is eventually bound to wait on another resource in which time the threads waiting to obtain the logging-related lock will be able to obtain it. BTW, invoking Thread.yield() is another way to force a thread to let other threads run. All I am saying is that a "normal" application will have these Thread.yield() points naturally and transparently on its execution path.
As a side note, and if my memory serves me well, you gather caller data for every log call which can have significant impact on performance. Are you collecting caller data?
Yes, I do, but performance was absolutely sufficient on a single-core system - which is quite ironic. Let's just forget about my appender for the moment. The behavior is similar but less dramatic in case of FileAppender.
Interesting. Could you post your config file? When you say less dramatic, do you mean the behavior of your application in production? I guess it could be infeasible to try running your application with IBM's JDK on your 4-core Solaris machine.
I have the exact same issue with the Apple implementation of Java which, sadly, isn't a real Sun JVM. I can't post the config right now but it's seriously unspectacular. Nothing special in there.
What is unspectacular? The way the JVM distributes the lock among competing threads?
Collecting caller data might just cause waiting threads to be parked at the kernel instead of spun.
Regardless of the cause, either collecting the caller data or not, such a behavior simply mustn't happen in my books.
I am trying to solve this issue the best I can. Insisting on fair locks without exploring alternatives will not get us very far. Given that collecting caller data is pretty expensive, it might influence the way the JVM treats threads waiting for a lock (spinning vs parking) which mat be the cause behind the starvation effects you are seeing. Could you please try to set up logging without CallerData in your application and see what happens? While I agree with you that the logging framework should not have undesired side-effects such as thread starvation, a java logging framework is bound by the limitations of the JVM under which it is executing. It's *not* logback's responsibility to fix the host JVM. Also note that Sun excepted my bug report on this issue. See http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6855216 Your request for fair locking in appenders is not unreasonable. However, it will cause a measurable slow down in a large number of cases. It also feels like fixing the JVM. So, I need more evidence before going down the path of fair locking. Best regards,
Regards, Joern.
-- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch