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;
15  
16  import static org.junit.Assert.assertTrue;
17  
18  import org.junit.Before;
19  import org.junit.Ignore;
20  import org.junit.Test;
21  
22  import ch.qos.logback.classic.spi.ILoggingEvent;
23  import ch.qos.logback.classic.turbo.NOPTurboFilter;
24  import ch.qos.logback.core.UnsynchronizedAppenderBase;
25  import ch.qos.logback.core.helpers.NOPAppender;
26  import ch.qos.logback.core.testUtil.EnvUtilForTests;
27  
28  @Ignore
29  public class LoggerPerfTest {
30  
31      static final long NANOS_IN_ONE_SEC = 1000 * 1000 * 1000L;
32      static long NORMAL_RUN_LENGTH = 1 * 1000 * 1000;
33      static long SHORTENED_RUN_LENGTH = 500 * 1000;
34  
35      LoggerContext lc = new LoggerContext();
36      Logger lbLogger = lc.getLogger(this.getClass());
37      org.slf4j.Logger logger = lbLogger;
38  
39      @Before
40      public void setUp() throws Exception {
41      }
42  
43      // ===========================================================================
44      @Test
45      public void durationOfDisabledLogsWith_1_NOPFilter() {
46          double avg = computeDurationOfDisabledLogsWith_1_NOPFilter(1, NORMAL_RUN_LENGTH);
47          System.out.println("durationOfDisabledLogsWith_1_NOPFilter=" + avg);
48          @SuppressWarnings("unused")
49          long referencePerf = 60;
50  
51          //BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS);
52      }
53  
54      double computeDurationOfDisabledLogsWith_1_NOPFilter(int numOfFilters, long len) {
55          for (int i = 0; i < numOfFilters; i++) {
56              lc.addTurboFilter(new NOPTurboFilter());
57          }
58          lbLogger.setLevel(Level.OFF);
59          for (long i = 0; i < len; i++)
60              logger.debug("Toto");
61  
62          long start = System.nanoTime();
63          for (long i = 0; i < len; i++)
64              logger.debug("Toto");
65  
66          return (System.nanoTime() - start) / len;
67      }
68  
69      // ===========================================================================
70      @Test
71      public void durationOfIsDebugEnabled() {
72          double avg = computedurationOfIsDebugEnabled(10 * NORMAL_RUN_LENGTH);
73          System.out.println("durationOfIsDebugEnabled=" + avg);
74  
75          @SuppressWarnings("unused")
76          long referencePerf = 15;
77          //BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS);
78      }
79  
80      double computedurationOfIsDebugEnabled(final long len) {
81          lbLogger.setLevel(Level.OFF);
82          for (long i = 0; i < len; i++)
83              logger.isDebugEnabled();
84          Thread.yield();
85          for (long i = 0; i < len; i++)
86              logger.isDebugEnabled();
87  
88          long start = System.nanoTime();
89          for (long i = 0; i < len; i++)
90              logger.isDebugEnabled();
91          return (System.nanoTime() - start) / len;
92      }
93  
94      // ===========================================================================
95      @Test
96      public void durationOfDisabledLog_NoParameters() {
97          double avg = computeDurationOfDisabledLog_NoParameters(10 * NORMAL_RUN_LENGTH);
98          System.out.println("durationOfDisabledLog_NoParameters=" + avg);
99  
100         @SuppressWarnings("unused")
101         long referencePerf = 18;
102         //BogoPerf.assertDuration(avg, referencePerf, CoreConstants.REFERENCE_BIPS);
103     }
104 
105     double computeDurationOfDisabledLog_NoParameters(final long len) {
106         lbLogger.setLevel(Level.OFF);
107         for (long i = 0; i < len; i++)
108             logger.debug("Toto");
109         Thread.yield();
110         for (long i = 0; i < len; i++)
111             logger.debug("Toto");
112         Thread.yield();
113 
114         long start = System.nanoTime();
115         for (long i = 0; i < len; i++)
116             logger.debug("Toto");
117         return (System.nanoTime() - start) / len;
118     }
119 
120     // ===========================================================================
121 
122     @Test
123     public void durationOfDisabledLog_1_Parameter() {
124         double avgDuration = computeDurationOfDisabledLog_1_Parameter(NORMAL_RUN_LENGTH);
125         System.out.println("durationOfDisabledLog_1_Parameter=" + avgDuration);
126 
127         @SuppressWarnings("unused")
128         long referencePerf = 30;
129         //BogoPerf.assertDuration(avgDuration, referencePerf, CoreConstants.REFERENCE_BIPS);
130     }
131 
132     double computeDurationOfDisabledLog_1_Parameter(long len) {
133         lbLogger.setLevel(Level.OFF);
134         final Object o = new Object();
135         for (long i = 0; i < len; i++)
136             logger.debug("Toto {}", o);
137 
138         long start = System.nanoTime();
139         for (long i = 0; i < len; i++)
140             logger.debug("Toto {}", o);
141 
142         long end = System.nanoTime();
143         return (end - start) / len;
144     }
145 
146     // ===========================================================================
147 
148     @Test
149     public void durationOfEnabledLog() {
150         if (EnvUtilForTests.isLinux()) {
151             // the JIT on Linux behaves very differently
152             return;
153         }
154         double avgDuration = computeDurationOfEnabledLog(SHORTENED_RUN_LENGTH);
155         System.out.println("durationOfEnabledLog=" + avgDuration);
156 
157         @SuppressWarnings("unused")
158         long referencePerf = 800;
159        // BogoPerf.assertDuration(avgDuration, referencePerf, CoreConstants.REFERENCE_BIPS);
160     }
161 
162     double computeDurationOfEnabledLog(long len) {
163         lbLogger.setLevel(Level.ALL);
164 
165         NOPAppender<ILoggingEvent> nopAppender = new NOPAppender<ILoggingEvent>();
166         nopAppender.start();
167         ((ch.qos.logback.classic.Logger) logger).addAppender(nopAppender);
168         for (long i = 0; i < len; i++) {
169             logger.debug("Toto");
170         }
171         long start = System.nanoTime();
172         for (long i = 0; i < len; i++) {
173             logger.debug("Toto");
174         }
175         long end = System.nanoTime();
176         return (end - start) / len;
177     }
178 
179     // ===========================================================================
180 
181     @Test
182     public void testThreadedLogging() throws InterruptedException {
183         SleepAppender<ILoggingEvent> appender = new SleepAppender<ILoggingEvent>();
184 
185         int MILLIS_PER_CALL = 250;
186         int NANOS_PER_CALL = 250 * 1000 * 1000;
187 
188         appender.setDuration(MILLIS_PER_CALL);
189         appender.start();
190 
191         lbLogger.addAppender(appender);
192         lbLogger.setLevel(Level.DEBUG);
193         long start;
194         long end;
195         int threadCount = 10;
196         int iterCount = 5;
197         TestRunner[] threads = new TestRunner[threadCount];
198         for (int i = 0; i < threads.length; ++i) {
199             threads[i] = new TestRunner(logger, iterCount);
200         }
201         start = System.nanoTime();
202         for (Thread thread : threads) {
203             thread.start();
204         }
205         for (TestRunner thread : threads) {
206             thread.join();
207         }
208         end = System.nanoTime();
209         double tolerance = threadCount * .125; // Very little thread contention
210         // should occur in this test.
211         double max = ((((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount) * tolerance;
212         double serialized = (((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount * threadCount;
213         double actual = ((double) (end - start)) / NANOS_IN_ONE_SEC;
214         System.out.printf("Sleep duration: %,.4f seconds. Max expected: %,.4f seconds, Serialized: %,.4f\n", actual, max, serialized);
215         assertTrue("Exceeded maximum expected time.", actual < max);
216     }
217 
218     // ============================================================
219     private static class TestRunner extends Thread {
220         private org.slf4j.Logger logger;
221         private long len;
222 
223         public TestRunner(org.slf4j.Logger logger, long len) {
224             this.logger = logger;
225             this.len = len;
226         }
227 
228         public void run() {
229             Thread.yield();
230             for (long i = 0; i < len; i++) {
231                 logger.debug("Toto");
232             }
233         }
234     }
235 
236     // ============================================================
237     public static class SleepAppender<E> extends UnsynchronizedAppenderBase<E> {
238         private static long duration = 500;
239 
240         public void setDuration(long millis) {
241             duration = millis;
242         }
243 
244         @Override
245         protected void append(E eventObject) {
246             try {
247                 Thread.sleep(duration);
248             } catch (InterruptedException ie) {
249                 // Ignore
250             }
251         }
252     }
253     // ============================================================
254 }