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 org.junit.jupiter.api.BeforeEach;
17  import org.junit.jupiter.api.Disabled;
18  import org.junit.jupiter.api.Test;
19  
20  import ch.qos.logback.classic.spi.ILoggingEvent;
21  import ch.qos.logback.classic.turbo.NOPTurboFilter;
22  import ch.qos.logback.core.UnsynchronizedAppenderBase;
23  import ch.qos.logback.core.helpers.NOPAppender;
24  import ch.qos.logback.core.testUtil.EnvUtilForTests;
25  
26  import static org.junit.jupiter.api.Assertions.assertTrue;
27  
28  @Disabled
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      @BeforeEach
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,
130         // CoreConstants.REFERENCE_BIPS);
131     }
132 
133     double computeDurationOfDisabledLog_1_Parameter(long len) {
134         lbLogger.setLevel(Level.OFF);
135         final Object o = new Object();
136         for (long i = 0; i < len; i++)
137             logger.debug("Toto {}", o);
138 
139         long start = System.nanoTime();
140         for (long i = 0; i < len; i++)
141             logger.debug("Toto {}", o);
142 
143         long end = System.nanoTime();
144         return (end - start) / len;
145     }
146 
147     // ===========================================================================
148 
149     @Test
150     public void durationOfEnabledLog() {
151         if (EnvUtilForTests.isLinux()) {
152             // the JIT on Linux behaves very differently
153             return;
154         }
155         double avgDuration = computeDurationOfEnabledLog(SHORTENED_RUN_LENGTH);
156         System.out.println("durationOfEnabledLog=" + avgDuration);
157 
158         @SuppressWarnings("unused")
159         long referencePerf = 800;
160         // BogoPerf.assertDuration(avgDuration, referencePerf,
161         // CoreConstants.REFERENCE_BIPS);
162     }
163 
164     double computeDurationOfEnabledLog(long len) {
165         lbLogger.setLevel(Level.ALL);
166 
167         NOPAppender<ILoggingEvent> nopAppender = new NOPAppender<ILoggingEvent>();
168         nopAppender.start();
169         ((ch.qos.logback.classic.Logger) logger).addAppender(nopAppender);
170         for (long i = 0; i < len; i++) {
171             logger.debug("Toto");
172         }
173         long start = System.nanoTime();
174         for (long i = 0; i < len; i++) {
175             logger.debug("Toto");
176         }
177         long end = System.nanoTime();
178         return (end - start) / len;
179     }
180 
181     // ===========================================================================
182 
183     @Test
184     public void testThreadedLogging() throws InterruptedException {
185         SleepAppender<ILoggingEvent> appender = new SleepAppender<ILoggingEvent>();
186 
187         int MILLIS_PER_CALL = 250;
188         int NANOS_PER_CALL = 250 * 1000 * 1000;
189 
190         appender.setDuration(MILLIS_PER_CALL);
191         appender.start();
192 
193         lbLogger.addAppender(appender);
194         lbLogger.setLevel(Level.DEBUG);
195         long start;
196         long end;
197         int threadCount = 10;
198         int iterCount = 5;
199         TestRunner[] threads = new TestRunner[threadCount];
200         for (int i = 0; i < threads.length; ++i) {
201             threads[i] = new TestRunner(logger, iterCount);
202         }
203         start = System.nanoTime();
204         for (Thread thread : threads) {
205             thread.start();
206         }
207         for (TestRunner thread : threads) {
208             thread.join();
209         }
210         end = System.nanoTime();
211         double tolerance = threadCount * .125; // Very little thread contention
212         // should occur in this test.
213         double max = ((((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount) * tolerance;
214         double serialized = (((double) NANOS_PER_CALL) / NANOS_IN_ONE_SEC) * iterCount * threadCount;
215         double actual = ((double) (end - start)) / NANOS_IN_ONE_SEC;
216         System.out.printf("Sleep duration: %,.4f seconds. Max expected: %,.4f seconds, Serialized: %,.4f\n", actual,
217                 max, serialized);
218         assertTrue(actual < max, "Exceeded maximum expected time.");
219     }
220 
221     // ============================================================
222     private static class TestRunner extends Thread {
223         private org.slf4j.Logger logger;
224         private long len;
225 
226         public TestRunner(org.slf4j.Logger logger, long len) {
227             this.logger = logger;
228             this.len = len;
229         }
230 
231         public void run() {
232             Thread.yield();
233             for (long i = 0; i < len; i++) {
234                 logger.debug("Toto");
235             }
236         }
237     }
238 
239     // ============================================================
240     public static class SleepAppender<E> extends UnsynchronizedAppenderBase<E> {
241         private static long duration = 500;
242 
243         public void setDuration(long millis) {
244             duration = millis;
245         }
246 
247         @Override
248         protected void append(E eventObject) {
249             try {
250                 Thread.sleep(duration);
251             } catch (InterruptedException ie) {
252                 // Ignore
253             }
254         }
255     }
256     // ============================================================
257 }