LoggerPerfTest.java

/**
 * Logback: the reliable, generic, fast and flexible logging framework.
 * Copyright (C) 1999-2013, QOS.ch. All rights reserved.
 *
 * This program and the accompanying materials are dual-licensed under
 * either the terms of the Eclipse Public License v1.0 as published by
 * the Eclipse Foundation
 *
 *   or (per the licensee's choosing)
 *
 * under the terms of the GNU Lesser General Public License version 2.1
 * as published by the Free Software Foundation.
 */
package ch.qos.logback.classic;

import static junit.framework.Assert.assertTrue;

import ch.qos.logback.core.testUtil.EnvUtilForTests;
import org.junit.Before;
import org.junit.Ignore;
import org.junit.Test;
import org.slf4j.helpers.BogoPerf;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.classic.turbo.NOPTurboFilter;
import ch.qos.logback.core.UnsynchronizedAppenderBase;
import ch.qos.logback.core.helpers.NOPAppender;
import ch.qos.logback.core.util.CoreTestConstants;

@Ignore
public class LoggerPerfTest {

  static final long NANOS_IN_ONE_SEC = 1000 * 1000 * 1000L;
  static long NORMAL_RUN_LENGTH = 1 * 1000 * 1000;
  static long SHORTENED_RUN_LENGTH = 500 * 1000;

  LoggerContext lc = new LoggerContext();
  Logger lbLogger = lc.getLogger(this.getClass());
  org.slf4j.Logger logger = lbLogger;

  @Before
  public void setUp() throws Exception {
  }

  // ===========================================================================
  @Test
  public void durationOfDisabledLogsWith_1_NOPFilter() {
    double avg = computeDurationOfDisabledLogsWith_1_NOPFilter(1,
            NORMAL_RUN_LENGTH);
    System.out.println("durationOfDisabledLogsWith_1_NOPFilter=" + avg);
    long referencePerf = 60;

    BogoPerf.assertDuration(avg, referencePerf, CoreTestConstants.REFERENCE_BIPS);
  }

  double computeDurationOfDisabledLogsWith_1_NOPFilter(int numOfFilters,
                                                       long len) {
    for (int i = 0; i < numOfFilters; i++) {
      lc.addTurboFilter(new NOPTurboFilter());
    }
    lbLogger.setLevel(Level.OFF);
    for (long i = 0; i < len; i++)
      logger.debug("Toto");

    long start = System.nanoTime();
    for (long i = 0; i < len; i++)
      logger.debug("Toto");

    return (System.nanoTime() - start) / len;
  }

  // ===========================================================================
  @Test
  public void durationOfIsDebugEnabled() {
    double avg = computedurationOfIsDebugEnabled(10 * NORMAL_RUN_LENGTH);
    System.out.println("durationOfIsDebugEnabled=" + avg);

    long referencePerf = 15;
    BogoPerf.assertDuration(avg, referencePerf, CoreTestConstants.REFERENCE_BIPS);
  }

  double computedurationOfIsDebugEnabled(final long len) {
    lbLogger.setLevel(Level.OFF);
    for (long i = 0; i < len; i++)
      logger.isDebugEnabled();
    Thread.yield();
    for (long i = 0; i < len; i++)
      logger.isDebugEnabled();

    long start = System.nanoTime();
    for (long i = 0; i < len; i++)
      logger.isDebugEnabled();
    return (System.nanoTime() - start) / len;
  }

  // ===========================================================================
  @Test
  public void durationOfDisabledLog_NoParameters() {
    double avg = computeDurationOfDisabledLog_NoParameters(10 * NORMAL_RUN_LENGTH);
    System.out.println("durationOfDisabledLog_NoParameters=" + avg);

    long referencePerf = 18;
    BogoPerf.assertDuration(avg, referencePerf, CoreTestConstants.REFERENCE_BIPS);
  }

  double computeDurationOfDisabledLog_NoParameters(final long len) {
    lbLogger.setLevel(Level.OFF);
    for (long i = 0; i < len; i++)
      logger.debug("Toto");
    Thread.yield();
    for (long i = 0; i < len; i++)
      logger.debug("Toto");
    Thread.yield();

    long start = System.nanoTime();
    for (long i = 0; i < len; i++)
      logger.debug("Toto");
    return (System.nanoTime() - start) / len;
  }

  // ===========================================================================

  @Test
  public void durationOfDisabledLog_1_Parameter() {
    double avgDuration = computeDurationOfDisabledLog_1_Parameter(NORMAL_RUN_LENGTH);
    System.out.println("durationOfDisabledLog_1_Parameter=" + avgDuration);

    long referencePerf = 30;
    BogoPerf.assertDuration(avgDuration, referencePerf,
            CoreTestConstants.REFERENCE_BIPS);
  }

  double computeDurationOfDisabledLog_1_Parameter(long len) {
    lbLogger.setLevel(Level.OFF);
    final Object o = new Object();
    for (long i = 0; i < len; i++)
      logger.debug("Toto {}", o);

    long start = System.nanoTime();
    for (long i = 0; i < len; i++)
      logger.debug("Toto {}", o);

    long end = System.nanoTime();
    return (end - start) / len;
  }

  // ===========================================================================

  @Test
  public void durationOfEnabledLog() {
    if (EnvUtilForTests.isLinux()) {
      // the JIT on Linux behaves very differently
      return;
    }
    double avgDuration = computeDurationOfEnabledLog(SHORTENED_RUN_LENGTH);
    System.out.println("durationOfEnabledLog=" + avgDuration);

    long referencePerf = 800;
    BogoPerf.assertDuration(avgDuration, referencePerf,
            CoreTestConstants.REFERENCE_BIPS);
  }

  double computeDurationOfEnabledLog(long len) {
    lbLogger.setLevel(Level.ALL);

    NOPAppender<ILoggingEvent> nopAppender = new NOPAppender<ILoggingEvent>();
    nopAppender.start();
    ((ch.qos.logback.classic.Logger) logger).addAppender(nopAppender);
    for (long i = 0; i < len; i++) {
      logger.debug("Toto");
    }
    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 testThreadedLogging() throws InterruptedException {
    SleepAppender<ILoggingEvent> appender = new SleepAppender<ILoggingEvent>();

    int MILLIS_PER_CALL = 250;
    int NANOS_PER_CALL = 250 * 1000 * 1000;

    appender.setDuration(MILLIS_PER_CALL);
    appender.start();

    lbLogger.addAppender(appender);
    lbLogger.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 org.slf4j.Logger logger;
    private long len;

    public TestRunner(org.slf4j.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
      }
    }
  }
  // ============================================================
}