Skip to content

Latest commit

 

History

History
281 lines (215 loc) · 20.1 KB

README.md

File metadata and controls

281 lines (215 loc) · 20.1 KB
Raw

Java Logger Benchmark

GitHub Action

JMH Benchmark for different synchronous Java Logger implementations.

Idea of this benchmark is to put all loggers in the same conditions and measure how they all handle the most common scenarios. Compare their implementation in such scenarios, some loggers have more flexible configurations, different APIs, some have more features, different implementations.

At the end it's your choice, do you want flexibility some loggers provide and what are trade-offs of each implementation.

Loggers

Benchmark features these loggers:

Benchmark

Benchmark consists of different common logging scenarios developers typically use in their applications, by the name of the test you can understand what this situation try to emulate, here is full list of tests:

  • messageAndStacktrace
  • messageWithoutArguments
  • messageOneArgumentInTheEnd
  • messageOneArgumentInTheMiddle
  • messageOneArgumentInTheStart
  • messageTwoArgumentInTheEnd
  • messageTwoArgumentInTheMiddle
  • messageTwoArgumentInTheStart
  • messageThreeArgumentInTheEnd
  • messageThreeArgumentInTheMiddle
  • messageThreeArgumentInTheStart

Here are corresponding examples of resulted log messages (excluding messageAndStacktrace due to big stacktrace):

2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - Message is printed for this logger without arguments
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - Message is printed for this logger and with the argument: FirstArgument
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - Message is printed for FirstArgument argument for this logger
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - FirstArgument argument and message is printed for this logger
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - Message is printed for this logger and with arguments FirstArgument and SecondArgument
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - Message is printed for FirstArgument and SecondArgument argument for this logger
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - FirstArgument and SecondArgument arguments and message is printed for this logger
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - Message is printed for this logger and with arguments FirstArgument and SecondArgument and ThirdArgument
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - Message is printed for FirstArgument and SecondArgument and ThirdArgument argument for this logger
2022-03-22T15:33:48.723 [INFO] io.goodforgod.benchmark.LoggerBenchmark - FirstArgument and SecondArgument and ThirdArgument argument and message is printed for this logger

If you want to look at benchmark details, you can check it here.

Layout

All loggers participants are configured to the same layout, so the all participants will be in equal conditions.

Pseudo layout for all loggers:

{date} [{level}] {logger} - {message}{separator}{throwable with stacktrace}

Description of layout:

  • date - uses formatter yyyy-MM-dd'T'HH:mm:ss.SSS
  • level - logging level
  • logger - logger full class name
  • message - logging message
  • separator - new line to separate logging messages
  • stacktrace - exception stacktrace

Configuration

All loggers use synchronous output, without any async appending mechanism.

All loggers are configured to output to STDERR.

Benchmark emulates real world usage of loggers, same way logger will be used in real running application. To achieve this, benchmark uses real IO output for loggers, but to mitigate IO of the specific machine and console output, all loggers output is redirected to /dev/null. This is done to benchmark how loggers are working in real environment including IO interactions and avoid benchmarking how machine prints data to STDOUT where benchmark is running at.

Loggers have different implementations and such huge performance gaps (as seen by results) occur mostly due to some loggers accessing IO more frequently than others. So measuring IO interactions is indented and critical to receive real world insights.

Setups

JMH precaution:

REMEMBER: The numbers below are just data. To gain reusable insights, you need to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design factorial
experiments, perform baseline and negative tests that provide experimental control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from the domain experts.
Do not assume the numbers tell you what you want them to tell.

Setup 1

This benchmark results are based on run inside GitHub CI and have forwarded stderr to /dev/null.

Benchmark setup configuration:

  • OS: Ubuntu (Github CI)
  • Processor: Unknown
  • Java: JDK 17.0.2, OpenJDK 64-Bit Server VM, 17.0.2+8-LTS
  • Execution: java -jar benchmark-name.jar 2>/dev/null

Raw Results

Benchmark Warmup Runs Units goodforgod-simple logback log4j slf4j-simple java-system
messageAndStacktrace 2 6 ops/s 118216±813 115822±428 104783±501 13338±223 40445±203
messageWithoutArguments 2 6 ops/s 499217±1199 473321±5493 417106±6782 175836±1835 43540±467
messageOneArgumentInTheEnd 2 6 ops/s 458897±4559 443582±2258 400907±5836 169457±3192 40692±811
messageOneArgumentInTheMiddle 2 6 ops/s 473144±13985 451131±15834 422485±5795 173946±1803 40464±552
messageOneArgumentInTheStart 2 6 ops/s 460671±4028 432312±2706 406973±6916 173542±2095 41138±587
messageTwoArgumentInTheEnd 2 6 ops/s 452458±6389 444213±3966 397294±7014 164550±3379 40661±531
messageTwoArgumentInTheMiddle 2 6 ops/s 432949±5454 442847±5500 390417±3958 168683±1862 41380±403
messageTwoArgumentInTheStart 2 6 ops/s 448363±4246 440998±4881 392745±10002 167334±2699 39528±231
messageThreeArgumentInTheEnd 2 6 ops/s 423541±3972 426526±5837 396242±8698 169260±1842 40128±464
messageThreeArgumentInTheMiddle 2 6 ops/s 430087±2801 409115±3378 392355±5064 167569±9936 40184±244
messageThreeArgumentInTheStart 2 6 ops/s 425695±2946 422243±7029 373625±6822 168490±848 39986±586

