[logback-dev] synchronization style?

[Ceki Gulcu]

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