[logback-dev] synchronization style?

[Joern Huxhorn]

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.