[logback-dev] svn commit: r1923 - in logback/trunk: logback-classic/src/main/java/ch/qos/logback/classic/spi logback-classic/src/test/java/ch/qos/logback/classic logback-classic/src/test/java/ch/qos/logback/classic/net logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders logback-classic/src/test/java/ch/qos/logback/classic/spi logback-core/src/main/java/ch/qos/logback/core logback-core/src/main/java/ch/qos/logback/core/net
noreply.ceki at qos.ch
noreply.ceki at qos.ch
Thu Oct 30 22:52:20 CET 2008
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.
More information about the logback-dev
mailing list