[logback-dev] svn commit: r1855 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic

noreply.ceki at qos.ch noreply.ceki at qos.ch
Mon Oct 20 21:57:39 CEST 2008


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
+      }
+    }
+  }
+  // ============================================================
 }


More information about the logback-dev mailing list