001/**
002 * Logback: the reliable, generic, fast and flexible logging framework.
003 * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
004 *
005 * This program and the accompanying materials are dual-licensed under
006 * either the terms of the Eclipse Public License v1.0 as published by
007 * the Eclipse Foundation
008 *
009 *   or (per the licensee's choosing)
010 *
011 * under the terms of the GNU Lesser General Public License version 2.1
012 * as published by the Free Software Foundation.
013 */
014package ch.qos.logback.classic.net;
015
016import java.io.IOException;
017import java.io.ObjectOutputStream;
018import java.net.Socket;
019
020import junit.framework.TestCase;
021import ch.qos.logback.classic.net.testObjectBuilders.Builder;
022import ch.qos.logback.classic.net.testObjectBuilders.MinimalSer;
023import ch.qos.logback.classic.net.testObjectBuilders.MinimalSerBuilder;
024import ch.qos.logback.classic.net.testObjectBuilders.TrivialLoggingEventVOBuilder;
025import ch.qos.logback.classic.spi.LoggingEventVO;
026
027public class SerializationPerfTest extends TestCase {
028
029    ObjectOutputStream oos;
030
031    int loopNumber = 10000;
032    int resetFrequency = 100;
033    int pauseFrequency = 10;
034    long pauseLengthInMillis = 20;
035
036    /**
037     * <p>
038     * Run the test with a MockSocketServer or with a NOPOutputStream
039     * 
040     * <p>
041     * Run with external mock can be done using the ExternalMockSocketServer. It
042     * needs to be launched from a separate JVM. The ExternalMockSocketServer does
043     * not consume the events but passes through the available bytes that it is
044     * receiving.
045     * 
046     * <p>
047     * For example, with 4 test methods, you can launch the
048     * ExternalMockSocketServer this way:
049     * </p>
050     * <p>
051     * <code>java ch.qos.logback.classic.net.ExternalMockSocketServer 4</code>
052     * </p>
053     */
054    boolean runWithExternalMockServer = true;
055
056    /**
057     * Last results:
058     * Data sent mesured in kilobytes.
059     * Avg time mesured in microsecs.
060     * 
061     * NOPOutputStream: 
062     *   |                |  Runs | Avg time | Data sent |
063     *   | MinimalObj Ext | 10000 |          |           |
064     *   | MinimalObj Ser | 10000 |          |           |
065     *   | LoggEvent Ext  | 10000 |          |           |
066     *   | LoggEvent Ser  | 10000 |          |           |
067     * 
068     * External MockServer with 45 letters-long message: on localhost
069     * (always the same message)
070     *       |                |  Runs | Avg time | Data sent |
071     *   | MinimalObj Ext | 10000 |      -   |       -   |
072     *   | MinimalObj Ser | 10000 |     74   |     248   |
073     *   | LoggEvent Ext  | 10000 |      -   |       -   |
074     *   | LoggEvent Ser  | 10000 |    156   |     835   |
075     *       pauseFrequency = 10 and pauseLengthInMillis = 20
076     *
077     * External MockServer with 45 letters-long message: on localhost
078     * (different message each time)
079     *       |                |  Runs | Avg time | Data sent |
080     *   | MinimalObj Ext | 10000 |          |           |
081     *   | MinimalObj Ser | 10000 |     73   |    1139   |
082     *   | LoggEvent Ext  | 10000 |          |           |
083     *   | LoggEvent Ser  | 10000 |    162   |    1752   |
084     *       pauseFrequency = 10 and pauseLengthInMillis = 20
085     *
086     * External MockServer with 45 letters-long message: on PIXIE
087     * (always the same message)
088     *       |                |  Runs | Avg time | Data sent |
089     *   | MinimalObj Ext | 10000 |      -   |       -   |
090     *   | MinimalObj Ser | 10000 |     29   |     248   |
091     *   | LoggEvent Ext  | 10000 |      -   |       -   |
092     *   | LoggEvent Ser  | 10000 |     42   |     835   |
093     *       pauseFrequency = 10 and pauseLengthInMillis = 20
094     *
095     * External MockServer with 45 letters-long message: on PIXIE
096     * (different message each time)
097     *       |                |  Runs | Avg time | Data sent |
098     *   | MinimalObj Ext | 10000 |          |           |
099     *   | MinimalObj Ser | 10000 |     27   |    1139   |
100     *   | LoggEvent Ext  | 10000 |          |           |
101     *   | LoggEvent Ser  | 10000 |     44   |    1752   |
102     *       pauseFrequency = 10 and pauseLengthInMillis = 20
103     *
104     */
105
106    public void setUp() throws Exception {
107        super.setUp();
108        if (runWithExternalMockServer) {
109            oos = new ObjectOutputStream(new Socket("localhost", ExternalMockSocketServer.PORT).getOutputStream());
110        } else {
111            oos = new ObjectOutputStream(new NOPOutputStream());
112        }
113    }
114
115    public void tearDown() throws Exception {
116        super.tearDown();
117        oos.close();
118        oos = null;
119    }
120
121    public void runPerfTest(Builder<?> builder, String label) throws Exception {
122        // long time1 = System.nanoTime();
123
124        // Object builtObject = builder.build(1);
125
126        // first run for just in time compiler
127        int resetCounter = 0;
128        int pauseCounter = 0;
129        for (int i = 0; i < loopNumber; i++) {
130            try {
131                oos.writeObject(builder.build(i));
132                oos.flush();
133                if (++resetCounter >= resetFrequency) {
134                    oos.reset();
135                    resetCounter = 0;
136                }
137                if (++pauseCounter >= pauseFrequency) {
138                    Thread.sleep(pauseLengthInMillis);
139                    pauseCounter = 0;
140                }
141
142            } catch (IOException ex) {
143                fail(ex.getMessage());
144            }
145        }
146
147        // second run
148        Long t1;
149        Long t2;
150        Long total = 0L;
151        resetCounter = 0;
152        pauseCounter = 0;
153        // System.out.println("Beginning mesured run");
154        for (int i = 0; i < loopNumber; i++) {
155            try {
156                t1 = System.nanoTime();
157                oos.writeObject(builder.build(i));
158                oos.flush();
159                t2 = System.nanoTime();
160                total += (t2 - t1);
161                if (++resetCounter >= resetFrequency) {
162                    oos.reset();
163                    resetCounter = 0;
164                }
165                if (++pauseCounter >= pauseFrequency) {
166                    Thread.sleep(pauseLengthInMillis);
167                    pauseCounter = 0;
168                }
169            } catch (IOException ex) {
170                fail(ex.getMessage());
171            }
172        }
173        total /= 1000;
174        System.out.println(label + " : average time = " + total / loopNumber + " microsecs after " + loopNumber + " writes.");
175
176        // long time2 = System.nanoTime();
177        // System.out.println("********* -> Time needed to run the test method: " +
178        // Long.toString(time2-time1));
179    }
180
181    // public void testWithMinimalExternalization() throws Exception {
182    // Builder builder = new MinimalExtBuilder();
183    // runPerfTest(builder, "Minimal object externalization");
184    // }
185
186    public void testWithMinimalSerialization() throws Exception {
187        Builder<MinimalSer> builder = new MinimalSerBuilder();
188        runPerfTest(builder, "Minimal object serialization");
189    }
190
191    // public void testWithExternalization() throws Exception {
192    // Builder builder = new LoggingEventExtBuilder();
193    // runPerfTest(builder, "LoggingEvent object externalization");
194    // }
195
196    public void testWithSerialization() throws Exception {
197        Builder<LoggingEventVO> builder = new TrivialLoggingEventVOBuilder();
198        runPerfTest(builder, "LoggingEventVO object serialization");
199    }
200
201}