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 org.junit.jupiter.api.AfterEach;
21  import org.junit.jupiter.api.Assertions;
22  import org.junit.jupiter.api.BeforeEach;
23  import org.junit.jupiter.api.Disabled;
24  
25  import ch.qos.logback.classic.net.testObjectBuilders.Builder;
26  import ch.qos.logback.classic.net.testObjectBuilders.MinimalSer;
27  import ch.qos.logback.classic.net.testObjectBuilders.MinimalSerBuilder;
28  import ch.qos.logback.classic.net.testObjectBuilders.TrivialLoggingEventVOBuilder;
29  import ch.qos.logback.classic.spi.LoggingEventVO;
30  import org.junit.jupiter.api.Test;
31  
32  @Disabled
33  public class SerializationPerfTest {
34  
35      ObjectOutputStream oos;
36  
37      int loopNumber = 10000;
38      int resetFrequency = 100;
39      int pauseFrequency = 10;
40      long pauseLengthInMillis = 20;
41  
42      /**
43       * <p>
44       * Run the test with a MockSocketServer or with a NOPOutputStream
45       * 
46       * <p>
47       * Run with external mock can be done using the ExternalMockSocketServer. It
48       * needs to be launched from a separate JVM. The ExternalMockSocketServer does
49       * not consume the events but passes through the available bytes that it is
50       * receiving.
51       * 
52       * <p>
53       * For example, with 4 test methods, you can launch the ExternalMockSocketServer
54       * this way:
55       * </p>
56       * <p>
57       * <code>java ch.qos.logback.classic.net.ExternalMockSocketServer 4</code>
58       * </p>
59       */
60      boolean runWithExternalMockServer = true;
61  
62      /**
63       * Last results: Data sent measured in kilobytes. Avg time measured in microsecs.
64       * 
65       * NOPOutputStream: | | Runs | Avg time | Data sent | | MinimalObj Ext | 10000 |
66       * | | | MinimalObj Ser | 10000 | | | | LoggEvent Ext | 10000 | | | | LoggEvent
67       * Ser | 10000 | | |
68       * 
69       * External MockServer with 45 letters-long message: on localhost (always the
70       * same message) | | Runs | Avg time | Data sent | | MinimalObj Ext | 10000 | -
71       * | - | | MinimalObj Ser | 10000 | 74 | 248 | | LoggEvent Ext | 10000 | - | - |
72       * | LoggEvent Ser | 10000 | 156 | 835 | pauseFrequency = 10 and
73       * pauseLengthInMillis = 20
74       *
75       * External MockServer with 45 letters-long message: on localhost (different
76       * message each time) | | Runs | Avg time | Data sent | | MinimalObj Ext | 10000
77       * | | | | MinimalObj Ser | 10000 | 73 | 1139 | | LoggEvent Ext | 10000 | | | |
78       * LoggEvent Ser | 10000 | 162 | 1752 | pauseFrequency = 10 and
79       * pauseLengthInMillis = 20
80       *
81       * External MockServer with 45 letters-long message: on PIXIE (always the same
82       * message) | | Runs | Avg time | Data sent | | MinimalObj Ext | 10000 | - | - |
83       * | MinimalObj Ser | 10000 | 29 | 248 | | LoggEvent Ext | 10000 | - | - | |
84       * LoggEvent Ser | 10000 | 42 | 835 | pauseFrequency = 10 and
85       * pauseLengthInMillis = 20
86       *
87       * External MockServer with 45 letters-long message: on PIXIE (different message
88       * each time) | | Runs | Avg time | Data sent | | MinimalObj Ext | 10000 | | | |
89       * MinimalObj Ser | 10000 | 27 | 1139 | | LoggEvent Ext | 10000 | | | |
90       * LoggEvent Ser | 10000 | 44 | 1752 | pauseFrequency = 10 and
91       * pauseLengthInMillis = 20
92       *
93       */
94  
95      @BeforeEach
96      public void setUp() throws Exception {
97          if (runWithExternalMockServer) {
98              oos = new ObjectOutputStream(new Socket("localhost", ExternalMockSocketServer.PORT).getOutputStream());
99          } else {
100             oos = new ObjectOutputStream(new NOPOutputStream());
101         }
102     }
103 
104     @AfterEach
105     public void tearDown() throws Exception {
106         oos.close();
107         oos = null;
108     }
109 
110     public void runPerfTest(Builder<?> builder, String label) throws Exception {
111         // long time1 = System.nanoTime();
112 
113         // Object builtObject = builder.build(1);
114 
115         // first run for just in time compiler
116         int resetCounter = 0;
117         int pauseCounter = 0;
118         for (int i = 0; i < loopNumber; i++) {
119             try {
120                 oos.writeObject(builder.build(i));
121                 oos.flush();
122                 if (++resetCounter >= resetFrequency) {
123                     oos.reset();
124                     resetCounter = 0;
125                 }
126                 if (++pauseCounter >= pauseFrequency) {
127                     Thread.sleep(pauseLengthInMillis);
128                     pauseCounter = 0;
129                 }
130 
131             } catch (IOException ex) {
132                 Assertions.fail(ex.getMessage());
133             }
134         }
135 
136         // second run
137         Long t1;
138         Long t2;
139         Long total = 0L;
140         resetCounter = 0;
141         pauseCounter = 0;
142         // System.out.println("Beginning measured run");
143         for (int i = 0; i < loopNumber; i++) {
144             try {
145                 t1 = System.nanoTime();
146                 oos.writeObject(builder.build(i));
147                 oos.flush();
148                 t2 = System.nanoTime();
149                 total += (t2 - t1);
150                 if (++resetCounter >= resetFrequency) {
151                     oos.reset();
152                     resetCounter = 0;
153                 }
154                 if (++pauseCounter >= pauseFrequency) {
155                     Thread.sleep(pauseLengthInMillis);
156                     pauseCounter = 0;
157                 }
158             } catch (IOException ex) {
159                 Assertions.fail(ex.getMessage());
160             }
161         }
162         total /= 1000;
163         System.out.println(
164                 label + " : average time = " + total / loopNumber + " microsecs after " + loopNumber + " writes.");
165 
166         // long time2 = System.nanoTime();
167         // System.out.println("********* -> Time needed to run the test method: " +
168         // Long.toString(time2-time1));
169     }
170 
171     // public void testWithMinimalExternalization() throws Exception {
172     // Builder builder = new MinimalExtBuilder();
173     // runPerfTest(builder, "Minimal object externalization");
174     // }
175 
176     @Test
177     public void testWithMinimalSerialization() throws Exception {
178         Builder<MinimalSer> builder = new MinimalSerBuilder();
179         runPerfTest(builder, "Minimal object serialization");
180     }
181 
182     // public void testWithExternalization() throws Exception {
183     // Builder builder = new LoggingEventExtBuilder();
184     // runPerfTest(builder, "LoggingEvent object externalization");
185     // }
186 
187     @Test
188     public void testWithSerialization() throws Exception {
189         Builder<LoggingEventVO> builder = new TrivialLoggingEventVOBuilder();
190         runPerfTest(builder, "LoggingEventVO object serialization");
191     }
192 
193 }