Author: ceki Date: Thu Oct 30 22:52:20 2008 New Revision: 1923 Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEventWithParametersBuilder.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/TrivialLoggingEventBuilder.java - copied, changed from r1920, /logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEventBuilder.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/LoggingEventSerializationPerfTest.java Removed: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEventBuilder.java Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/NOPOutputStream.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SerializationPerfsTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PackageTest.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/CoreConstants.java logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java Log: - Moved RESET_FREQUENCY from SocketAppender to CoreConstants - added a performance test on LoggingEvent serialization Modified: logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java ============================================================================== --- logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java (original) +++ logback/trunk/logback-classic/src/main/java/ch/qos/logback/classic/spi/LoggingEvent.java Thu Oct 30 22:52:20 2008 @@ -73,6 +73,10 @@ private transient Level level; private String message; + + // we gain significant space at serialization time by marking + // formattedMessage as transient and constructing it lazily in + // getFormmatedMessage() private transient String formattedMessage; private transient Object[] argumentArray; 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 Thu Oct 30 22:52:20 2008 @@ -17,6 +17,7 @@ import ch.qos.logback.classic.spi.LoggingEvent; import ch.qos.logback.classic.turbo.NOPTurboFilter; +import ch.qos.logback.core.CoreConstants; import ch.qos.logback.core.UnsynchronizedAppenderBase; import ch.qos.logback.core.appender.NOPAppender; import ch.qos.logback.core.testUtil.Env; @@ -26,8 +27,8 @@ 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 = 9000; - + + @Before public void setUp() throws Exception { } @@ -38,7 +39,7 @@ double avg = computeDurationOfDisabledLogWithStraightStringParameter(NORMAL_RUN_LENGTH); long referencePerf = 17; - BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS); + BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS); } double computeDurationOfDisabledLogWithStraightStringParameter(long len) { @@ -61,7 +62,7 @@ computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH); double avgDuration = computeDurationOfDisabledLogWithParameters(NORMAL_RUN_LENGTH); long referencePerf = 36; - BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS); + BogoPerf.assertDuration(avgDuration, referencePerf, CoreConstants.REFERENCE_BIPS); } double computeDurationOfDisabledLogWithParameters(long len) { @@ -88,7 +89,7 @@ computeDurationOfEnabledLog(SHORTENED_RUN_LENGTH); double avgDuration = computeDurationOfEnabledLog(SHORTENED_RUN_LENGTH); long referencePerf = 500; - BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS); + BogoPerf.assertDuration(avgDuration, referencePerf, CoreConstants.REFERENCE_BIPS); } double computeDurationOfEnabledLog(long len) { @@ -114,7 +115,7 @@ computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH); double avg = computeDurationOfDisabledLogsWithNOPFilter(NORMAL_RUN_LENGTH); long referencePerf = 48; - BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS); + BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS); } double computeDurationOfDisabledLogsWithNOPFilter(long len) { Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/NOPOutputStream.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/NOPOutputStream.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/NOPOutputStream.java Thu Oct 30 22:52:20 2008 @@ -15,10 +15,25 @@ public class NOPOutputStream extends OutputStream { + long count; + @Override public void write(int b) throws IOException { + count++; // do nothing + } + + public long getCount() { + return count; + } + + public long size() { + return count; + } + + public void reset() { + count = 0; } } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SerializationPerfsTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SerializationPerfsTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SerializationPerfsTest.java Thu Oct 30 22:52:20 2008 @@ -6,7 +6,7 @@ import junit.framework.TestCase; import ch.qos.logback.classic.net.testObjectBuilders.Builder; -import ch.qos.logback.classic.net.testObjectBuilders.LoggingEventBuilder; +import ch.qos.logback.classic.net.testObjectBuilders.TrivialLoggingEventBuilder; import ch.qos.logback.classic.net.testObjectBuilders.MinimalSerBuilder; public class SerializationPerfsTest extends TestCase { @@ -181,7 +181,7 @@ // } public void testWithSerialization() throws Exception { - Builder builder = new LoggingEventBuilder(); + Builder builder = new TrivialLoggingEventBuilder(); runPerfTest(builder, "LoggingEvent object serialization"); } } Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEventWithParametersBuilder.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEventWithParametersBuilder.java Thu Oct 30 22:52:20 2008 @@ -0,0 +1,48 @@ +/** + * Logback: the generic, reliable, fast and flexible logging framework. + * + * Copyright (C) 2000-2008, QOS.ch + * + * This library is free software, you can redistribute it and/or modify it under + * the terms of the GNU Lesser General Public License as published by the Free + * Software Foundation. + */ +package ch.qos.logback.classic.net.testObjectBuilders; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.LoggingEvent; + +public class LoggingEventWithParametersBuilder implements Builder { + + final String MSG = "aaaaabbbbbcccc {} cdddddaaaaabbbbbcccccdddddaaaa {}"; + + private Logger logger = new LoggerContext() + .getLogger(LoggerContext.ROOT_NAME); + + public Object build(int i) { + + LoggingEvent le = new LoggingEvent(); + le.setTimeStamp(System.currentTimeMillis()); + + Object[] aa = new Object[] { i, "HELLO WORLD [========== ]" + i }; + + le.setArgumentArray(aa); + String msg = MSG + i; + le.setMessage(msg); + + // compute formatted message + // this forces le.formmatedMessage to be set (this is the whole point of the + // exercise) + le.getFormattedMessage(); + le.setLevel(Level.DEBUG); + le.setLoggerRemoteView(logger.getLoggerRemoteView()); + le.setThreadName("threadName"); + + if (i == 2) { + System.out.println(le.getFormattedMessage()); + } + return le; + } +} Copied: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/TrivialLoggingEventBuilder.java (from r1920, /logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEventBuilder.java) ============================================================================== --- /logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEventBuilder.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/TrivialLoggingEventBuilder.java Thu Oct 30 22:52:20 2008 @@ -14,16 +14,16 @@ import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.spi.LoggingEvent; -public class LoggingEventBuilder implements Builder { +public class TrivialLoggingEventBuilder implements Builder { private Logger logger = new LoggerContext() .getLogger(LoggerContext.ROOT_NAME); public Object build(int i) { LoggingEvent le = new LoggingEvent(); + le.setTimeStamp(System.currentTimeMillis()); le.setLevel(Level.DEBUG); le.setLoggerRemoteView(logger.getLoggerRemoteView()); - // le.setLogger(new LoggerContext().getLogger(LoggerContext.ROOT_NAME)); le.setMessage(MSG_PREFIX); le.setThreadName("threadName"); return le; Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/LoggingEventSerializationPerfTest.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/LoggingEventSerializationPerfTest.java Thu Oct 30 22:52:20 2008 @@ -0,0 +1,96 @@ +package ch.qos.logback.classic.spi; + +import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; + +import java.io.IOException; +import java.io.ObjectOutputStream; + +import org.junit.After; +import org.junit.Before; +import org.junit.Test; +import org.slf4j.helpers.BogoPerf; + +import ch.qos.logback.classic.net.NOPOutputStream; +import ch.qos.logback.classic.net.testObjectBuilders.Builder; +import ch.qos.logback.classic.net.testObjectBuilders.LoggingEventWithParametersBuilder; +import ch.qos.logback.classic.net.testObjectBuilders.TrivialLoggingEventBuilder; +import ch.qos.logback.core.CoreConstants; + +public class LoggingEventSerializationPerfTest { + + static int LOOP_LEN = 10 * 1000; + + NOPOutputStream noos = new NOPOutputStream(); + ObjectOutputStream oos; + + @Before + public void setUp() throws Exception { + oos = new ObjectOutputStream(noos); + + } + + @After + public void tearDown() throws Exception { + } + + double doLoop(Builder builder, int loopLen) { + long start = System.nanoTime(); + int resetCounter = 0; + for (int i = 0; i < loopLen; i++) { + try { + oos.writeObject(builder.build(i)); + oos.flush(); + if (++resetCounter >= CoreConstants.OOS_RESET_FREQUENCY) { + oos.reset(); + resetCounter = 0; + } + + } catch (IOException ex) { + fail(ex.getMessage()); + } + } + long end = System.nanoTime(); + return (end - start) / (1.0d * loopLen); + } + + @Test + public void testPerformance() { + TrivialLoggingEventBuilder builder = new TrivialLoggingEventBuilder(); + + doLoop(builder, LOOP_LEN); + noos.reset(); + double avg = doLoop(builder, LOOP_LEN); + + + long actualSize = (long) (noos.size()/(1024*1.1d)); + double baosSizeLimit = 500; + + assertTrue("baos size" + actualSize + " should be less than " + + baosSizeLimit, baosSizeLimit > actualSize); + + // the reference was computed on Orion (Ceki's computer) + long referencePerf = 5000; + BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS); + } + + + @Test + public void testPerformanceWithParameters() { + LoggingEventWithParametersBuilder builder = new LoggingEventWithParametersBuilder(); + + doLoop(builder, LOOP_LEN); + noos.reset(); + double avg = doLoop(builder, LOOP_LEN); + + long actualSize = (long) (noos.size()/(1024*1.1d)); + + double baosSizeLimit = 1300; + assertTrue("actualSize " + actualSize + " should be less than " + + baosSizeLimit, baosSizeLimit > actualSize); + + // the reference was computed on Orion (Ceki's computer) + long referencePerf = 7000; + BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS); + } +} Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PackageTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PackageTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/spi/PackageTest.java Thu Oct 30 22:52:20 2008 @@ -1,11 +1,11 @@ /** - * LOGBack: the reliable, fast and flexible logging library for Java. - * - * Copyright (C) 1999-2006, QOS.ch - * - * This library is free software, you can redistribute it and/or - * modify it under the terms of the GNU Lesser General Public License as - * published by the Free Software Foundation. + * Logback: the generic, reliable, fast and flexible logging framework. + * + * Copyright (C) 2000-2008, QOS.ch + * + * This library is free software, you can redistribute it and/or modify it under + * the terms of the GNU Lesser General Public License as published by the Free + * Software Foundation. */ package ch.qos.logback.classic.spi; @@ -23,8 +23,9 @@ suite.addTestSuite(CallerDataTest.class); suite.addTest(new JUnit4TestAdapter (LoggerComparatorTest.class)); suite.addTest(new JUnit4TestAdapter (LoggingEventSerializationTest.class)); - suite.addTest(new JUnit4TestAdapter(ch.qos.logback.classic.spi.ThrowableToDataPointTest.class)); - suite.addTest(new JUnit4TestAdapter(ch.qos.logback.classic.spi.BasicCPDCTest.class)); + suite.addTest(new JUnit4TestAdapter(LoggingEventSerializationPerfTest.class)); + suite.addTest(new JUnit4TestAdapter(ThrowableToDataPointTest.class)); + suite.addTest(new JUnit4TestAdapter(BasicCPDCTest.class)); return suite; } } \ No newline at end of file Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/CoreConstants.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/CoreConstants.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/CoreConstants.java Thu Oct 30 22:52:20 2008 @@ -63,5 +63,16 @@ * we close the table and create a new one */ public static final int TABLE_ROW_LIMIT = 10000; + + + // reset the ObjectOutputStream every 70 calls + // this avoid serious memory leaks + public static final int OOS_RESET_FREQUENCY = 70; + + /** + * The reference bogo instructions per second on + * Ceki's machine (Orion) + */ + public static long REFERENCE_BIPS = 9000; } Modified: logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java ============================================================================== --- logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java (original) +++ logback/trunk/logback-core/src/main/java/ch/qos/logback/core/net/SocketAppenderBase.java Thu Oct 30 22:52:20 2008 @@ -17,6 +17,7 @@ import java.net.Socket; import ch.qos.logback.core.AppenderBase; +import ch.qos.logback.core.CoreConstants; /** * @@ -53,16 +54,6 @@ protected int counter = 0; - // reset the ObjectOutputStream every 70 calls - private static final int RESET_FREQUENCY = 70; - - // /** - // * Connect to the specified <b>RemoteHost</b> and <b>Port</b>. - // */ - // public void activateOptions() { - // connect(address, port); - // } - /** * Start this appender. */ @@ -163,7 +154,7 @@ oos.writeObject(event); // addInfo("=========Flushing."); oos.flush(); - if (++counter >= RESET_FREQUENCY) { + if (++counter >= CoreConstants.OOS_RESET_FREQUENCY) { counter = 0; // Failing to reset the object output stream every now and // then creates a serious memory leak.