@@ -263,8 +263,7 @@ be taken.
263
263
264
264
However, asynchronous loggers need to make this decision before passing
265
265
the log message to another thread; the location information will be lost
266
- after that point. The
267
- xref:manual/performance.adoc#asyncLoggingWithLocation[performance impact] of
266
+ after that point. The performance impact of
268
267
taking a stack trace snapshot is even higher for asynchronous loggers:
269
268
logging with location is 30-100 times slower than without location. For
270
269
this reason, asynchronous loggers and asynchronous appenders do not
@@ -273,181 +272,6 @@ include location information by default.
273
272
You can override the default behavior in your logger or asynchronous
274
273
appender configuration by specifying `includeLocation="true"`.
275
274
276
- [#Performance]
277
- == Asynchronous Logging Performance
278
-
279
- The throughput performance results below were derived from running the
280
- PerfTest, MTPerfTest and PerfTestDriver classes which can be found in
281
- the Log4j 2 unit test source directory. For throughput tests, the
282
- methodology used was:
283
-
284
- * First, warm up the JVM by logging 200,000 log messages of 500
285
- characters.
286
- * Repeat the warm-up 10 times, then wait 10 seconds for the I/O thread
287
- to catch up and buffers to drain.
288
- * Measure how long it takes to execute 256 * 1024 / threadCount calls to
289
- Logger.log and express the result in messages per second.
290
- * Repeat the test 5 times and average the results.
291
-
292
- The results below were obtained with log4j-2.0-beta5,
293
- disruptor-3.0.0.beta3, log4j-1.2.17 and logback-1.0.10.
294
-
295
- === Logging Peak Throughput
296
-
297
- The graph below compares the throughput of synchronous loggers,
298
- asynchronous appenders and asynchronous loggers. This is the total
299
- throughput of all threads together. In the test with 64 threads,
300
- asynchronous loggers are 12 times faster than asynchronous appenders,
301
- and 68 times faster than synchronous loggers.
302
-
303
- Asynchronous loggers' throughput increases with the number of threads,
304
- whereas both synchronous loggers and asynchronous appenders have more or
305
- less constant throughput regardless of the number of threads that are
306
- doing the logging.
307
-
308
- image:async-vs-sync-throughput.png[Async loggers have much
309
- higher throughput than sync loggers.]
310
-
311
- === Asynchronous Throughput Comparison with Other Logging Packages
312
-
313
- We also compared the peak throughput of asynchronous loggers to the
314
- synchronous loggers and asynchronous appenders available in other
315
- logging packages, specifically log4j-1.2.17 and logback-1.0.10, with
316
- similar results. For asynchronous appenders, the total logging throughput of
317
- all threads together remains roughly constant when adding more threads.
318
- Asynchronous loggers make more effective use of the multiple cores
319
- available on the machine in multi-threaded scenarios.
320
-
321
- image:async-throughput-comparison.png[Async loggers have the
322
- highest throughput.]
323
-
324
- On Solaris 10 (64bit) with JDK1.7.0_06, 4-core Xeon X5570 dual CPU
325
- @2.93Ghz with hyperthreading switched on (16 virtual cores):
326
-
327
- .Throughput per thread in messages/second
328
- [cols="h,>,>,>,>,>,>,>",options="header",]
329
- |=======================================================================
330
- |Logger |1 thread |2 threads |4 threads |8 threads |16 threads |32
331
- threads |64 threads
332
- |Log4j 2: Loggers all asynchronous |2,652,412 |909,119 |776,993 |516,365
333
- |239,246 |253,791 |288,997
334
-
335
- |Log4j 2: Loggers mixed sync/async |2,454,358 |839,394 |854,578 |597,913
336
- |261,003 |216,863 |218,937
337
-
338
- |Log4j 2: Async Appender |1,713,429 |603,019 |331,506 |149,408 |86,107
339
- |45,529 |23,980
340
-
341
- |Log4j1: Async Appender |2,239,664 |494,470 |221,402 |109,314 |60,580
342
- |31,706 |14,072
343
-
344
- |Logback: Async Appender |2,206,907 |624,082 |307,500 |160,096 |85,701
345
- |43,422 |21,303
346
-
347
- |Log4j 2: Synchronous |273,536 |136,523 |67,609 |34,404 |15,373 |7,903
348
- |4,253
349
-
350
- |Log4j1: Synchronous |326,894 |105,591 |57,036 |30,511 |13,900 |7,094
351
- |3,509
352
-
353
- |Logback: Synchronous |178,063 |65,000 |34,372 |16,903 |8,334 |3,985
354
- |1,967
355
- |=======================================================================
356
-
357
- On Windows 7 (64bit) with JDK1.7.0_11, 2-core Intel i5-3317u CPU
358
- @1.70Ghz with hyperthreading switched on (4 virtual cores):
359
-
360
- .Throughput per thread in messages/second
361
- [cols="h,>,>,>,>,>,>",options="header",]
362
- |=======================================================================
363
- |Logger |1 thread |2 threads |4 threads |8 threads |16 threads |32
364
- threads
365
- |Log4j 2: Loggers all asynchronous |1,715,344 |928,951 |1,045,265
366
- |1,509,109 |1,708,989 |773,565
367
-
368
- |Log4j 2: Loggers mixed sync/async |571,099 |1,204,774 |1,632,204
369
- |1,368,041 |462,093 |908,529
370
-
371
- |Log4j 2: Async Appender |1,236,548 |1,006,287 |511,571 |302,230
372
- |160,094 |60,152
373
-
374
- |Log4j1: Async Appender |1,373,195 |911,657 |636,899 |406,405 |202,777
375
- |162,964
376
-
377
- |Logback: Async Appender |1,979,515 |783,722 |582,935 |289,905 |172,463
378
- |133,435
379
-
380
- |Log4j 2: Synchronous |281,250 |225,731 |129,015 |66,590 |34,401 |17,347
381
-
382
- |Log4j1: Synchronous |147,824 |72,383 |32,865 |18,025 |8,937 |4,440
383
-
384
- |Logback: Synchronous |149,811 |66,301 |32,341 |16,962 |8,431 |3,610
385
- |=======================================================================
386
-
387
- [#Latency]
388
- === Response Time Latency
389
-
390
- This section has been rewritten with the Log4j 2.6 release. The
391
- previous version only reported _service time_ instead of _response
392
- time_. See the xref:manual/performance.adoc#responseTime[response time] sidebar on the performance page on why this is too optimistic.
393
- Furthermore, the previous version reported average latency, which does not make sense
394
- since latency is not a normal distribution. Finally, the previous
395
- version of this section only reported the maximum latency of up to
396
- 99.99% of the measurements, which does not tell you how bad the worst
397
- 0.01% were. This is unfortunate because often the "outliers" are all
398
- that matter when it comes to response time. From this release, we will
399
- try to do better and report response time latency across the full range
400
- of percentages, including all the outliers. Our thanks to Gil Tene for
401
- his http://www.infoq.com/presentations/latency-response-time[How NOT to
402
- measure latency] presentation. (Now we know why this is also known as
403
- the "Oh s#@t!" presentation.)
404
-
405
- xref:manual/performance.adoc#responseTime[Response time] is how long it
406
- takes to log a message under a certain load. What is often reported as
407
- latency is _service time_: how long it took to operate.
408
- This hides the fact that a single spike in service time adds
409
- a queueing delay for many of the subsequent operations. Service time is
410
- easy to measure (and often looks good on paper) but is irrelevant for
411
- users since it omits the time spent waiting for service. For this reason,
412
- we report response time: service time plus wait time.
413
-
414
- The response time test results below were all derived from running the
415
- ResponseTimeTest class which can be found in the Log4j 2 unit test
416
- source directory. If you want to run these tests yourself, here are the
417
- command line options we used:
418
-
419
- * -Xms1G -Xmx1G (prevent heap resizing during the test)
420
- * -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
421
- -DAsyncLogger.WaitStrategy=busyspin (to use Async Loggers. The BusySpin
422
- wait strategy reduces some jitter.)
423
- * *classic mode:* -Dlog4j2.enable.direct.encoders=false +
424
- *garbage-free mode:* -Dlog4j2.enable.direct.encoders=true
425
- * -XX:CompileCommand=dontinline,org.apache.logging.log4j.core.async.perftest.NoOpIdleStrategy::idle
426
- * -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps
427
- -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationConcurrentTime
428
- -XX:+PrintGCApplicationStoppedTime (to eyeball GC and savepoint pauses)
429
-
430
- The graph below compares the response time latency of the
431
- ArrayBlockingQueue-based asynchronous appenders in Logback 1.1.7, Log4j
432
- 1.2.17 to the various options for asynchronous logging that Log4j 2.6
433
- offers. Under a workload of 128,000 messages per second, using 16
434
- threads (each logging at a rate of 8,000 messages per second), we see
435
- that Logback 1.1.7, Log4j 1.2.17 experience latency spikes that are
436
- orders of magnitude larger than Log4j 2.
437
-
438
- image:ResponseTimeAsyncLogging16Threads_8kEach.png[When 16
439
- threads generate a total workload of 128,000 msg/sec, Logback 1.1.7 and
440
- Log4j 1.2.17 experiences latency spikes that are orders of magnitude
441
- larger than Log4j 2]
442
-
443
- The graph below zooms in on the Log4j 2 results for the same test. We
444
- see that the worst-case response time is highest for the
445
- ArrayBlockingQueue-based Async Appender.
446
- xref:manual/garbagefree.adoc[Garbage-free] async loggers have the best response
447
- time behavior.
448
-
449
- image:ResponseTimeAsyncLogging16Threads_8kEachLog4j2Only-labeled.png[image]
450
-
451
275
[#UnderTheHood]
452
276
== Under The Hood
453
277
0 commit comments