I'm having trouble getting the new version of LoggerPerfTest to pass. I've attached the output of the test. Ralph noreply.ceki@qos.ch wrote:
Author: ceki Date: Mon Oct 20 21:57:39 2008 New Revision: 1855
Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java
Log: Related to LBCORE-58
SleepAppender can derive from UnsynchronizedAppenderBase
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 Mon Oct 20 21:57:39 2008 @@ -9,89 +9,111 @@ */ package ch.qos.logback.classic;
+import static org.junit.Assert.assertTrue;
-import java.net.InetAddress; - -import junit.framework.TestCase; - +import org.junit.Before; +import org.junit.Test; import org.slf4j.helpers.BogoPerf;
import ch.qos.logback.classic.spi.LoggingEvent; import ch.qos.logback.classic.turbo.NOPTurboFilter; +import ch.qos.logback.core.UnsynchronizedAppenderBase; import ch.qos.logback.core.appender.NOPAppender;
-public class LoggerPerfTest extends TestCase { - - final static String KAL = "kal"; - String localhostName = null; - static long NORMAL_RUN_LENGTH = 1000*1000; +public class LoggerPerfTest {
+ long NANOS_IN_ONE_SEC = 1000*1000*1000L; + static long NORMAL_RUN_LENGTH = 1000 * 1000; + static long SHORTENED_RUN_LENGTH = 500 * 1000; static long REFERENCE_BIPS = 9324; - + + @Before public void setUp() throws Exception { - localhostName = InetAddress.getLocalHost().getCanonicalHostName(); } - public void testBasic() { - basicDurationInNanos(NORMAL_RUN_LENGTH); - double avg = basicDurationInNanos(NORMAL_RUN_LENGTH); - + + @Test + public void testDurationOfDisabledLogWithStraightStringParameter() { + computeDurationOfDisabledLogWithStraightStringParameter(NORMAL_RUN_LENGTH); + double avg = computeDurationOfDisabledLogWithStraightStringParameter(NORMAL_RUN_LENGTH); + long referencePerf = 17; BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS); - //System.out.println("Average log time for disabled statements: "+avg+" nanos."); - } - - public void testParameterized() { - loopParameterized(NORMAL_RUN_LENGTH); - double avgDuration = loopParameterized(NORMAL_RUN_LENGTH); - long referencePerf = 36; - BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS); - //System.out.println("Average log time for disabled (parameterized) statements: "+avg+" nanos."); } - - - public void testNOPFilter() { - loopNopFilter(NORMAL_RUN_LENGTH); - double avg = loopNopFilter(NORMAL_RUN_LENGTH); - //System.out.println("Average log time for disabled (NOPFilter) statements: "+avg+" nanos."); - long referencePerf = 48; - BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS); - } - - double basicDurationInNanos(long len) { + + double computeDurationOfDisabledLogWithStraightStringParameter(long len) { LoggerContext lc = new LoggerContext(); - NOPAppender<LoggingEvent> mopAppender = new NOPAppender<LoggingEvent>(); - mopAppender.start(); Logger logger = lc.getLogger(this.getClass()); logger.setLevel(Level.OFF); - for(long i = 0; i < len; i++) { + for (long i = 0; i < len; i++) { logger.debug("Toto"); } long start = System.nanoTime(); - for(long i = 0; i < len; i++) { + for (long i = 0; i < len; i++) { logger.debug("Toto"); } long end = System.nanoTime(); - return (end-start)/len; + return (end - start) / len; }
- double loopParameterized(long len) { + @Test + public void testDurationOfDisabledLogWithParameters() { + computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH); + double avgDuration = computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH); + long referencePerf = 36; + BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS); + } + + double computeDurationOfDisabledLogWithParameters(long len) { LoggerContext lc = new LoggerContext(); - NOPAppender<LoggingEvent> mopAppender = new NOPAppender<LoggingEvent>(); - mopAppender.start(); Logger logger = lc.getLogger(this.getClass()); logger.setLevel(Level.OFF); - for(long i = 0; i < len; i++) { + for (long i = 0; i < len; i++) { logger.debug("Toto {}", i); } long start = System.nanoTime(); - for(long i = 0; i < len; i++) { + for (long i = 0; i < len; i++) { logger.debug("Toto {}", i); } long end = System.nanoTime(); - return (end-start)/len; + return (end - start) / len; + } + + @Test + public void testDurationOfEnabledWithStraightStringParameter() { + computeDurationOfEnabledLogWithStraightStringParameter(SHORTENED_RUN_LENGTH); + double avgDuration = computeDurationOfEnabledLogWithStraightStringParameter(SHORTENED_RUN_LENGTH); + long referencePerf = 500; + BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS); + System.out.println("avgDuration="+avgDuration); }
- double loopNopFilter(long len) { + double computeDurationOfEnabledLogWithStraightStringParameter(long len) { + LoggerContext lc = new LoggerContext(); + Logger logger = lc.getLogger(this.getClass()); + logger.setLevel(Level.ALL); + NOPAppender<LoggingEvent> nopAppender = new NOPAppender<LoggingEvent>(); + nopAppender.start(); + logger.addAppender(nopAppender); + for (long i = 0; i < len; i++) { + logger.debug("Toto", i); + } + long start = System.nanoTime(); + for (long i = 0; i < len; i++) { + logger.debug("Toto"); + } + long end = System.nanoTime(); + return (end - start) / len; + } + + @Test + public void testComputeDurationOfDisabledLogsWithNOPFilter() { + computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH); + double avg = computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH); + long referencePerf = 48; + BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS); + } + + double computeDurationOfDisabledLogsWithNOPFilter(long len) { LoggerContext lc = new LoggerContext(); NOPAppender<LoggingEvent> mopAppender = new NOPAppender<LoggingEvent>(); NOPTurboFilter nopFilter = new NOPTurboFilter(); @@ -100,15 +122,92 @@ lc.addTurboFilter(nopFilter); Logger logger = lc.getLogger(this.getClass()); logger.setLevel(Level.OFF); - for(long i = 0; i < len; i++) { + for (long i = 0; i < len; i++) { logger.debug("Toto"); } long start = System.nanoTime(); - for(long i = 0; i < len; i++) { + for (long i = 0; i < len; i++) { logger.debug("Toto"); } long end = System.nanoTime(); - return (end-start)/len; + return (end - start) / len; } - + + @Test + public void testThreadedLogging() throws InterruptedException { + LoggerContext lc = new LoggerContext(); + SleepAppender<LoggingEvent> appender = new SleepAppender<LoggingEvent>(); + + int MILLIS_PER_CALL = 250; + int NANOS_PER_CALL = 250*1000*1000;; + appender.setDuration(MILLIS_PER_CALL); + appender.start(); + Logger logger = lc.getLogger(this.getClass()); + logger.addAppender(appender); + logger.setLevel(Level.DEBUG); + long start; + long end; + int threadCount = 10; + int iterCount = 5; + TestRunner[] threads = new TestRunner[threadCount]; + for (int i = 0; i < threads.length; ++i) { + threads[i] = new TestRunner(logger, iterCount); + } + start = System.nanoTime(); + for (Thread thread : threads) { + thread.start(); + } + for (TestRunner thread : threads) { + thread.join(); + } + end = System.nanoTime(); + double tolerance = threadCount * .125; // Very little thread contention + // should occur in this test. + double max = ((((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount) * tolerance; + double serialized = (((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount + * threadCount; + double actual = ((double) (end - start)) / NANOS_IN_ONE_SEC; + System.out + .printf( + "Sleep duration: %,.4f seconds. Max expected: %,.4f seconds, Serialized: %,.4f\n", + actual, max, serialized); + assertTrue("Exceeded maximum expected time.", actual < max); + } + + // ============================================================ + private static class TestRunner extends Thread { + private Logger logger; + private long len; + + public TestRunner(Logger logger, long len) { + this.logger = logger; + this.len = len; + } + + public void run() { + Thread.yield(); + for (long i = 0; i < len; i++) { + logger.debug("Toto"); + } + } + } + + // ============================================================ + public static class SleepAppender<E> extends UnsynchronizedAppenderBase<E> { + private static long duration = 500; + + public void setDuration(long millis) { + duration = millis; + } + + @Override + protected void append(E eventObject) { + try { + Thread.sleep(duration); + } catch (InterruptedException ie) { + // Ignore + } + } + } + // ============================================================ } _______________________________________________ logback-dev mailing list logback-dev@qos.ch http://qos.ch/mailman/listinfo/logback-dev
------------------------------------------------------------------------------- Test set: ch.qos.logback.classic.LoggerPerfTest ------------------------------------------------------------------------------- Tests run: 5, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 8.095 sec <<< FAILURE! testDurationOfDisabledLogWithStraightStringParameter(ch.qos.logback.classic.LoggerPerfTest) Time elapsed: 0.454 sec testDurationOfDisabledLogWithParameters(ch.qos.logback.classic.LoggerPerfTest) Time elapsed: 0.301 sec testDurationOfEnabledWithStraightStringParameter(ch.qos.logback.classic.LoggerPerfTest) Time elapsed: 5.74 sec <<< FAILURE! junit.framework.AssertionFailedError: current duration 2605.0 exceeded expected 438.08813999999995 (adjusted reference), 500 (raw reference) at org.slf4j.helpers.BogoPerf.assertDuration(BogoPerf.java:92) at ch.qos.logback.classic.LoggerPerfTest.testDurationOfEnabledWithStraightStringParameter(LoggerPerfTest.java:86) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.junit.internal.runners.TestMethod.invoke(TestMethod.java:59) at org.junit.internal.runners.MethodRoadie.runTestMethod(MethodRoadie.java:98) at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:79) at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAfters(MethodRoadie.java:87) at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:77) at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:42) at org.junit.internal.runners.JUnit4ClassRunner.invokeTestMethod(JUnit4ClassRunner.java:88) at org.junit.internal.runners.JUnit4ClassRunner.runMethods(JUnit4ClassRunner.java:51) at org.junit.internal.runners.JUnit4ClassRunner$1.run(JUnit4ClassRunner.java:44) at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:27) at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:37) at org.junit.internal.runners.JUnit4ClassRunner.run(JUnit4ClassRunner.java:42) at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) at org.apache.maven.surefire.Surefire.run(Surefire.java:177) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997) testComputeDurationOfDisabledLogsWithNOPFilter(ch.qos.logback.classic.LoggerPerfTest) Time elapsed: 0.263 sec testThreadedLogging(ch.qos.logback.classic.LoggerPerfTest) Time elapsed: 1.268 sec