svn commit: r1867 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic
Author: ceki Date: Thu Oct 23 20:45:29 2008 New Revision: 1867 Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java Log: tweaking Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java Thu Oct 23 20:45:29 2008 @@ -19,14 +19,13 @@ import ch.qos.logback.classic.turbo.NOPTurboFilter; import ch.qos.logback.core.UnsynchronizedAppenderBase; import ch.qos.logback.core.appender.NOPAppender; -import ch.qos.logback.core.util.StatusPrinter; public class LoggerPerfTest { long NANOS_IN_ONE_SEC = 1000*1000*1000L; static long NORMAL_RUN_LENGTH = 1000 * 1000; - static long SHORTENED_RUN_LENGTH = 1000 * 1000; - static long REFERENCE_BIPS = 9324; + static long SHORTENED_RUN_LENGTH = 500 * 1000; + static long REFERENCE_BIPS = 9000; @Before public void setUp() throws Exception { @@ -96,15 +95,13 @@ nopAppender.start(); logger.addAppender(nopAppender); for (long i = 0; i < len; i++) { - logger.debug("Toto", i); + logger.debug("Toto"); } long start = System.nanoTime(); for (long i = 0; i < len; i++) { logger.debug("Toto"); } long end = System.nanoTime(); - StatusPrinter.print(lc); - return (end - start) / len; }
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
participants (2)
-
Ceki Gulcu -
noreply.ceki＠qos.ch