You can validate results yourself.

Processed Results

If we take goodforgod-simple-logger as baseline and compute other loggers performance based on numbers above:

Benchmark goodforgod-simple logback log4j slf4j-simple java-system
messageAndStacktrace 100 98.0 88.6 11.3 34.2
messageWithoutArguments 100 94.8 83.6 35.2 8.7
messageOneArgumentInTheEnd 100 96.7 87.4 36.9 8.9
messageOneArgumentInTheMiddle 100 95.3 89.3 36.8 8.6
messageOneArgumentInTheStart 100 93.8 88.3 37.7 8.9
messageTwoArgumentInTheEnd 100 98.2 87.8 36.4 9.0
messageTwoArgumentInTheMiddle 100 102.3 90.2 39.0 9.6
messageTwoArgumentInTheStart 100 98.4 87.6 37.3 8.8
messageThreeArgumentInTheEnd 100 100.7 93.6 40.0 9.5
messageThreeArgumentInTheMiddle 100 95.1 91.2 39.0 9.3
messageThreeArgumentInTheStart 100 99.2 87.8 39.6 9.4

If we shrink results even more and compute average for all messages with arguments as single result then:

Benchmark goodforgod-simple logback log4j slf4j-simple java-system
message and stacktrace 100 98.0 88.6 11.3 34.2
message with arguments 100 97.5 88.7 37.8 9.1

Setup 1

Setup 2

This benchmark have forwarded stderr to NUL (/dev/null analog in windows)

Benchmark setup configuration:

  • OS: Windows 10
  • Processor: AMD Ryzen 2600X
  • Java: OpenJDK 64-Bit Server VM (build 17+35-2724, mixed mode, sharing)
  • Execution: java -jar benchmark-name.jar 2>NUL

Raw Results

Benchmark Warmup Runs Units goodforgod-simple logback log4j slf4j-simple java-system
messageAndStacktrace 2 6 ops/s 58718±669 54617±240 43765±605 2684±142 22721±262
messageWithoutArguments 2 6 ops/s 120257±34208 101818±5985 89485±12457 32231±4528 31956±747
messageOneArgumentInTheEnd 2 6 ops/s 116935±32015 93380±13191 87549±1835 43576±4416 29963±355
messageOneArgumentInTheMiddle 2 6 ops/s 137995±36420 82164±3273 90059±17408 40252±9626 30299±167
messageOneArgumentInTheStart 2 6 ops/s 100351±19414 88131±5613 92676±18736 41611±9423 30424±353
messageTwoArgumentInTheEnd 2 6 ops/s 95318±4567 85102±3035 87795±7094 44082±4324 29248±548
messageTwoArgumentInTheMiddle 2 6 ops/s 101764±13604 86166±987 96163±28330 41920±7623 30086±642
messageTwoArgumentInTheStart 2 6 ops/s 97099±14191 91736±10191 85855±4260 48236±8364 29137±518
messageThreeArgumentInTheEnd 2 6 ops/s 99141±11514 91344±8744 89784±14493 46913±3136 29543±371
messageThreeArgumentInTheMiddle 2 6 ops/s 96524±10997 90234±1231 89083±11264 38981±3724 30155±409
messageThreeArgumentInTheStart 2 6 ops/s 125277±10888 83704±1428 86095±2454 40526±13953 29521±311

Processed Results

If we take goodforgod-simple-logger as baseline and compute other loggers performance based on numbers above:

Benchmark goodforgod-simple logback log4j slf4j-simple java-system
messageAndStacktrace 100 93.0 74.5 4.6 38.7
messageWithoutArguments 100 84.7 74.4 26.8 26.6
messageOneArgumentInTheEnd 100 79.9 74.9 37.3 25.6
messageOneArgumentInTheMiddle 100 59.5 65.3 29.2 22.0
messageOneArgumentInTheStart 100 87.8 92.4 41.5 30.3
messageTwoArgumentInTheEnd 100 89.3 92.1 46.2 30.7
messageTwoArgumentInTheMiddle 100 84.7 94.5 41.2 29.6
messageTwoArgumentInTheStart 100 94.5 88.4 49.7 30.0
messageThreeArgumentInTheEnd 100 92.1 90.6 47.3 29.8
messageThreeArgumentInTheMiddle 100 93.5 92.3 40.4 31.2
messageThreeArgumentInTheStart 100 66.8 68.7 32.3 23.6

