[logback-dev] tests and new code

[Ceki Gulcu]

Hello all,

Ralph and I have been working on making the logback code less
susceptible to contention when accessed by multiple threads. These
changes were made in the Logger class and another helper classes.

As a "just-in-case" measure, I almost subconsciously wrote a test to
check the new code did not degrade performance. The test checks that
the amount of time required to process an enabled log statement is
less than a given number of nanoseconds (500 to be exact). The check
attempts to adjust the number to the speed of the host machine. This
test passes flawlessly on my Windows machine, before and after the
changes made in the Logger class.

On the continuous integration machine, which uses a different CPU, a
different OS, and a different JDK, the aforementioned test failed
systematically. However, since other performance related tests failed
from time to time, I was not too bothered. Given that the continuous
integration machine host many other services, and that increases CPU
its clock rate under heavy load and decreases it under light load,
there were many reasons to suspect that test was failing due to
external influences independent of the code being tested.

The differences in performance could hide within Maven, within the JDK
classes, within the JIT compiler and several other places. I have
spent a good part of the last two days hunting down the reasons for
the test's failure.

It turns out that the due to some unknown reason the test is spending
much more time in the CopyOnWriteArrayList.iterator method on Linux
while on Windows hardly any time is spent within this method. (The
CopyOnWriteArrayList.iterator is one of the recent changes made to
reduce resource contention.)

 > cd logback-classic
 > export CLASSPATH=../../logback-core/target/classes/:\
   ../../logback-core/target/test-classes/:\
   ./classes/:./test-classes/:slf4j-api-1.5.6-SNAPSHOT.jar:\
   slf4j-api-1.5.6-SNAPSHOT-tests.jar:junit-4.4.jar

 > java -Xrunhprof:cpu=samples org.junit.runner.JUnitCore \
            ch.qos.logback.classic.LoggerPerfTest

yields (in java.hprof.txt)

CPU SAMPLES BEGIN (total = 500) Thu Oct 23 20:49:32 2008
rank   self  accum   count method
    1 81.60% 81.60%     408 java.util.concurrent.CopyOnWriteArrayList.iterator
    2  1.60% 83.20%       8 ch.qos.logback.classic.Logger.buildLoggingEventAndAppend
    3  1.00% 84.20%       5 org.slf4j.helpers.BogoPerf.bogoInstruction
    4  1.00% 85.20%       5 
ch.qos.logback.classic.spi.TurboFilterAttachableImpl.getTurboFilterChainDecision
    5  0.80% 86.00%       4 java.lang.ClassLoader.defineClass1
    6  0.80% 86.80%       4 org.slf4j.helpers.BogoPerf.bogoInstruction
    7  0.60% 87.40%       3 java.lang.Long.valueOf
    8  0.60% 88.00%       3 ch.qos.logback.classic.Logger.buildLoggingEventAndAppend
    9  0.40% 88.40%       2 org.slf4j.helpers.BogoPerf.computeBogoIPS
   10  0.40% 88.80%       2 
ch.qos.logback.classic.LoggerPerfTest.computeDurationOfDisabledLogWithParameters
   11  0.40% 89.20%       2 
ch.qos.logback.classic.LoggerPerfTest.computeDurationOfDisabledLogWithParameters
   12  0.40% 89.60%       2 java.lang.Long.valueOf
[snip]

The CopyOnWriteArrayList.iterator simply creates a new COWIterator
instance passing it a reference to its internal array. The same test
on Windows shows that hardly no time is spent in CopyOnWriteArrayList.
Apparently creating a COWIterator instance is much slower on Linux
than on Windows.

It looks like the test served its purpose although it is still not
clear why creating a simple object is so much slower on Linux.

Cheers,


-- 
Ceki Gülcü
Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch