Author: seb Date: Tue Sep 5 18:19:17 2006 New Revision: 508 Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/ExternalMockSocketServer.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/net/testObjectBuilders/Builder.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEvent2Builder.java 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/MinimalExtBuilder.java logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/MinimalSerBuilder.java Log: improved performance tests Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/ExternalMockSocketServer.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/ExternalMockSocketServer.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/ExternalMockSocketServer.java Tue Sep 5 18:19:17 2006 @@ -1,7 +1,6 @@ package ch.qos.logback.classic.net; -import java.io.BufferedInputStream; -import java.io.ObjectInputStream; +import java.io.InputStream; import java.net.ServerSocket; import java.net.Socket; import java.util.ArrayList; @@ -16,7 +15,7 @@ static final int PORT = 4560; - static int loopLen; + //static int loopLen; static int clientNumber; static List<String> msgList = new ArrayList<String>(); @@ -25,10 +24,9 @@ String className = LOGGINGEVENT; public static void main(String[] args) { - if (args.length == 2) { + if (args.length == 1) { clientNumber = Integer.parseInt(args[0]); - loopLen = Integer.parseInt((args[1])); - System.out.println("Starting Server..."); + //loopLen = Integer.parseInt((args[1])); runServer(); } else { usage("Wrong number of arguments."); @@ -37,29 +35,39 @@ static void usage(String msg) { System.err.println(msg); - System.err.println("Usage: java " - + ExternalMockSocketServer.class.getName() + " clientNumber loopNumber"); + System.err + .println("Usage: java " + ExternalMockSocketServer.class.getName() + + " loopNumber"); System.exit(1); } static void runServer() { - ObjectInputStream ois; - Object readObject; + try { - System.out.println("Listening on port " + PORT); + System.out.println("Starting Server..."); ServerSocket serverSocket = new ServerSocket(PORT); + System.out.println("Listening on port " + PORT); for (int j = 0; j < clientNumber; j++) { Socket socket = serverSocket.accept(); System.out.println("New client accepted."); System.out.println("Connected to client at " + socket.getInetAddress()); - ois = new ObjectInputStream(new BufferedInputStream(socket - .getInputStream())); - for (int i = 0; i < loopLen; i++) { - readObject = ois.readObject(); - //msgList.add(readObject.toString()); + + InputStream is = socket.getInputStream(); + long sum = 0; + + while (true) { + // this call is blocking + int val = is.read(); + if(val == -1) { + break; + } + // if a byte is available, we skip it. + // this allows to pass all available bytes in a quick manner. + int a = is.available(); + sum += a + 1; + is.skip(a); } - ois.close(); - System.out.println("Finished with this client."); + System.out.println(sum); } serverSocket.close(); } catch (Exception se) { 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 Tue Sep 5 18:19:17 2006 @@ -18,6 +18,9 @@ int loopNumber = 10000; int resetFrequency = 100; + int pauseFrequency = 200; + long pauseLengthInMillis = 50; + /** * Run the test with a MockSocketServer or with a NOPOutputStream */ @@ -26,41 +29,54 @@ * <p> * Run with external mock can be done using the * ExternalMockSocketServer. It needs to be launched - * from a separate JVM. + * from a separate JVM. The ExternalMockSocketServer does not + * consume the events but passes through the available bytes + * that it is recieving. * </p> * <p> - * For example, with 4 test methods and a loopNumber of 10000, + * For example, with 4 test methods, * you can launch the ExternalMockSocketServer this way: * </p> * <p> - * <code>java ch.qos.logback.classic.net.ExternalMockSocketServer 4 20000</code> - * </p> - * <p> - * (20000 because each methods iterate twice). + * <code>java ch.qos.logback.classic.net.ExternalMockSocketServer 4</code> * </p> */ boolean runWithExternalMockServer = true; /** * Last results: + * Data sent mesured in bytes. + * Avg time mesured in nanos. * * NOPOutputStream: - * Minimal Object externalization: average time = 6511 after 10000 writes. - * Minimal Object serialization: average time = 7883 after 10000 writes. - * LoggingEvent object externalization: average time = 9641 after 10000 writes. - * LoggingEvent object serialization: average time = 25729 after 10000 writes. + * | | Runs | Avg time | Data sent | + * | MinimalObj Ext | 10000 | 6511 | | + * | MinimalObj Ser | 10000 | 7883 | | + * | LoggEvent Ext | 10000 | 9641 | | + * | LoggEvent Ser | 10000 | 25729 | | * * Internal MockServer: - * Minimal object externalization : average time = 62040 after 10000 writes. - * Minimal object serialization : average time = 76237 after 10000 writes. - * LoggingEvent object externalization : average time = 122714 after 10000 writes. - * LoggingEvent object serialization : average time = 121711 after 10000 writes. + * | | Runs | Avg time | Data sent | + * | MinimalObj Ext | 10000 | 62040 | | + * | MinimalObj Ser | 10000 | 76237 | | + * | LoggEvent Ext | 10000 | 122714 | | + * | LoggEvent Ser | 10000 | 121711 | | * - * External MockServer: - * Minimal object externalization : average time = 55577 after 10000 writes. - * Minimal object serialization : average time = 56669 after 10000 writes. - * LoggingEvent object externalization : average time = 121477 after 10000 writes. - * LoggingEvent object serialization : average time = 111148 after 10000 writes. + * External MockServer with 45 letters-long message: + * | | Runs | Avg time | Data sent | + * | MinimalObj Ext | 10000 | 70240 | 1171384 | + * | MinimalObj Ser | 10000 | 62754 | 1157584 | + * | LoggEvent Ext | 10000 | 198910 | 1509984 | + * | LoggEvent Ser | 10000 | 189970 | 1715984 | + * pauseFrequency = 200 and pauseLengthInMillis = 50 + * + * External MockServer with 2 letters-long message: + * | | Runs | Avg time | Data sent | + * | MinimalObj Ext | 10000 | 43234 | 311384 | + * | MinimalObj Ser | 10000 | 31603 | 297584 | + * | LoggEvent Ext | 10000 | 106442 | 649984 | + * | LoggEvent Ser | 10000 | 93467 | 855984 | + * pauseFrequency = 200 and pauseLengthInMillis = 50 */ public void setUp() throws Exception { @@ -85,15 +101,22 @@ } public void runPerfTest(Builder builder, String label) throws Exception { + //long time1 = System.nanoTime(); // first run for just in time compiler - int counter = 0; + int resetCounter = 0; + int pauseCounter = 0; for (int i = 0; i < loopNumber; i++) { try { oos.writeObject(builder.build(i)); oos.flush(); - if (++counter >= resetFrequency) { + if (++resetCounter >= resetFrequency) { oos.reset(); + //resetCounter = 0; + } + if (++pauseCounter >= pauseFrequency) { + Thread.sleep(pauseLengthInMillis); + pauseCounter = 0; } } catch (IOException ex) { fail(ex.getMessage()); @@ -102,24 +125,30 @@ // second run Long t1; - Long t2; + Long t2 ; Long total = 0L; - counter = 0; - // System.out.println("Beginning mesured run"); - t1 = System.nanoTime(); + resetCounter = 0; + pauseCounter = 0; + //System.out.println("Beginning mesured run"); for (int i = 0; i < loopNumber; i++) { try { + t1 = System.nanoTime(); oos.writeObject(builder.build(i)); oos.flush(); - if (++counter >= resetFrequency) { + t2 = System.nanoTime(); + total += (t2 - t1); + if (++resetCounter >= resetFrequency) { oos.reset(); + //resetCounter = 0; + } + if (++pauseCounter >= pauseFrequency) { + Thread.sleep(pauseLengthInMillis); + pauseCounter = 0; } } catch (IOException ex) { fail(ex.getMessage()); } } - t2 = System.nanoTime(); - total += (t2 - t1); System.out.println(label + " : average time = " + total / loopNumber + " after " + loopNumber + " writes."); @@ -127,6 +156,9 @@ mockServer.join(1000); assertTrue(mockServer.finished); } + + //long time2 = System.nanoTime(); + //System.out.println("********* -> Time needed to run the test method: " + Long.toString(time2-time1)); } public void testWithMinimalExternalization() throws Exception { Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/Builder.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/Builder.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/Builder.java Tue Sep 5 18:19:17 2006 @@ -2,6 +2,7 @@ public interface Builder { + //45 characters message final String MSG_PREFIX = "aaaaabbbbbcccccdddddaaaaabbbbbcccccdddddaaaa"; //final String MSG_PREFIX = "a"; Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEvent2Builder.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEvent2Builder.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/LoggingEvent2Builder.java Tue Sep 5 18:19:17 2006 @@ -10,7 +10,6 @@ LoggingEvent2 le = new LoggingEvent2(); le.setLevel(Level.DEBUG); le.setLogger(new LoggerContext().getLogger(LoggerContext.ROOT_NAME)); - // 45 characters message le.setMessage(MSG_PREFIX + i); le.setThreadName("threadName"); return le; Modified: 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/LoggingEventBuilder.java Tue Sep 5 18:19:17 2006 @@ -10,7 +10,6 @@ LoggingEvent le = new LoggingEvent(); le.setLevel(Level.DEBUG); le.setLogger(new LoggerContext().getLogger(LoggerContext.ROOT_NAME)); - // 45 characters message le.setMessage(MSG_PREFIX + i); le.setThreadName("threadName"); return le; Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/MinimalExtBuilder.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/MinimalExtBuilder.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/MinimalExtBuilder.java Tue Sep 5 18:19:17 2006 @@ -25,7 +25,6 @@ } public MinimalExt(int i) { - // 45 characters message message = Builder.MSG_PREFIX + i; } Modified: logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/MinimalSerBuilder.java ============================================================================== --- logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/MinimalSerBuilder.java (original) +++ logback/trunk/logback-classic/src/test/java/ch/qos/logback/classic/net/testObjectBuilders/MinimalSerBuilder.java Tue Sep 5 18:19:17 2006 @@ -18,7 +18,6 @@ String message; public MinimalSer(int i) { - // 45 characters message message = Builder.MSG_PREFIX + i; } } \ No newline at end of file