View Javadoc
1   /**
2    * Logback: the reliable, generic, fast and flexible logging framework.
3    * Copyright (C) 1999-2015, QOS.ch. All rights reserved.
4    *
5    * This program and the accompanying materials are dual-licensed under
6    * either the terms of the Eclipse Public License v1.0 as published by
7    * the Eclipse Foundation
8    *
9    *   or (per the licensee's choosing)
10   *
11   * under the terms of the GNU Lesser General Public License version 2.1
12   * as published by the Free Software Foundation.
13   */
14  package ch.qos.logback.classic.net;
15  
16  import java.io.IOException;
17  import java.io.ObjectOutputStream;
18  import java.net.Socket;
19  
20  import junit.framework.TestCase;
21  import ch.qos.logback.classic.net.testObjectBuilders.Builder;
22  import ch.qos.logback.classic.net.testObjectBuilders.MinimalSer;
23  import ch.qos.logback.classic.net.testObjectBuilders.MinimalSerBuilder;
24  import ch.qos.logback.classic.net.testObjectBuilders.TrivialLoggingEventVOBuilder;
25  import ch.qos.logback.classic.spi.LoggingEventVO;
26  
27  public class SerializationPerfTest extends TestCase {
28  
29      ObjectOutputStream oos;
30  
31      int loopNumber = 10000;
32      int resetFrequency = 100;
33      int pauseFrequency = 10;
34      long pauseLengthInMillis = 20;
35  
36      /**
37       * <p>
38       * Run the test with a MockSocketServer or with a NOPOutputStream
39       * 
40       * <p>
41       * Run with external mock can be done using the ExternalMockSocketServer. It
42       * needs to be launched from a separate JVM. The ExternalMockSocketServer does
43       * not consume the events but passes through the available bytes that it is
44       * receiving.
45       * 
46       * <p>
47       * For example, with 4 test methods, you can launch the
48       * ExternalMockSocketServer this way:
49       * </p>
50       * <p>
51       * <code>java ch.qos.logback.classic.net.ExternalMockSocketServer 4</code>
52       * </p>
53       */
54      boolean runWithExternalMockServer = true;
55  
56      /**
57       * Last results:
58       * Data sent mesured in kilobytes.
59       * Avg time mesured in microsecs.
60       * 
61       * NOPOutputStream: 
62       *   |                |  Runs | Avg time | Data sent |
63       *   | MinimalObj Ext | 10000 |          |           |
64       *   | MinimalObj Ser | 10000 |          |           |
65       *   | LoggEvent Ext  | 10000 |          |           |
66       *   | LoggEvent Ser  | 10000 |          |           |
67       * 
68       * External MockServer with 45 letters-long message: on localhost
69       * (always the same message)
70       *       |                |  Runs | Avg time | Data sent |
71       *   | MinimalObj Ext | 10000 |      -   |       -   |
72       *   | MinimalObj Ser | 10000 |     74   |     248   |
73       *   | LoggEvent Ext  | 10000 |      -   |       -   |
74       *   | LoggEvent Ser  | 10000 |    156   |     835   |
75       *       pauseFrequency = 10 and pauseLengthInMillis = 20
76       *
77       * External MockServer with 45 letters-long message: on localhost
78       * (different message each time)
79       *       |                |  Runs | Avg time | Data sent |
80       *   | MinimalObj Ext | 10000 |          |           |
81       *   | MinimalObj Ser | 10000 |     73   |    1139   |
82       *   | LoggEvent Ext  | 10000 |          |           |
83       *   | LoggEvent Ser  | 10000 |    162   |    1752   |
84       *       pauseFrequency = 10 and pauseLengthInMillis = 20
85       *
86       * External MockServer with 45 letters-long message: on PIXIE
87       * (always the same message)
88       *       |                |  Runs | Avg time | Data sent |
89       *   | MinimalObj Ext | 10000 |      -   |       -   |
90       *   | MinimalObj Ser | 10000 |     29   |     248   |
91       *   | LoggEvent Ext  | 10000 |      -   |       -   |
92       *   | LoggEvent Ser  | 10000 |     42   |     835   |
93       *       pauseFrequency = 10 and pauseLengthInMillis = 20
94       *
95       * External MockServer with 45 letters-long message: on PIXIE
96       * (different message each time)
97       *       |                |  Runs | Avg time | Data sent |
98       *   | MinimalObj Ext | 10000 |          |           |
99       *   | 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 }