On 02.07.2009, at 19:07, Ceki Gulcu wrote:
Joern Huxhorn wrote:
Ceki Gulcu wrote:
Joern Huxhorn wrote:
Nope, a discussion like that is really necessary because this whole
issue is pretty crucial and will essentially decide how well
Logback
will perform in environments with >1 CPU-cores.
This will become more and more important with more cores added in
every
new CPU generation. The more cores are present, the more relevant
the
issue of unfairness will become, since waiting threads will mean
idling
CPUs.
While open to further investigation and new data, evidence collected
indicates that threads in Sun's JDK on multi-core CPU
on Linux as well as other platforms can make other threads
starve but that is *not* a logback issue. Moreover, it would be
unfair to
penalize *all* logback users using fair locking which is much slower
than synchronization or unfair locks.
I copied your results over from your test for the sake of discussion:
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
Sync: 139698775, or 35 nanos per cycle
Unfair: 87028802, or 57 nanos per cycle
Fair: 4106449, or 1217 nanos per cycle
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
Sync: 356946629, or 14 nanos per cycle
Unfair: 91892449, or 54 nanos per cycle
Fair: 7380308, or 677 nanos per cycle
So yes, the locking itself is significantly slower.
The following numbers are the max amount of wasted time of my
example app:
2959018000 synchronized
2078606000 unfair lock
27691000 fair lock
The maximum wasted time of all threads is ~100 times smaller in
case of
the fair lock!! This means that the overall system is running *waaay*
smoother... regardless of the additional nanos spent for the fair
lock.
The main problem is that *every* CPU has to access the appender,
degrading multi-core-systems to semi-single-core.
Minimizing the amount of time a thread (and therefore one of the
other
cores) has to wait is crucial.
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
"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.
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.
The question is why there is starvation. In a real-world application,
threads will be waiting on several monitors so that the starvation
problem is less likely to occur. In other words, LockingInJava is not
or may not be so a representative of reality.
That's not true, the only monitor that needs to be acquired is the one
on (or inside) the appender.
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.
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.
Regards,
Joern.
_______________________________________________
logback-dev mailing list
logback-dev@qos.ch
http://qos.ch/mailman/listinfo/logback-dev
