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

Ralph Goers ralph.goers at dslextreme.com
Tue Oct 21 01:07:21 CEST 2008


I'm having trouble getting the new version of LoggerPerfTest to pass.  
I've attached the output of the test.

Ralph

noreply.ceki at 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 at qos.ch
> http://qos.ch/mailman/listinfo/logback-dev
>   
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: ch.qos.logback.classic.LoggerPerfTest.txt
Url: http://qos.ch/pipermail/logback-dev/attachments/20081020/ab2e5340/attachment-0001.txt 


More information about the logback-dev mailing list