August 2008 - logback-dev - mailman3.qos.ch

svn commit: r1730 - logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net
by noreply.ceki＠qos.ch 04 Aug '08

04 Aug '08

Author: ceki Date: Mon Aug 4 22:49:22 2008 New Revision: 1730 Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java Log: test now wait for the SimpleSocketServer to send a notification Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/SocketAppenderTest.java Mon Aug 4 22:49:22 2008 @@ -9,12 +9,10 @@ */ package ch.qos.logback.classic.net; - import static org.junit.Assert.*; import java.util.Map; - import org.junit.Test; import org.slf4j.MDC; import org.slf4j.Marker; @@ -29,17 +27,20 @@ import ch.qos.logback.core.read.ListAppender; import ch.qos.logback.core.util.StatusPrinter; -public class SocketAppenderTest { +public class SocketAppenderTest { static final String LIST_APPENDER_NAME = "la"; + static final int JOIN__OR_WAIT_TIMEOUT = 200; + static final int SLEEP_AFTER_LOG = 100; + int port = 4561; LoggerContext lc = new LoggerContext(); LoggerContext serverLC = new LoggerContext(); ListAppender<LoggingEvent> la = new ListAppender<LoggingEvent>(); SocketAppender socketAppender = new SocketAppender(); - + private SimpleSocketServer simpleSocketServer; - + @Test public void startFailNoRemoteHost() { SocketAppender appender = new SocketAppender(); @@ -52,17 +53,16 @@ @Test public void recieveMessage() throws InterruptedException { fireServer(); + waitForServerToStart(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); logger.debug("test msg"); - - Thread.sleep(100); - - // Wait max 2 seconds for mock server to finish. However, it should - // finish much sooner than that. + + Thread.sleep(SLEEP_AFTER_LOG); + simpleSocketServer.close(); - simpleSocketServer.join(2000); + simpleSocketServer.join(JOIN__OR_WAIT_TIMEOUT); assertTrue(simpleSocketServer.isClosed()); assertEquals(1, la.list.size()); @@ -74,16 +74,15 @@ @Test public void recieveWithContext() throws InterruptedException { fireServer(); + waitForServerToStart(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); logger.debug("test msg"); + Thread.sleep(SLEEP_AFTER_LOG); - // Wait max 2 seconds for mock server to finish. However, it should - // finish much sooner than that. - Thread.sleep(100); simpleSocketServer.close(); - simpleSocketServer.join(2000); + simpleSocketServer.join(JOIN__OR_WAIT_TIMEOUT); assertTrue(simpleSocketServer.isClosed()); assertEquals(1, la.list.size()); @@ -104,6 +103,7 @@ @Test public void messageWithMDC() throws InterruptedException { fireServer(); + waitForServerToStart(); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); @@ -111,11 +111,9 @@ MDC.put("key", "testValue"); logger.debug("test msg"); - // Wait max 2 seconds for mock server to finish. However, it should - // finish much sooner than that. - Thread.sleep(100); + Thread.sleep(SLEEP_AFTER_LOG); simpleSocketServer.close(); - simpleSocketServer.join(2000); + simpleSocketServer.join(JOIN__OR_WAIT_TIMEOUT); assertTrue(simpleSocketServer.isClosed()); ListAppender<LoggingEvent> la = getListAppender(); assertEquals(1, la.list.size()); @@ -124,23 +122,23 @@ Map<String, String> MDCPropertyMap = remoteEvent.getMDCPropertyMap(); assertEquals("testValue", MDCPropertyMap.get("key")); } - + @Test public void messageWithMarker() throws InterruptedException { fireServer(); + waitForServerToStart(); + + //Thread.sleep(SLEEP_AFTER_SERVER_START); configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); - + Marker marker = MarkerFactory.getMarker("testMarker"); logger.debug(marker, "test msg"); + Thread.sleep(SLEEP_AFTER_LOG); - Thread.sleep(100); - - // Wait max 2 seconds for mock server to finish. However, it should - // finish much sooner than that. simpleSocketServer.close(); - simpleSocketServer.join(2000); + simpleSocketServer.join(JOIN__OR_WAIT_TIMEOUT); assertTrue(simpleSocketServer.isClosed()); assertEquals(1, la.list.size()); @@ -151,6 +149,8 @@ @Test public void messageWithUpdatedMDC() throws InterruptedException { fireServer(); + waitForServerToStart(); + configureClient(); Logger logger = lc.getLogger(LoggerContext.ROOT_NAME); @@ -160,16 +160,13 @@ MDC.put("key", "updatedTestValue"); logger.debug("test msg 2"); + Thread.sleep(SLEEP_AFTER_LOG); - Thread.sleep(100); - - // Wait max 2 seconds for mock server to finish. However, it should - // finish much sooner than that. simpleSocketServer.close(); - simpleSocketServer.join(2000); + simpleSocketServer.join(JOIN__OR_WAIT_TIMEOUT); assertTrue(simpleSocketServer.isClosed()); ListAppender<LoggingEvent> la = getListAppender(); - + assertEquals(2, la.list.size()); // We observe the second logging event. It should provide us with @@ -187,16 +184,12 @@ logger.debug("test msg"); fireServer(); - synchronized (simpleSocketServer) { - simpleSocketServer.wait(1000); - } - Thread.yield(); // give the server a little more time - Thread.yield(); + waitForServerToStart(); logger.debug("test msg 2"); - Thread.yield(); // give the server a little more time + Thread.sleep(SLEEP_AFTER_LOG); simpleSocketServer.close(); - simpleSocketServer.join(2000); + simpleSocketServer.join(JOIN__OR_WAIT_TIMEOUT); StatusPrinter.print(lc); assertTrue(simpleSocketServer.isClosed()); assertEquals(1, la.list.size()); @@ -205,7 +198,13 @@ assertEquals("test msg 2", remoteEvent.getMessage()); assertEquals(Level.DEBUG, remoteEvent.getLevel()); } - + + private void waitForServerToStart() throws InterruptedException { + synchronized (simpleSocketServer) { + simpleSocketServer.wait(JOIN__OR_WAIT_TIMEOUT); + } + } + private void fireServer() throws InterruptedException { Logger root = serverLC.getLogger("root"); la.setName(LIST_APPENDER_NAME); @@ -217,12 +216,11 @@ Thread.yield(); } - ListAppender<LoggingEvent> getListAppender() { Logger root = serverLC.getLogger("root"); return (ListAppender<LoggingEvent>) root.getAppender(LIST_APPENDER_NAME); } - + private void configureClient() { lc = new LoggerContext(); lc.setName("test");

1 0

svn commit: r1729 - in logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic: . util
by noreply.ceki＠qos.ch 04 Aug '08

04 Aug '08

Author: ceki Date: Mon Aug 4 22:15:53 2008 New Revision: 1729 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/util/BogoPerf.java Log: - adjust numbers according to the performance of the host CPU 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 Aug 4 22:15:53 2008 @@ -24,25 +24,25 @@ String localhostName = null; static long NORMAL_RUN_LENGTH = 1000*1000; - static long REFERENCE_BIPS = 10000; + static long REFERENCE_BIPS = 9324; public void setUp() throws Exception { localhostName = InetAddress.getLocalHost().getCanonicalHostName(); } public void testBasic() { - loopBasic(NORMAL_RUN_LENGTH); - double avg = loopBasic(NORMAL_RUN_LENGTH); + basicDurationInNanos(NORMAL_RUN_LENGTH); + double avg = basicDurationInNanos(NORMAL_RUN_LENGTH); long referencePerf = 17; - BogoPerf.assertPerformance(avg, referencePerf, REFERENCE_BIPS); + BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS); //System.out.println("Average log time for disabled statements: "+avg+" nanos."); } public void testParameterized() { - loopBasic(NORMAL_RUN_LENGTH); - double avg = loopParameterized(NORMAL_RUN_LENGTH); + basicDurationInNanos(NORMAL_RUN_LENGTH); + double avgDuration = loopParameterized(NORMAL_RUN_LENGTH); long referencePerf = 36; - BogoPerf.assertPerformance(avg, referencePerf, REFERENCE_BIPS); + BogoPerf.assertDuration(avgDuration, referencePerf, REFERENCE_BIPS); //System.out.println("Average log time for disabled (parameterized) statements: "+avg+" nanos."); } @@ -52,10 +52,10 @@ double avg = loopNopFilter(NORMAL_RUN_LENGTH); //System.out.println("Average log time for disabled (NOPFilter) statements: "+avg+" nanos."); long referencePerf = 48; - BogoPerf.assertPerformance(avg, referencePerf, REFERENCE_BIPS); + BogoPerf.assertDuration(avg, referencePerf, REFERENCE_BIPS); } - double loopBasic(long len) { + double basicDurationInNanos(long len) { LoggerContext lc = new LoggerContext(); NOPAppender<LoggingEvent> mopAppender = new NOPAppender<LoggingEvent>(); mopAppender.start(); Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/util/BogoPerf.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/util/BogoPerf.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/util/BogoPerf.java Mon Aug 4 22:15:53 2008 @@ -19,7 +19,7 @@ } /** - * compute bogoInstructions per second + * Compute bogoInstructions per second * * on a 3.2 Ghz Pentium D CPU (around 2007), we obtain about 10'000 bogoIPS. * @@ -69,20 +69,54 @@ return (2 * lastBogos + INITIAL_BOGO_IPS) / 3; } + /** + * Assertion used for values that decrease with faster CPUs, + * typically the time (duration) needed to perform a task. + * + * @param currentDuration + * @param referenceDuraion + * @param referenceBIPS + * @throws AssertionFailedError + */ + public static void assertDuration(double currentDuration, + long referenceDuraion, double referenceBIPS) + throws AssertionFailedError { + double ajustedDuration = adjustExpectedDuration(referenceDuraion, + referenceBIPS); + if (currentDuration > ajustedDuration * SLACK) { + throw new AssertionFailedError(currentDuration + " exceeded expected " + + ajustedDuration + " (adjusted), " + referenceDuraion + " (raw)"); + } + } + /** + * Assertion used for values that increase with faster CPUs, typically + * the number of operations accomplished per unit of time. + * + * @param currentPerformance + * @param referencePerformance + * @param referenceBIPS + * @throws AssertionFailedError + */ public static void assertPerformance(double currentPerformance, - long referencePerf, double referenceBIPS) + long referencePerformance, double referenceBIPS) throws AssertionFailedError { - double ajustedPerf = adjustExpectedValue(referencePerf, + double ajustedPerf = adjustExpectedPerformance(referencePerformance, referenceBIPS); - if (currentPerformance > ajustedPerf * SLACK) { - throw new AssertionFailedError(currentPerformance + " exceeded expected " - + ajustedPerf + " (adjusted), " + referencePerf + " (raw)"); + if (currentPerformance*SLACK < ajustedPerf) { + throw new AssertionFailedError(currentPerformance + " below expected " + + ajustedPerf + " (adjusted), " + referencePerformance + " (raw)"); } } - - private static double adjustExpectedValue(long referencePerf, + + private static double adjustExpectedPerformance(long referenceDuration, + double referenceBIPS) { + double currentBIPS = currentBIPS(); + return referenceDuration * (currentBIPS/referenceBIPS); + } + + private static double adjustExpectedDuration(long referenceDuration, double referenceBIPS) { double currentBIPS = currentBIPS(); - return referencePerf * (referenceBIPS / currentBIPS); + return referenceDuration * (referenceBIPS / currentBIPS); } }

1 0

svn commit: r1728 - in logback/trunk/logback-classic: . src/test/java/ch/qos/logback/classic src/test/java/ch/qos/logback/classic/util
by noreply.ceki＠qos.ch 04 Aug '08

04 Aug '08

Author: ceki Date: Mon Aug 4 19:00:40 2008 New Revision: 1728 Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/util/BogoPerf.java Modified: logback/trunk/logback-classic/pom.xml logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/LoggerPerfTest.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java Log: - performance test are not adjusted according to the performance of the host CPU Modified: logback/trunk/logback-classic/pom.xml ============================================================================== --- logback/trunk/logback-classic/pom.xml (original) +++ logback/trunk/logback-classic/pom.xml Mon Aug 4 19:00:40 2008 @@ -140,7 +140,6 @@ <exclude>**/PackageTest.java</exclude> <exclude>**/TestConstants.java</exclude> <exclude>**/SerializationPerfsTest.java</exclude> - <exclude>**/LoggerPerfTest.java</exclude> </excludes> </configuration> </plugin> 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 Aug 4 19:00:40 2008 @@ -15,54 +15,44 @@ import junit.framework.TestCase; import ch.qos.logback.classic.spi.LoggingEvent; import ch.qos.logback.classic.turbo.NOPTurboFilter; +import ch.qos.logback.classic.util.BogoPerf; import ch.qos.logback.core.appender.NOPAppender; public class LoggerPerfTest extends TestCase { final static String KAL = "kal"; String localhostName = null; - static long RUN_LENGTH = 1000*1000*10; + static long NORMAL_RUN_LENGTH = 1000*1000; + + static long REFERENCE_BIPS = 10000; public void setUp() throws Exception { localhostName = InetAddress.getLocalHost().getCanonicalHostName(); } public void testBasic() { - loopBasic(RUN_LENGTH); - double avg = loopBasic(RUN_LENGTH); + loopBasic(NORMAL_RUN_LENGTH); + double avg = loopBasic(NORMAL_RUN_LENGTH); - System.out.println("Running on "+localhostName); - // check for performance on KAL only - if(KAL.equals(localhostName)) { - assertTrue(30 > avg); - } - System.out.println("Average log time for disabled statements: "+avg+" nanos."); + long referencePerf = 17; + BogoPerf.assertPerformance(avg, referencePerf, REFERENCE_BIPS); + //System.out.println("Average log time for disabled statements: "+avg+" nanos."); } public void testParameterized() { - - loopBasic(RUN_LENGTH); - double avg = loopParameterized(RUN_LENGTH); - - System.out.println("Running on "+localhostName); - // check for performance on KAL only - if(KAL.equals(localhostName)) { - assertTrue(30 > avg); - } - System.out.println("Average log time for disabled (parameterized) statements: "+avg+" nanos."); + loopBasic(NORMAL_RUN_LENGTH); + double avg = loopParameterized(NORMAL_RUN_LENGTH); + long referencePerf = 36; + BogoPerf.assertPerformance(avg, referencePerf, REFERENCE_BIPS); + //System.out.println("Average log time for disabled (parameterized) statements: "+avg+" nanos."); } public void testNOPFilter() { - loopNopFilter(RUN_LENGTH); - double avg = loopNopFilter(RUN_LENGTH); - - System.out.println("Running on "+localhostName); - System.out.println("Average log time for disabled (NOPFilter) statements: "+avg+" nanos."); - // check for performance on KAL only - if(KAL.equals(localhostName)) { - assertTrue(80 > avg); - } - + 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.assertPerformance(avg, referencePerf, REFERENCE_BIPS); } double loopBasic(long len) { Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/PackageTest.java Mon Aug 4 19:00:40 2008 @@ -16,6 +16,7 @@ public static Test suite() { TestSuite suite = new TestSuite(); suite.addTestSuite(LoggerContextTest.class); + suite.addTestSuite(LoggerPerfTest.class); suite.addTestSuite(DynamicLoggerContextTest.class); suite.addTestSuite(PatternLayoutTest.class); suite.addTestSuite(BasicLoggerTest.class); Added: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/util/BogoPerf.java ============================================================================== --- (empty file) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/util/BogoPerf.java Mon Aug 4 19:00:40 2008 @@ -0,0 +1,88 @@ +package ch.qos.logback.classic.util; + +import java.util.Arrays; +import java.util.Random; + +import junit.framework.AssertionFailedError; + +public class BogoPerf { + + private static long NANOS_IN_ONE_SECOND = 1000 * 1000 * 1000; + private static int INITIAL_N = 1000; + private static int LAST_N = 100; + private static double INITIAL_BOGO_IPS = computeBogoIPS(INITIAL_N); + + private static int SLACK = 2; + + static { + System.out.println("Host runs at "+INITIAL_BOGO_IPS + " BIPS"); + } + + /** + * compute bogoInstructions per second + * + * on a 3.2 Ghz Pentium D CPU (around 2007), we obtain about 10'000 bogoIPS. + * + * @param N + * number of bogoInstructions to average over in order to + * compute the result + * @return bogo Instructions Per Second + */ + private static double computeBogoIPS(int N) { + long begin = System.nanoTime(); + + for (int i = 0; i < N; i++) { + bogoInstruction(); + } + long end = System.nanoTime(); + + // duration + double D = end - begin; + // average duration per instruction + double avgDPIS = D / N; + // System.out.println(D + " nanos for " + N + " instructions"); + // System.out.println(avgD + " nanos per instruction"); + + double bogoIPS = NANOS_IN_ONE_SECOND / avgDPIS; + // System.out.println(bogoIPS + " bogoIPS"); + + return bogoIPS; + } + + private static void bogoInstruction() { + Random random = new Random(100); + int len = 500; + int[] intArray = new int[len]; + for (int i = 0; i < len; i++) { + intArray[i] = random.nextInt(); + } + Arrays.sort(intArray); + } + + /** + * Computed the BogoIPS for this host CPU. + * + * @return + */ + public static double currentBIPS() { + double lastBogos = computeBogoIPS(LAST_N); + return (2 * lastBogos + INITIAL_BOGO_IPS) / 3; + } + + public static void assertPerformance(double currentPerformance, + long referencePerf, double referenceBIPS) + throws AssertionFailedError { + double ajustedPerf = adjustExpectedValue(referencePerf, + referenceBIPS); + if (currentPerformance > ajustedPerf * SLACK) { + throw new AssertionFailedError(currentPerformance + " exceeded expected " + + ajustedPerf + " (adjusted), " + referencePerf + " (raw)"); + } + } + + private static double adjustExpectedValue(long referencePerf, + double referenceBIPS) { + double currentBIPS = currentBIPS(); + return referencePerf * (referenceBIPS / currentBIPS); + } +}

1 0

benchmarking extension to junit?
by Ceki Gulcu 04 Aug '08

04 Aug '08

Hello all, Logback contains a small number of time-sensitive tests. The time needed to execute these tests depend on the capabilities of the host CPU. For example, if on my machine a test executes in 1 millisecond, I would expect it to finish in say 1*10 milliseconds on most machine -- allowing for 10 fold variation. Does anyone know of a junit extension which can help me normalize the coefficient, 10 in the previous example, so that it adapts to the speed of the host CPU? There is also the problem of the JIT compiler... Any recommendations on the subject? -- Ceki Gülcü

4 5