If we shrink results even more and compute average for all messages with arguments as single result then:

Benchmark goodforgod-simple logback log4j slf4j-simple java-system
message and stacktrace 100 93.0 74.5 4.6 38.7
message with arguments 100 83.3 83.3 39.2 27.9

Setup 2

Setup 3

This benchmark have forwarded stderr to NUL (/dev/null analog in windows)

Benchmark setup configuration:

  • OS: Windows 10
  • Processor: Intel i5-6200U
  • Java: OpenJDK 64-Bit Server VM (build 17.0.1+12-39, mixed mode, sharing)
  • Execution: java -jar benchmark-name.jar 2>NUL

Raw Results

Benchmark Warmup Runs Units goodforgod-simple logback log4j slf4j-simple java-system
messageAndStacktrace 2 6 ops/s 44741±1227 30574±551 28409±718 2074±166 15384±161
messageWithoutArguments 2 6 ops/s 77648±2357 72632±2107 70858±4008 33142±4502 20126±5878
messageOneArgumentInTheEnd 2 6 ops/s 75533±4976 70459±1576 67934±3651 32307±12165 20420±693
messageOneArgumentInTheMiddle 2 6 ops/s 75453±8568 71517±3054 65894±6387 31073±6345 20141±585
messageOneArgumentInTheStart 2 6 ops/s 73486±15079 66942±2062 66961±1409 31229±7186 20163±276
messageTwoArgumentInTheEnd 2 6 ops/s 75008±1818 66768±4096 65697±1048 32632±448 20421±265
messageTwoArgumentInTheMiddle 2 6 ops/s 75396±1473 69392±7265 68996±4110 30265±3249 20178±344
messageTwoArgumentInTheStart 2 6 ops/s 75785±2851 68737±4562 67683±1720 34428±996 20206±239
messageThreeArgumentInTheEnd 2 6 ops/s 75579±4230 66103±2858 66542±2149 30621±5432 20232±371
messageThreeArgumentInTheMiddle 2 6 ops/s 74463±1725 69847±1797 66406±1474 30986±4792 20311±333
messageThreeArgumentInTheStart 2 6 ops/s 75444±1727 68149±3567 66786±1621 30203±4660 20280±315

Processed Results

If we take goodforgod-simple-logger as baseline and compute other loggers performance based on numbers above:

Benchmark goodforgod-simple logback log4j slf4j-simple java-system
messageAndStacktrace 100 68.3 63.5 4.6 34.4
messageWithoutArguments 100 93.5 91.3 42.7 25.9
messageOneArgumentInTheEnd 100 93.3 89.9 42.8 27.0
messageOneArgumentInTheMiddle 100 94.8 87.3 41.2 26.7
messageOneArgumentInTheStart 100 91.1 91.1 42.5 27.4
messageTwoArgumentInTheEnd 100 89.0 87.6 43.5 27.2
messageTwoArgumentInTheMiddle 100 92.0 91.5 40.1 26.8
messageTwoArgumentInTheStart 100 90.7 89.3 45.4 26.7
messageThreeArgumentInTheEnd 100 87.5 88.0 40.5 26.8
messageThreeArgumentInTheMiddle 100 93.8 89.2 41.6 27.3
messageThreeArgumentInTheStart 100 90.3 88.5 40.0 26.9

If we shrink results even more and compute average for all messages with arguments as single result then:

Benchmark goodforgod-simple logback log4j slf4j-simple java-system
message and stacktrace 100 68.3 63.5 4.6 34.4
message with arguments 100 91.6 89.4 42.0 26.9

Setup 3

Run

In case you want to try benchmark yourself, then you should compile and package all benchmarks first:

./gradlew shadowJar

Then you can run each of them in their proper directory, for example to run goodforgod-simple-logger benchmark:

java -jar goodforgod-simple-logger/build/libs/*all.jar

If you want to suppress logger output to measure raw performance, you should redirect STRERR that logger produce to /dev/null.

java -jar goodforgod-simple-logger/build/libs/*all.jar 2>/dev/null

Configuration

You can configure the number of warmup and iterations with command line arguments, the first argument corresponds to warmups and second is for iterations:

Example below will run 1 warmup and 2 iteration:

java -jar goodforgod-simple-logger/build/libs/*all.jar 1 2