svn commit: r1855 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic
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 + } + } + } + // ============================================================ }
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
I increased referencePerf from 500 to 2500 and got the test to pass. I'm not really sure how the appropriate number was determined. Ralph Goers wrote:
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
Ralph Goers wrote:
I increased referencePerf from 500 to 2500 and got the test to pass. I'm not really sure how the appropriate number was determined.
The number was determined on my machine. During the test the number is adjusted according to the performance of the host machine, in this case, your machine. Thus, in principle the tests should pass, unless the machine is heavily used. -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch
I am running Linux in VMWare under Windows. It is a pretty decent laptop, but of course Linux isn't going to get the full machine. I'll try running it on my other Linux machine. Ralph Ceki Gulcu wrote:
Ralph Goers wrote:
I increased referencePerf from 500 to 2500 and got the test to pass. I'm not really sure how the appropriate number was determined.
The number was determined on my machine. During the test the number is adjusted according to the performance of the host machine, in this case, your machine. Thus, in principle the tests should pass, unless the machine is heavily used.
Ralph Goers wrote:
I am running Linux in VMWare under Windows. It is a pretty decent laptop, but of course Linux isn't going to get the full machine.
I'll try running it on my other Linux machine.
On Linux, I also regularly see 'testDurationOfEnabledWithStraightStringParameter' failing with very similar durations, 2600 instead of 550. The 5 fold difference between the actual duration 2600 and the expected 550 duration is very puzzling. I really have no idea why this is happening. -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch
Ralph Goers wrote:
I'm having trouble getting the new version of LoggerPerfTest to pass. I've attached the output of the test.
Ralph
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)
Your tests results show that the code is not contention free, unless you machine is loaded which can alter the test results. -- Ceki Gülcü Logback: The reliable, generic, fast and flexible logging framework for Java. http://logback.qos.ch
participants (3)
-
Ceki Gulcu -
noreply.ceki＠qos.ch -
Ralph Goers