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

21 Oct 2008

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

    