1
2
3
4
5
6
7
8
9
10
11
12
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
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
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
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
130
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
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
161
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;
212
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
253 }
254 }
255 }
256
257 }