Very strange benchmark results on Ryzen (very slow) and ARM (very quick!) ?!?

[yuannan]

I'm using spdlog in a C++ application and I'm testing it on my laptop (Ryzen 7 5800H) and my phone (Qualcomm SM8550-AB Snapdragon 8 Gen 2).

I'm compiling this NixOS with Clang 18, GCC 13, repeated on Arch, as well as Ubuntu which all return similar results.

The results on Ryzen are shockingly slow compared to the the i7-4770 (the one shown in /README.md.

The i7-4770 is able to complete basic_st in around 0.17s, while my 5800H takes 1.38! That is >8X slower!

Is this benchmark data old, and spdlog has simply gotten slower over time or is my setup improperly configured?

I decided to test this on my phone with Termux and Clang 19, and the results were even more shocking. It is substaintly quicker than my 5800H by ~4 times for ./bench!

The results for async are very wacky, Ryzen speeds up by quite a bit, while Snapdragon slows down. I would only expect one general pattern. It could either speed up because now more thread are being used and the load is distributed. Or it can slow down as more thread as fighting over the same resources. However, I'm seeing both on 2 different platforms!

The results are even stranger when I do the ./latency test on both of my devices. My phone once again whoops a laptop grade CPU.

Ryzen 7 5800

[info] **************************************************************
[info] Single threaded: 1000000 messages
[info] **************************************************************
[info] basic_st                       Elapsed: 1.30 secs          768,537/sec
[info] basic_st/backtrace-on          Elapsed: 1.32 secs          758,250/sec
[info] 
[info] rotating_st                    Elapsed: 1.32 secs          760,437/sec
[info] rotating_st/backtrace-on       Elapsed: 1.34 secs          747,656/sec
[info] 
[info] daily_st                       Elapsed: 1.31 secs          764,107/sec
[info] daily_st/backtrace-on          Elapsed: 1.35 secs          743,062/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs      308,188,158/sec
[info] level-off/backtrace-on         Elapsed: 1.24 secs          808,266/sec
[info] **************************************************************
[info] Multi threaded: 1 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 1.33 secs          753,847/sec
[info] basic_mt/backtrace-on          Elapsed: 1.35 secs          743,440/sec
[info] 
[info] rotating_mt                    Elapsed: 1.32 secs          758,301/sec
[info] rotating_mt/backtrace-on       Elapsed: 1.35 secs          741,785/sec
[info] 
[info] daily_mt                       Elapsed: 1.34 secs          747,952/sec
[info] daily_mt/backtrace-on          Elapsed: 1.36 secs          733,010/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs      304,530,623/sec
[info] level-off/backtrace-on         Elapsed: 1.24 secs          806,141/sec
[info] **************************************************************
[info] Multi threaded: 4 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 0.68 secs        1,461,648/sec
[info] basic_mt/backtrace-on          Elapsed: 0.71 secs        1,403,680/sec
[info] 
[info] rotating_mt                    Elapsed: 0.73 secs        1,367,823/sec
[info] rotating_mt/backtrace-on       Elapsed: 0.75 secs        1,336,481/sec
[info] 
[info] daily_mt                       Elapsed: 0.69 secs        1,450,190/sec
[info] daily_mt/backtrace-on          Elapsed: 0.72 secs        1,392,806/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs      286,723,634/sec
[info] level-off/backtrace-on         Elapsed: 1.24 secs          804,420/sec
[info] -------------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 8
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 432 = 3456 KB 
[info] Total iters  : 3
[info] -------------------------------------------------
[info] 
[info] *********************************
[info] Queue Overflow Policy: block
[info] *********************************
[info] Elapsed: 1.172239397 secs         853068/sec
[info] Elapsed: 1.283507239 secs         779115/sec
[info] Elapsed: 1.1794687 secs   847839/sec
[info] 
[info] *********************************
[info] Queue Overflow Policy: overrun
[info] *********************************
[info] Elapsed: 0.457225272 secs         2187105/sec
[info] Elapsed: 0.554288802 secs         1804113/sec
[info] Elapsed: 0.497242335 secs         2011091/sec
2024-10-14T19:08:36+01:00
Running ./latency
Run on (16 X 4114.45 MHz CPU s)
CPU Caches:
  L1 Data 32 KiB (x8)
  L1 Instruction 32 KiB (x8)
  L2 Unified 512 KiB (x8)
  L3 Unified 16384 KiB (x1)
Load Average: 2.87, 2.01, 1.41
------------------------------------------------------------------------------------
Benchmark                                          Time             CPU   Iterations
------------------------------------------------------------------------------------
disabled-at-compile-time                       0.000 ns        0.000 ns   1000000000
disabled-at-compile-time (global logger)       0.000 ns        0.000 ns   1000000000
disabled-at-runtime                             3.29 ns         3.29 ns    217568010
disabled-at-runtime (global logger)             3.85 ns         3.85 ns    178092907
disabled-at-runtime/backtrace                   1283 ns         1283 ns       545817
null_sink_st (500_bytes c_str)                  1149 ns         1149 ns       605978
null_sink_st                                    1243 ns         1243 ns       564719
null_sink_st (global logger)                    1237 ns         1237 ns       563155
null_sink_st/backtrace                          1281 ns         1281 ns       546279
/dev/null_st/real_time                          1304 ns         1304 ns       536711
/dev/null_mt/real_time                          1310 ns         1310 ns       534305
async_logger/real_time/threads:16                531 ns         5472 ns      1330112
async_logger/tracing/real_time/threads:16        540 ns         5522 ns      1218352

Snapdragon 8 Gen 2

[info] **************************************************************
[info] Single threaded: 1000000 messages
[info] **************************************************************
[info] basic_st                       Elapsed: 0.39 secs          2570478/sec
[info] basic_st/backtrace-on          Elapsed: 0.40 secs          2519454/sec
[info] 
[info] rotating_st                    Elapsed: 0.36 secs          2757159/sec
[info] rotating_st/backtrace-on       Elapsed: 0.40 secs          2511073/sec
[info] 
[info] daily_st                       Elapsed: 0.30 secs          3317735/sec
[info] daily_st/backtrace-on          Elapsed: 0.33 secs          2986583/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs        343452001/sec
[info] level-off/backtrace-on         Elapsed: 0.20 secs          5120872/sec
[info] **************************************************************
[info] Multi threaded: 1 threads, 1000000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 0.37 secs          2721741/sec
[info] basic_mt/backtrace-on          Elapsed: 0.40 secs          2509725/sec
[info] 
[info] rotating_mt                    Elapsed: 0.33 secs          3002592/sec
[info] rotating_mt/backtrace-on       Elapsed: 0.41 secs          2444274/sec
[info] 
[info] daily_mt                       Elapsed: 0.33 secs          3007027/sec
[info] daily_mt/backtrace-on          Elapsed: 0.46 secs          2179975/sec
[info] 
[info] level-off                      Elapsed: 0.01 secs        106177660/sec
[info] level-off/backtrace-on         Elapsed: 0.19 secs          5251595/sec
[info] **************************************************************
[info] Multi threaded: 4 threads, 1000000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 1.34 secs           746489/sec
[info] basic_mt/backtrace-on          Elapsed: 1.52 secs           656308/sec
[info] 
[info] rotating_mt                    Elapsed: 1.30 secs           769744/sec
[info] rotating_mt/backtrace-on       Elapsed: 1.56 secs           640529/sec
[info] 
[info] daily_mt                       Elapsed: 1.25 secs           800257/sec
[info] daily_mt/backtrace-on          Elapsed: 1.29 secs           776797/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs        219190573/sec
[info] level-off/backtrace-on         Elapsed: 0.19 secs          5265406/sec
[info] -------------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 8
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 416 = 3328 KB 
[info] Total iters  : 3
[info] -------------------------------------------------
[info] 
[info] *********************************
[info] Queue Overflow Policy: block
[info] *********************************
[info] Elapsed: 3.294561093 secs         303530/sec
[info] Elapsed: 3.282163123 secs         304677/sec
[info] Elapsed: 3.291099009 secs         303849/sec
[info] 
[info] *********************************
[info] Queue Overflow Policy: overrun
[info] *********************************
[info] Elapsed: 0.779369271 secs         1283088/sec
[info] Elapsed: 0.767421042 secs         1303065/sec
[info] Elapsed: 0.768563073 secs         1301129/sec
2024-10-14T19:13:41+01:00
Running ./latency
Run on (8 X 2016 MHz CPU s)
***WARNING*** CPU scaling is enabled, the benchmark real time measurements may be noisy and will incur extra overhead.
-----------------------------------------------------------------------------------
Benchmark                                         Time             CPU   Iterations
-----------------------------------------------------------------------------------
disabled-at-compile-time                      0.000 ns        0.000 ns   1000000000
disabled-at-compile-time (global logger)      0.000 ns        0.000 ns   1000000000
disabled-at-runtime                            2.80 ns         2.79 ns    258485544
disabled-at-runtime (global logger)            4.98 ns         4.96 ns    138678650
disabled-at-runtime/backtrace                   230 ns          229 ns      2931826
null_sink_st (500_bytes c_str)                 78.1 ns         77.7 ns      9184915
null_sink_st                                    191 ns          191 ns      3478164
null_sink_st (global logger)                    193 ns          192 ns      3683067
null_sink_st/backtrace                          220 ns          219 ns      3232640
/dev/null_st/real_time                          275 ns          274 ns      2549217
/dev/null_mt/real_time                          291 ns          291 ns      2423830
async_logger/real_time/threads:8                914 ns         3461 ns       828424
async_logger/tracing/real_time/threads:8       1179 ns         4044 ns       648880

All of this has left me with more questions than answers, does anyone know why my laptop seems to have such lackluster performance, and is this worth opening a bug report?

I would really appreciate if others can run the bencmarks on their systems and what differences you experience.

This is what I did to get the benchmarks to run:

cd $(mktemp -d) &&
git clone https://github.com/gabime/spdlog.git &&
cd spdlog &&
mkdir build &&
cd build &&
cmake .. -D SPDLOG_BUILD_BENCH=ON &&
make -j &&
cd bench &&
./bench 1000000 &&
./async_bench 1000000 8 &&
./latency

[tt4g]

It could be a bug in Clang, you could try to measure the performance with GCC.

[yuannan]

I tried it with NixOS, Arch, and Ubuntu on Clang and GCC. Pretty sure it's my hardware or spdlog.

What results do you get when you run the benchmarks, and what hard ware do you have? I'd really appreciate it.

[tt4g]

Now I do not have a machine running a UNIX OS running directly on the hardware.
I can check the performance with UNIX on a virtual machine, but that would not be comparable.

[tt4g]

It may be helpful to use time, iostat, or dstat to see where the bottleneck is in the hardware, I/O, or program to isolate the cause.

[tt4g]

BTW, you are measuring benchmarks with debug builds.
It would be better to measure benchmarks on release builds.

 cd $(mktemp -d) &&
 git clone https://github.com/gabime/spdlog.git &&
 cd spdlog &&
 mkdir build &&
 cd build &&
-cmake .. -D SPDLOG_BUILD_BENCH=ON &&
+cmake .. -DCMAKE_BUILD_TYPE=Release -D SPDLOG_BUILD_BENCH=ON &&
 make -j &&
 cd bench &&
 ./bench 1000000 &&
 ./async_bench 1000000 8 &&
 ./latency

[gabime]

@yuannan Did building with DEBUG caused the problem?

[yuannan]

I've tried it explicitely with the "Release" flag which has the original results.

Here is the log for the "Debug" build

Debug Build R7 5800H

cd $(mktemp -d) &&
git clone https://github.com/gabime/spdlog.git &&
cd spdlog &&     
mkdir build &&
cd build &&   
cmake .. -D SPDLOG_BUILD_BENCH=ON -DCMAKE_BUILD_TYPE=Debug &&  
make -j &&
cd bench &&
./bench 1000000 &&
./async_bench 1000000 8 &&
./latency
Cloning into 'spdlog'...
remote: Enumerating objects: 28681, done.
remote: Counting objects: 100% (1136/1136), done.
remote: Compressing objects: 100% (451/451), done.
remote: Total 28681 (delta 689), reused 962 (delta 585), pack-reused 27545 (from 1)
Receiving objects: 100% (28681/28681), 41.32 MiB | 21.16 MiB/s, done.
Resolving deltas: 100% (19128/19128), done.
-- The CXX compiler identification is Clang 18.1.8
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- Check for working CXX compiler: /home/emperor/.nix-profile/bin/c++ - skipped
-- Detecting CXX compile features
-- Detecting CXX compile features - done
-- Build spdlog: 1.14.1
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Success
-- Found Threads: TRUE
-- Build type: Debug
-- Generating example(s)
-- Generating benchmarks
-- Could NOT find benchmark (missing: benchmark_DIR)
-- Using CMake Version 3.29.6
-- Downloading GoogleBenchmark
-- Failed to find LLVM FileCheck
-- Found Git: /run/current-system/sw/bin/git (found version "2.46.1")
-- git version: v1.6.0 normalized to 1.6.0
-- Version: 1.6.0
-- Performing Test HAVE_CXX_FLAG_STD_CXX11
-- Performing Test HAVE_CXX_FLAG_STD_CXX11 - Success
-- Performing Test HAVE_CXX_FLAG_WALL
-- Performing Test HAVE_CXX_FLAG_WALL - Success
-- Performing Test HAVE_CXX_FLAG_WEXTRA
-- Performing Test HAVE_CXX_FLAG_WEXTRA - Success
-- Performing Test HAVE_CXX_FLAG_WSHADOW
-- Performing Test HAVE_CXX_FLAG_WSHADOW - Success
-- Performing Test HAVE_CXX_FLAG_WERROR
-- Performing Test HAVE_CXX_FLAG_WERROR - Success
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC
-- Performing Test HAVE_CXX_FLAG_PEDANTIC - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS - Success
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32 - Success
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED - Success
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WD654
-- Performing Test HAVE_CXX_FLAG_WD654 - Failed
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY - Success
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES -- failed to compile
-- Performing Test HAVE_CXX_FLAG_COVERAGE
-- Performing Test HAVE_CXX_FLAG_COVERAGE - Success
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX -- success
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX -- failed to compile
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX -- success
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK -- success
-- Generating install
-- Configuring done (6.5s)
-- Generating done (0.0s)
-- Build files have been written to: /tmp/tmp.T9YJI0hSX9/spdlog/build
[ 15%] Building CXX object CMakeFiles/spdlog.dir/src/stdout_sinks.cpp.o
[ 15%] Building CXX object CMakeFiles/spdlog.dir/src/async.cpp.o
[  7%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_name.cc.o
[  7%] Building CXX object CMakeFiles/spdlog.dir/src/color_sinks.cpp.o
[ 15%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_register.cc.o
[ 12%] Building CXX object CMakeFiles/spdlog.dir/src/spdlog.cpp.o
[ 17%] Building CXX object CMakeFiles/spdlog.dir/src/bundled_fmtlib_format.cpp.o
[ 20%] Building CXX object CMakeFiles/spdlog.dir/src/file_sinks.cpp.o
[ 22%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/colorprint.cc.o
[ 25%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/commandlineflags.cc.o
[ 30%] Building CXX object CMakeFiles/spdlog.dir/src/cfg.cpp.o
[ 30%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_runner.cc.o
[ 32%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/complexity.cc.o
[ 35%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_api_internal.cc.o
[ 37%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark.cc.o
[ 40%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/console_reporter.cc.o
[ 42%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/csv_reporter.cc.o
[ 45%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/json_reporter.cc.o
[ 47%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/counter.cc.o
[ 50%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/perf_counters.cc.o
[ 52%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/reporter.cc.o
[ 55%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/string_util.cc.o
[ 57%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sysinfo.cc.o
[ 60%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/timers.cc.o
[ 62%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sleep.cc.o
[ 65%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/statistics.cc.o
[ 67%] Linking CXX static library libbenchmark.a
[ 67%] Built target benchmark
[ 70%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark_main.dir/benchmark_main.cc.o
[ 72%] Linking CXX static library libbenchmark_main.a
[ 72%] Built target benchmark_main
[ 75%] Linking CXX static library libspdlogd.a
[ 75%] Built target spdlog
[ 82%] Building CXX object bench/CMakeFiles/async_bench.dir/async_bench.cpp.o
[ 85%] Building CXX object example/CMakeFiles/example.dir/example.cpp.o
[ 87%] Building CXX object bench/CMakeFiles/latency.dir/latency.cpp.o
[ 85%] Building CXX object bench/CMakeFiles/bench.dir/bench.cpp.o
[ 87%] Building CXX object bench/CMakeFiles/formatter-bench.dir/formatter-bench.cpp.o
[ 90%] Linking CXX executable formatter-bench
[ 92%] Linking CXX executable async_bench
[ 92%] Built target formatter-bench
[ 95%] Linking CXX executable bench
[ 95%] Built target async_bench
[ 97%] Linking CXX executable latency
[ 97%] Built target bench
[ 97%] Built target latency
[100%] Linking CXX executable example
[100%] Built target example
[info] **************************************************************
[info] Single threaded: 1000000 messages
[info] **************************************************************
[info] basic_st                       Elapsed: 2.70 secs          370,994/sec
[info] basic_st/backtrace-on          Elapsed: 2.70 secs          369,748/sec
[info] 
[info] rotating_st                    Elapsed: 2.70 secs          370,702/sec
[info] rotating_st/backtrace-on       Elapsed: 2.98 secs          335,342/sec
[info] 
[info] daily_st                       Elapsed: 2.71 secs          368,333/sec
[info] daily_st/backtrace-on          Elapsed: 3.02 secs          331,620/sec
[info] 
[info] level-off                      Elapsed: 0.04 secs       27,043,324/sec
[info] level-off/backtrace-on         Elapsed: 2.22 secs          451,358/sec
[info] **************************************************************
[info] Multi threaded: 1 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 2.69 secs          372,177/sec
[info] basic_mt/backtrace-on          Elapsed: 2.96 secs          338,257/sec
[info] 
[info] rotating_mt                    Elapsed: 2.70 secs          370,171/sec
[info] rotating_mt/backtrace-on       Elapsed: 2.98 secs          335,739/sec
[info] 
[info] daily_mt                       Elapsed: 2.71 secs          368,546/sec
[info] daily_mt/backtrace-on          Elapsed: 2.98 secs          335,749/sec
[info] 
[info] level-off                      Elapsed: 0.04 secs       26,480,115/sec
[info] level-off/backtrace-on         Elapsed: 2.22 secs          450,832/sec
[info] **************************************************************
[info] Multi threaded: 4 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 1.65 secs          607,105/sec
[info] basic_mt/backtrace-on          Elapsed: 1.86 secs          538,224/sec
[info] 
[info] rotating_mt                    Elapsed: 1.72 secs          582,686/sec
[info] rotating_mt/backtrace-on       Elapsed: 1.86 secs          536,409/sec
[info] 
[info] daily_mt                       Elapsed: 1.73 secs          576,613/sec
[info] daily_mt/backtrace-on          Elapsed: 1.90 secs          525,485/sec
[info] 
[info] level-off                      Elapsed: 0.04 secs       26,421,039/sec
[info] level-off/backtrace-on         Elapsed: 2.22 secs          449,870/sec
[info] -------------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 8
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 432 = 3456 KB 
[info] Total iters  : 3
[info] -------------------------------------------------
[info] 
[info] *********************************
[info] Queue Overflow Policy: block
[info] *********************************
[info] Elapsed: 4.084819746 secs         244808/sec
[info] Elapsed: 4.041585194 secs         247427/sec
[info] Elapsed: 4.061591803 secs         246208/sec
[info] 
[info] *********************************
[info] Queue Overflow Policy: overrun
[info] *********************************
[info] Elapsed: 1.213404935 secs         824127/sec
[info] Elapsed: 1.229155298 secs         813566/sec
[info] Elapsed: 1.205088417 secs         829814/sec
2024-10-17T13:47:47+01:00
Running ./latency
Run on (16 X 4463 MHz CPU s)
CPU Caches:
  L1 Data 32 KiB (x8)
  L1 Instruction 32 KiB (x8)
  L2 Unified 512 KiB (x8)
  L3 Unified 16384 KiB (x1)
Load Average: 1.69, 0.84, 0.66
***WARNING*** CPU scaling is enabled, the benchmark real time measurements may be noisy and will incur extra overhead.
***WARNING*** Library was built as DEBUG. Timings may be affected.
------------------------------------------------------------------------------------
Benchmark                                          Time             CPU   Iterations
------------------------------------------------------------------------------------
disabled-at-compile-time                        1.91 ns         1.91 ns    371783188
disabled-at-compile-time (global logger)        1.89 ns         1.89 ns    360847790
disabled-at-runtime                             39.8 ns         39.8 ns     17837556
disabled-at-runtime (global logger)             58.3 ns         58.3 ns     11980928
disabled-at-runtime/backtrace                   2542 ns         2542 ns       275690
null_sink_st (500_bytes c_str)                  1314 ns         1314 ns       532814
null_sink_st                                    2281 ns         2280 ns       308419
null_sink_st (global logger)                    2281 ns         2280 ns       308369
null_sink_st/backtrace                          2557 ns         2557 ns       275188
/dev/null_st/real_time                          2910 ns         2910 ns       241339
/dev/null_mt/real_time                          2914 ns         2913 ns       241163
async_logger/real_time/threads:16               1279 ns         7890 ns       550672
async_logger/tracing/real_time/threads:16       1336 ns         9153 ns       522416

[yuannan]

The debug bug is significantly slower than the Release build which is to be expected. The results that stick out to me are that even the ones disabled at compile time are now taking some time process.

[yuannan]

The results for the debug build on my phone are slower which are to be expected, however, it is still faster than my laptop in certain cases. The gap is much closer, and more in line what result should be.

SD8-G2 Debug Build

cd $(mktemp -d) &&
git clone https://github.com/gabime/spdlog.git &&
cd spdlog &&
mkdir build &&
cd build &&
cmake .. -D SPDLOG_BUILD_BENCH=ON -DCMAKE_BUILD_TYPE=Debug &&
make -j &&
cd bench &&
./bench 1000000 &&
./async_bench 1000000 8 &&
./latency

Cloning into 'spdlog'...
remote: Enumerating objects: 28681, done.
remote: Counting objects: 100% (1136/1136), done.
remote: Compressing objects: 100% (451/451), done.
remote: Total 28681 (delta 689), reused 962 (delta 585), pack-reused 27545 (from 1)
Receiving objects: 100% (28681/28681), 41.32 MiB | 25.16 MiB/s, done.
Resolving deltas: 100% (19128/19128), done.
-- The CXX compiler identification is Clang 19.1.1
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- Check for working CXX compiler: /data/data/com.termux/files/usr/bin/c++ - skipped
-- Detecting CXX compile features
-- Detecting CXX compile features - done
-- Build spdlog: 1.14.1
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Failed
-- Looking for pthread_create in pthreads
-- Looking for pthread_create in pthreads - not found
-- Looking for pthread_create in pthread
-- Looking for pthread_create in pthread - found
-- Found Threads: TRUE
-- Build type: Debug
-- Generating example(s)
-- Generating benchmarks
-- Could NOT find benchmark (missing: benchmark_DIR)
-- Using CMake Version 3.30.5
-- Downloading GoogleBenchmark
-- Found Git: /data/data/com.termux/files/usr/bin/git (found version "2.47.0")
-- git version: v1.6.0 normalized to 1.6.0
-- Version: 1.6.0
-- Performing Test HAVE_CXX_FLAG_STD_CXX11
-- Performing Test HAVE_CXX_FLAG_STD_CXX11 - Success
-- Performing Test HAVE_CXX_FLAG_WALL
-- Performing Test HAVE_CXX_FLAG_WALL - Success
-- Performing Test HAVE_CXX_FLAG_WEXTRA
-- Performing Test HAVE_CXX_FLAG_WEXTRA - Success
-- Performing Test HAVE_CXX_FLAG_WSHADOW
-- Performing Test HAVE_CXX_FLAG_WSHADOW - Success
-- Performing Test HAVE_CXX_FLAG_WERROR
-- Performing Test HAVE_CXX_FLAG_WERROR - Success
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC
-- Performing Test HAVE_CXX_FLAG_PEDANTIC - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS - Success
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32 - Success
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED - Success
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WD654
-- Performing Test HAVE_CXX_FLAG_WD654 - Failed
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY - Success
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES -- failed to compile
-- Performing Test HAVE_CXX_FLAG_COVERAGE
-- Performing Test HAVE_CXX_FLAG_COVERAGE - Success
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX -- success
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX -- failed to compile
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX -- success
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK -- success
-- Check if compiler accepts -pthread
-- Check if compiler accepts -pthread - yes
-- Generating install
-- Configuring done (13.0s)
-- Generating done (0.0s)
-- Build files have been written to: /data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/build
[  2%] Building CXX object CMakeFiles/spdlog.dir/src/color_sinks.cpp.o
[  5%] Building CXX object CMakeFiles/spdlog.dir/src/stdout_sinks.cpp.o
[  7%] Building CXX object CMakeFiles/spdlog.dir/src/spdlog.cpp.o
[ 10%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark.cc.o
[ 12%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_api_internal.cc.o
[ 15%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_name.cc.o
[ 17%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_register.cc.o
[ 20%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_runner.cc.o
[ 22%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/colorprint.cc.o
[ 25%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/commandlineflags.cc.o
[ 27%] Building CXX object CMakeFiles/spdlog.dir/src/bundled_fmtlib_format.cpp.o
[ 30%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/complexity.cc.o
[ 32%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/console_reporter.cc.o
[ 35%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/counter.cc.o
[ 37%] Building CXX object CMakeFiles/spdlog.dir/src/file_sinks.cpp.o
[ 40%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/csv_reporter.cc.o
[ 42%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sleep.cc.o
[ 45%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/perf_counters.cc.o
[ 47%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/reporter.cc.o
[ 50%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/json_reporter.cc.o
[ 52%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/string_util.cc.o
[ 55%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sysinfo.cc.o
[ 57%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/statistics.cc.o
[ 60%] Building CXX object CMakeFiles/spdlog.dir/src/cfg.cpp.o
[ 62%] Building CXX object CMakeFiles/spdlog.dir/src/async.cpp.o
[ 65%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/timers.cc.o
In file included from /data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/src/color_sinks.cpp:8:
In file included from /data/data/com.termux/files/usr/include/c++/v1/mutex:192:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__condition_variable/condition_variable.h:17:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__mutex/unique_lock.h:17:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__system_error/system_error.h:14:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__system_error/error_category.h:15:
In file included from /data/data/com.termux/files/usr/include/c++/v1/string:625:
In file included from /data/data/com.termux/files/usr/include/c++/v1/string_view:213:
/data/data/com.termux/files/usr/include/c++/v1/__fwd/string_view.h:22:41: warning: 'char_traits<fmt::detail::char8_type>' is deprecated: char_traits<T> for T not equal to char, wchar_t, char8_t, char16_t or char32_t is non-standard and is provided for a temporary period. It will be removed in LLVM 19, so please migrate off of it. [-Wdeprecated-declarations]
   22 | template <class _CharT, class _Traits = char_traits<_CharT> >
      |                                         ^
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/core.h:361:26: note: in instantiation of default argument for 'basic_string_view<fmt::detail::char8_type>' required here
  361 | template <typename Char> using std_string_view = std::basic_string_view<Char>;
      |                          ^~~~~
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/core.h:452:50: note: in instantiation of template type alias 'std_string_view' requested here
  452 |                                       S, detail::std_string_view<Char>>::value)>
      |                                                  ^
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/format.h:737:57: note: in instantiation of template class 'fmt::basic_string_view<fmt::detail::char8_type>' requested here
  737 | inline auto compute_width(basic_string_view<char8_type> s) -> size_t {
      |                                                         ^
/data/data/com.termux/files/usr/include/c++/v1/__string/char_traits.h:81:8: note: 'char_traits<fmt::detail::char8_type>' has been explicitly marked deprecated here
   81 | struct _LIBCPP_DEPRECATED_(
      |        ^
/data/data/com.termux/files/usr/include/c++/v1/__config:916:53: note: expanded from macro '_LIBCPP_DEPRECATED_'
  916 | #      define _LIBCPP_DEPRECATED_(m) __attribute__((__deprecated__(m)))
      |                                                     ^
In file included from /data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/src/stdout_sinks.cpp:8:
In file included from /data/data/com.termux/files/usr/include/c++/v1/mutex:192:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__condition_variable/condition_variable.h:17:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__mutex/unique_lock.h:17:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__system_error/system_error.h:14:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__system_error/error_category.h:15:
In file included from /data/data/com.termux/files/usr/include/c++/v1/string:625:
In file included from /data/data/com.termux/files/usr/include/c++/v1/string_view:213:
/data/data/com.termux/files/usr/include/c++/v1/__fwd/string_view.h:22:41: warning: 'char_traits<fmt::detail::char8_type>' is deprecated: char_traits<T> for T not equal to char, wchar_t, char8_t, char16_t or char32_t is non-standard and is provided for a temporary period. It will be removed in LLVM 19, so please migrate off of it. [-Wdeprecated-declarations]
   22 | template <class _CharT, class _Traits = char_traits<_CharT> >
      |                                         ^
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/core.h:361:26: note: in instantiation of default argument for 'basic_string_view<fmt::detail::char8_type>' required here
  361 | template <typename Char> using std_string_view = std::basic_string_view<Char>;
      |                          ^~~~~
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/core.h:452:50: note: in instantiation of template type alias 'std_string_view' requested here
  452 |                                       S, detail::std_string_view<Char>>::value)>
      |                                                  ^
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/format.h:737:57: note: in instantiation of template class 'fmt::basic_string_view<fmt::detail::char8_type>' requested here
  737 | inline auto compute_width(basic_string_view<char8_type> s) -> size_t {
      |                                                         ^
/data/data/com.termux/files/usr/include/c++/v1/__string/char_traits.h:81:8: note: 'char_traits<fmt::detail::char8_type>' has been explicitly marked deprecated here
   81 | struct _LIBCPP_DEPRECATED_(
      |        ^
/data/data/com.termux/files/usr/include/c++/v1/__config:916:53: note: expanded from macro '_LIBCPP_DEPRECATED_'
  916 | #      define _LIBCPP_DEPRECATED_(m) __attribute__((__deprecated__(m)))
      |                                                     ^
In file included from /data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/src/bundled_fmtlib_format.cpp:11:
In file included from /data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/format-inl.h:18:
In file included from /data/data/com.termux/files/usr/include/c++/v1/locale:202:
In file included from /data/data/com.termux/files/usr/include/c++/v1/__locale:23:
In file included from /data/data/com.termux/files/usr/include/c++/v1/string:625:
In file included from /data/data/com.termux/files/usr/include/c++/v1/string_view:213:
/data/data/com.termux/files/usr/include/c++/v1/__fwd/string_view.h:22:41: warning: 'char_traits<fmt::detail::char8_type>' is deprecated: char_traits<T> for T not equal to char, wchar_t, char8_t, char16_t or char32_t is non-standard and is provided for a temporary period. It will be removed in LLVM 19, so please migrate off of it. [-Wdeprecated-declarations]
   22 | template <class _CharT, class _Traits = char_traits<_CharT> >
      |                                         ^
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/core.h:361:26: note: in instantiation of default argument for 'basic_string_view<fmt::detail::char8_type>' required here
  361 | template <typename Char> using std_string_view = std::basic_string_view<Char>;
      |                          ^~~~~
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/core.h:452:50: note: in instantiation of template type alias 'std_string_view' requested here
  452 |                                       S, detail::std_string_view<Char>>::value)>
      |                                                  ^
/data/data/com.termux/files/usr/tmp/tmp.tBJCAXm8pD/spdlog/include/spdlog/fmt/bundled/format.h:737:57: note: in instantiation of template class 'fmt::basic_string_view<fmt::detail::char8_type>' requested here
  737 | inline auto compute_width(basic_string_view<char8_type> s) -> size_t {
      |                                                         ^
/data/data/com.termux/files/usr/include/c++/v1/__string/char_traits.h:81:8: note: 'char_traits<fmt::detail::char8_type>' has been explicitly marked deprecated here
   81 | struct _LIBCPP_DEPRECATED_(
      |        ^
/data/data/com.termux/files/usr/include/c++/v1/__config:916:53: note: expanded from macro '_LIBCPP_DEPRECATED_'
  916 | #      define _LIBCPP_DEPRECATED_(m) __attribute__((__deprecated__(m)))
      |                                                     ^
1 warning generated.
1 warning generated.
1 warning generated.
[ 67%] Linking CXX static library libspdlogd.a
[ 70%] Linking CXX static library libbenchmark.a
[ 70%] Built target spdlog
[ 72%] Building CXX object bench/CMakeFiles/async_bench.dir/async_bench.cpp.o
[ 75%] Building CXX object bench/CMakeFiles/bench.dir/bench.cpp.o
[ 77%] Building CXX object example/CMakeFiles/example.dir/example.cpp.o
[ 77%] Built target benchmark
[ 80%] Building CXX object bench/CMakeFiles/formatter-bench.dir/formatter-bench.cpp.o
[ 82%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark_main.dir/benchmark_main.cc.o
[ 85%] Building CXX object bench/CMakeFiles/latency.dir/latency.cpp.o
[ 87%] Linking CXX executable async_bench
[ 90%] Linking CXX static library libbenchmark_main.a
[ 90%] Built target async_bench
[ 90%] Built target benchmark_main
[ 92%] Linking CXX executable formatter-bench
[ 92%] Built target formatter-bench
[ 95%] Linking CXX executable bench
[ 95%] Built target bench
[ 97%] Linking CXX executable latency
[ 97%] Built target latency
[100%] Linking CXX executable example
[100%] Built target example
[info] **************************************************************
[info] Single threaded: 1000000 messages
[info] **************************************************************
[info] basic_st                       Elapsed: 2.43 secs           410865/sec
[info] basic_st/backtrace-on          Elapsed: 2.63 secs           379964/sec
[info] 
[info] rotating_st                    Elapsed: 2.46 secs           406905/sec
[info] rotating_st/backtrace-on       Elapsed: 3.18 secs           314384/sec
[info] 
[info] daily_st                       Elapsed: 2.53 secs           394860/sec
[info] daily_st/backtrace-on          Elapsed: 3.14 secs           318399/sec
[info] 
[info] level-off                      Elapsed: 0.07 secs         15287220/sec
[info] level-off/backtrace-on         Elapsed: 2.01 secs           497909/sec
[info] **************************************************************
[info] Multi threaded: 1 threads, 1000000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 2.46 secs           407318/sec
[info] basic_mt/backtrace-on          Elapsed: 3.07 secs           326238/sec
[info] 
[info] rotating_mt                    Elapsed: 2.48 secs           403547/sec
[info] rotating_mt/backtrace-on       Elapsed: 3.10 secs           322145/sec
[info] 
[info] daily_mt                       Elapsed: 2.46 secs           407015/sec
[info] daily_mt/backtrace-on          Elapsed: 3.07 secs           325918/sec
[info] 
[info] level-off                      Elapsed: 0.07 secs         14817970/sec
[info] level-off/backtrace-on         Elapsed: 1.81 secs           551500/sec
[info] **************************************************************
[info] Multi threaded: 4 threads, 1000000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 5.05 secs           197873/sec
[info] basic_mt/backtrace-on          Elapsed: 5.11 secs           195627/sec
[info] 
[info] rotating_mt                    Elapsed: 5.34 secs           187140/sec
[info] rotating_mt/backtrace-on       Elapsed: 4.21 secs           237284/sec
[info] 
[info] daily_mt                       Elapsed: 6.03 secs           165931/sec
[info] daily_mt/backtrace-on          Elapsed: 4.00 secs           250089/sec
[info] 
[info] level-off                      Elapsed: 0.08 secs         12516599/sec
[info] level-off/backtrace-on         Elapsed: 1.79 secs           558402/sec
[info] -------------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 8
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 416 = 3328 KB 
[info] Total iters  : 3
[info] -------------------------------------------------
[info] 
[info] *********************************
[info] Queue Overflow Policy: block
[info] *********************************
[info] Elapsed: 4.988224946 secs         200472/sec
[info] Elapsed: 5.197078175 secs         192415/sec
[info] Elapsed: 5.231434269 secs         191152/sec
[info] 
[info] *********************************
[info] Queue Overflow Policy: overrun
[info] *********************************
[info] Elapsed: 1.741754583 secs         574133/sec
[info] Elapsed: 1.863006406 secs         536766/sec
[info] Elapsed: 1.953893541 secs         511798/sec
2024-10-17T13:52:44+01:00
Running ./latency
Run on (8 X 2016 MHz CPU s)
***WARNING*** CPU scaling is enabled, the benchmark real time measurements may be noisy and will incur extra overhead.
***WARNING*** Library was built as DEBUG. Timings may be affected.
-----------------------------------------------------------------------------------
Benchmark                                         Time             CPU   Iterations
-----------------------------------------------------------------------------------
disabled-at-compile-time                       3.91 ns         3.90 ns    187581621
disabled-at-compile-time (global logger)       4.55 ns         4.54 ns    150516765
disabled-at-runtime                            85.3 ns         85.1 ns      8564033
disabled-at-runtime (global logger)             102 ns          102 ns      7111631
disabled-at-runtime/backtrace                  2433 ns         2422 ns       278285
null_sink_st (500_bytes c_str)                  302 ns          301 ns      2355431
null_sink_st                                   1792 ns         1784 ns       382284
null_sink_st (global logger)                   1807 ns         1800 ns       385780
null_sink_st/backtrace                         2331 ns         2320 ns       305652
/dev/null_st/real_time                         3016 ns         3002 ns       245006
/dev/null_mt/real_time                         3034 ns         3020 ns       243193
async_logger/real_time/threads:8               2275 ns         8690 ns       329640
async_logger/tracing/real_time/threads:8       3304 ns        12143 ns       232304

[yuannan]

Interestingly, GCC 13 doesn't slow down the debug build, and Clang 19 doesn't slow down as much on the Debug build.

GCC 13 Debug Build

cd $(mktemp -d) &&
git clone https://github.com/gabime/spdlog.git &&
cd spdlog &&
mkdir build &&
cd build &&
cmake .. -D SPDLOG_BUILD_BENCH=ON -DCMAKE_BUILD_TYPE=Debug &&
make -j &&
cd bench &&
./bench 1000000 &&
./async_bench 1000000 8 &&
./latency
Cloning into 'spdlog'...
remote: Enumerating objects: 28681, done.
remote: Counting objects: 100% (1136/1136), done.
remote: Compressing objects: 100% (450/450), done.
remote: Total 28681 (delta 689), reused 959 (delta 586), pack-reused 27545 (from 1)
Receiving objects: 100% (28681/28681), 41.43 MiB | 19.97 MiB/s, done.
Resolving deltas: 100% (19117/19117), done.
-- The CXX compiler identification is GNU 13.3.0
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- Check for working CXX compiler: /nix/store/vh9fsdhgxcnab2qk7vdp2palkkn6j3cp-gcc-wrapper-13.3.0/bin/g++ - skipped
-- Detecting CXX compile features
-- Detecting CXX compile features - done
-- Build spdlog: 1.14.1
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Success
-- Found Threads: TRUE
-- Build type: Debug
-- Generating example(s)
-- Generating benchmarks
-- Could NOT find benchmark (missing: benchmark_DIR)
-- Using CMake Version 3.29.6
-- Downloading GoogleBenchmark
-- LLVM FileCheck Found: /nix/store/fhyq9fjj1p7h9afx1pcbxb3wclib4sxj-llvm-19.1.1/bin/FileCheck
-- Found Git: /run/current-system/sw/bin/git (found version "2.46.1")
-- git version: v1.6.0 normalized to 1.6.0
-- Version: 1.6.0
-- Performing Test HAVE_CXX_FLAG_STD_CXX11
-- Performing Test HAVE_CXX_FLAG_STD_CXX11 - Success
-- Performing Test HAVE_CXX_FLAG_WALL
-- Performing Test HAVE_CXX_FLAG_WALL - Success
-- Performing Test HAVE_CXX_FLAG_WEXTRA
-- Performing Test HAVE_CXX_FLAG_WEXTRA - Success
-- Performing Test HAVE_CXX_FLAG_WSHADOW
-- Performing Test HAVE_CXX_FLAG_WSHADOW - Success
-- Performing Test HAVE_CXX_FLAG_WERROR
-- Performing Test HAVE_CXX_FLAG_WERROR - Success
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC
-- Performing Test HAVE_CXX_FLAG_PEDANTIC - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS - Success
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32 - Failed
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED - Success
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WD654
-- Performing Test HAVE_CXX_FLAG_WD654 - Failed
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY - Failed
-- Performing Test HAVE_CXX_FLAG_COVERAGE
-- Performing Test HAVE_CXX_FLAG_COVERAGE - Success
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX -- success
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX -- failed to compile
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX -- success
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK -- success
-- Generating install
-- Configuring done (6.8s)
-- Generating done (0.0s)
-- Build files have been written to: /tmp/tmp.JEgrOBScCX/spdlog/build
[ 12%] Building CXX object CMakeFiles/spdlog.dir/src/stdout_sinks.cpp.o
[ 10%] Building CXX object CMakeFiles/spdlog.dir/src/color_sinks.cpp.o
[ 12%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark.cc.o
[ 12%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_register.cc.o
[ 10%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_name.cc.o
[ 15%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_runner.cc.o
[ 17%] Building CXX object CMakeFiles/spdlog.dir/src/cfg.cpp.o
[ 20%] Building CXX object CMakeFiles/spdlog.dir/src/spdlog.cpp.o
[ 22%] Building CXX object CMakeFiles/spdlog.dir/src/bundled_fmtlib_format.cpp.o
[ 25%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/commandlineflags.cc.o
[ 27%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_api_internal.cc.o
[ 30%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/complexity.cc.o
[ 32%] Building CXX object CMakeFiles/spdlog.dir/src/async.cpp.o
[ 35%] Building CXX object CMakeFiles/spdlog.dir/src/file_sinks.cpp.o
[ 37%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/colorprint.cc.o
[ 40%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/console_reporter.cc.o
[ 42%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/counter.cc.o
[ 45%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/json_reporter.cc.o
[ 50%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/reporter.cc.o
[ 50%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/csv_reporter.cc.o
[ 52%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/perf_counters.cc.o
[ 55%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sleep.cc.o
[ 57%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/string_util.cc.o
[ 62%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/timers.cc.o
[ 62%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/statistics.cc.o
[ 65%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sysinfo.cc.o
[ 67%] Linking CXX static library libbenchmark.a
[ 67%] Built target benchmark
[ 70%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark_main.dir/benchmark_main.cc.o
[ 72%] Linking CXX static library libbenchmark_main.a
[ 72%] Built target benchmark_main
[ 75%] Linking CXX static library libspdlogd.a
[ 75%] Built target spdlog
[ 82%] Building CXX object bench/CMakeFiles/latency.dir/latency.cpp.o
[ 82%] Building CXX object bench/CMakeFiles/async_bench.dir/async_bench.cpp.o
[ 82%] Building CXX object bench/CMakeFiles/formatter-bench.dir/formatter-bench.cpp.o
[ 85%] Building CXX object bench/CMakeFiles/bench.dir/bench.cpp.o
[ 87%] Building CXX object example/CMakeFiles/example.dir/example.cpp.o
[ 90%] Linking CXX executable formatter-bench
[ 90%] Built target formatter-bench
[ 92%] Linking CXX executable async_bench
[ 92%] Built target async_bench
[ 95%] Linking CXX executable latency
[ 95%] Built target latency
[ 97%] Linking CXX executable bench
[ 97%] Built target bench
[100%] Linking CXX executable example
[100%] Built target example
[info] **************************************************************
[info] Single threaded: 1000000 messages
[info] **************************************************************
[info] basic_st                       Elapsed: 1.37 secs          729,057/sec
[info] basic_st/backtrace-on          Elapsed: 1.38 secs          726,304/sec
[info] 
[info] rotating_st                    Elapsed: 1.38 secs          724,968/sec
[info] rotating_st/backtrace-on       Elapsed: 1.43 secs          696,865/sec
[info] 
[info] daily_st                       Elapsed: 1.37 secs          728,216/sec
[info] daily_st/backtrace-on          Elapsed: 1.43 secs          697,661/sec
[info] 
[info] level-off                      Elapsed: 0.01 secs      116,856,517/sec
[info] level-off/backtrace-on         Elapsed: 1.30 secs          767,003/sec
[info] **************************************************************
[info] Multi threaded: 1 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 1.39 secs          717,709/sec
[info] basic_mt/backtrace-on          Elapsed: 1.44 secs          694,114/sec
[info] 
[info] rotating_mt                    Elapsed: 1.39 secs          721,674/sec
[info] rotating_mt/backtrace-on       Elapsed: 1.45 secs          689,715/sec
[info] 
[info] daily_mt                       Elapsed: 1.40 secs          714,501/sec
[info] daily_mt/backtrace-on          Elapsed: 1.46 secs          686,277/sec
[info] 
[info] level-off                      Elapsed: 0.01 secs      121,867,398/sec
[info] level-off/backtrace-on         Elapsed: 1.30 secs          767,310/sec
[info] **************************************************************
[info] Multi threaded: 4 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 0.71 secs        1,406,326/sec
[info] basic_mt/backtrace-on          Elapsed: 0.75 secs        1,340,525/sec
[info] 
[info] rotating_mt                    Elapsed: 0.79 secs        1,268,253/sec
[info] rotating_mt/backtrace-on       Elapsed: 0.82 secs        1,223,788/sec
[info] 
[info] daily_mt                       Elapsed: 0.74 secs        1,358,168/sec
[info] daily_mt/backtrace-on          Elapsed: 0.77 secs        1,290,743/sec
[info] 
[info] level-off                      Elapsed: 0.01 secs      115,787,725/sec
[info] level-off/backtrace-on         Elapsed: 1.30 secs          770,090/sec
[info] -------------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 8
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 432 = 3456 KB 
[info] Total iters  : 3
[info] -------------------------------------------------
[info] 
[info] *********************************
[info] Queue Overflow Policy: block
[info] *********************************
[info] Elapsed: 1.04501703 secs  956922/sec
[info] Elapsed: 1.265120907 secs         790438/sec
[info] Elapsed: 1.185244473 secs         843707/sec
[info] 
[info] *********************************
[info] Queue Overflow Policy: overrun
[info] *********************************
[info] Elapsed: 0.452209237 secs         2211365/sec
[info] Elapsed: 0.459403635 secs         2176735/sec
[info] Elapsed: 0.454650552 secs         2199491/sec
2024-10-17T14:06:54+01:00
Running ./latency
Run on (16 X 4463 MHz CPU s)
CPU Caches:
  L1 Data 32 KiB (x8)
  L1 Instruction 32 KiB (x8)
  L2 Unified 512 KiB (x8)
  L3 Unified 16384 KiB (x1)
Load Average: 2.72, 1.40, 0.92
***WARNING*** CPU scaling is enabled, the benchmark real time measurements may be noisy and will incur extra overhead.
***WARNING*** Library was built as DEBUG. Timings may be affected.
------------------------------------------------------------------------------------
Benchmark                                          Time             CPU   Iterations
------------------------------------------------------------------------------------
disabled-at-compile-time                       0.000 ns        0.000 ns   1000000000
disabled-at-compile-time (global logger)       0.000 ns        0.000 ns   1000000000
disabled-at-runtime                             8.24 ns         8.23 ns     84466930
disabled-at-runtime (global logger)             8.86 ns         8.86 ns     78228990
disabled-at-runtime/backtrace                   1315 ns         1315 ns       531594
null_sink_st (500_bytes c_str)                  1211 ns         1211 ns       580305
null_sink_st                                    1273 ns         1273 ns       559647
null_sink_st (global logger)                    1287 ns         1287 ns       537732
null_sink_st/backtrace                          1315 ns         1314 ns       534235
/dev/null_st/real_time                          1350 ns         1349 ns       511381
/dev/null_mt/real_time                          1395 ns         1394 ns       509884
async_logger/real_time/threads:16                557 ns         5628 ns      1287488
async_logger/tracing/real_time/threads:16        570 ns         5618 ns      1243440

Clang 19 Debug Build

cd $(mktemp -d) &&
git clone https://github.com/gabime/spdlog.git &&
cd spdlog &&    
mkdir build &&
cd build &&   
cmake .. -D SPDLOG_BUILD_BENCH=ON -DCMAKE_BUILD_TYPE=Debug -DCMAKE_CXX_COMPILER=clang++&&
make -j &&
cd bench &&
./bench 1000000 &&
./async_bench 1000000 8 &&
./latency
Cloning into 'spdlog'...
remote: Enumerating objects: 28681, done.
remote: Counting objects: 100% (1136/1136), done.
remote: Compressing objects: 100% (450/450), done.
remote: Total 28681 (delta 689), reused 959 (delta 586), pack-reused 27545 (from 1)
Receiving objects: 100% (28681/28681), 41.43 MiB | 19.63 MiB/s, done.
Resolving deltas: 100% (19117/19117), done.
-- The CXX compiler identification is Clang 19.1.1
-- Detecting CXX compiler ABI info
-- Detecting CXX compiler ABI info - done
-- Check for working CXX compiler: /nix/store/smghi6rpg0a5j1612zsf5jx0yn47h8w6-clang-wrapper-19.1.1/bin/clang++ - skipped
-- Detecting CXX compile features
-- Detecting CXX compile features - done
-- Build spdlog: 1.14.1
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD
-- Performing Test CMAKE_HAVE_LIBC_PTHREAD - Success
-- Found Threads: TRUE
-- Build type: Debug
-- Generating example(s)
-- Generating benchmarks
-- Could NOT find benchmark (missing: benchmark_DIR)
-- Using CMake Version 3.29.6
-- Downloading GoogleBenchmark
-- LLVM FileCheck Found: /nix/store/fhyq9fjj1p7h9afx1pcbxb3wclib4sxj-llvm-19.1.1/bin/FileCheck
-- Found Git: /run/current-system/sw/bin/git (found version "2.46.1")
-- git version: v1.6.0 normalized to 1.6.0
-- Version: 1.6.0
-- Performing Test HAVE_CXX_FLAG_STD_CXX11
-- Performing Test HAVE_CXX_FLAG_STD_CXX11 - Success
-- Performing Test HAVE_CXX_FLAG_WALL
-- Performing Test HAVE_CXX_FLAG_WALL - Success
-- Performing Test HAVE_CXX_FLAG_WEXTRA
-- Performing Test HAVE_CXX_FLAG_WEXTRA - Success
-- Performing Test HAVE_CXX_FLAG_WSHADOW
-- Performing Test HAVE_CXX_FLAG_WSHADOW - Success
-- Performing Test HAVE_CXX_FLAG_WERROR
-- Performing Test HAVE_CXX_FLAG_WERROR - Success
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE
-- Performing Test HAVE_CXX_FLAG_WSUGGEST_OVERRIDE - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC
-- Performing Test HAVE_CXX_FLAG_PEDANTIC - Success
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS
-- Performing Test HAVE_CXX_FLAG_PEDANTIC_ERRORS - Success
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32
-- Performing Test HAVE_CXX_FLAG_WSHORTEN_64_TO_32 - Success
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_FSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED_DECLARATIONS - Success
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED
-- Performing Test HAVE_CXX_FLAG_WNO_DEPRECATED - Success
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING
-- Performing Test HAVE_CXX_FLAG_WSTRICT_ALIASING - Success
-- Performing Test HAVE_CXX_FLAG_WD654
-- Performing Test HAVE_CXX_FLAG_WD654 - Failed
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY
-- Performing Test HAVE_CXX_FLAG_WTHREAD_SAFETY - Success
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES
-- Performing Test HAVE_THREAD_SAFETY_ATTRIBUTES -- failed to compile
-- Performing Test HAVE_CXX_FLAG_COVERAGE
-- Performing Test HAVE_CXX_FLAG_COVERAGE - Success
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX
-- Performing Test HAVE_STD_REGEX -- success
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX
-- Performing Test HAVE_GNU_POSIX_REGEX -- failed to compile
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX
-- Performing Test HAVE_POSIX_REGEX -- success
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK
-- Performing Test HAVE_STEADY_CLOCK -- success
-- Generating install
-- Configuring done (8.1s)
-- Generating done (0.0s)
-- Build files have been written to: /tmp/tmp.hP1W9PSjoc/spdlog/build
[  7%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_api_internal.cc.o
[ 10%] Building CXX object CMakeFiles/spdlog.dir/src/color_sinks.cpp.o
[ 10%] Building CXX object CMakeFiles/spdlog.dir/src/spdlog.cpp.o
[ 10%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_name.cc.o
[ 12%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_runner.cc.o
[ 15%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark_register.cc.o
[ 17%] Building CXX object CMakeFiles/spdlog.dir/src/cfg.cpp.o
[ 20%] Building CXX object CMakeFiles/spdlog.dir/src/file_sinks.cpp.o
[ 22%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/commandlineflags.cc.o
[ 25%] Building CXX object CMakeFiles/spdlog.dir/src/async.cpp.o
[ 27%] Building CXX object CMakeFiles/spdlog.dir/src/bundled_fmtlib_format.cpp.o
[ 30%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/benchmark.cc.o
[ 32%] Building CXX object CMakeFiles/spdlog.dir/src/stdout_sinks.cpp.o
[ 35%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/colorprint.cc.o
[ 37%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/console_reporter.cc.o
[ 42%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/complexity.cc.o
[ 42%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/counter.cc.o
[ 47%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/json_reporter.cc.o
[ 47%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/csv_reporter.cc.o
[ 50%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/perf_counters.cc.o
[ 52%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/reporter.cc.o
[ 55%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sleep.cc.o
[ 57%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/string_util.cc.o
[ 60%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/timers.cc.o
[ 62%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/statistics.cc.o
[ 65%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark.dir/sysinfo.cc.o
[ 67%] Linking CXX static library libbenchmark.a
[ 67%] Built target benchmark
[ 70%] Building CXX object _deps/googlebenchmark-build/src/CMakeFiles/benchmark_main.dir/benchmark_main.cc.o
[ 72%] Linking CXX static library libbenchmark_main.a
[ 72%] Built target benchmark_main
[ 75%] Linking CXX static library libspdlogd.a
[ 75%] Built target spdlog
[ 80%] Building CXX object bench/CMakeFiles/async_bench.dir/async_bench.cpp.o
[ 80%] Building CXX object bench/CMakeFiles/bench.dir/bench.cpp.o
[ 82%] Building CXX object example/CMakeFiles/example.dir/example.cpp.o
[ 85%] Building CXX object bench/CMakeFiles/latency.dir/latency.cpp.o
[ 87%] Building CXX object bench/CMakeFiles/formatter-bench.dir/formatter-bench.cpp.o
[ 90%] Linking CXX executable formatter-bench
[ 90%] Built target formatter-bench
[ 92%] Linking CXX executable async_bench
[ 92%] Built target async_bench
[ 95%] Linking CXX executable bench
[ 95%] Built target bench
[ 97%] Linking CXX executable latency
[ 97%] Built target latency
[100%] Linking CXX executable example
[100%] Built target example
[info] **************************************************************
[info] Single threaded: 1000000 messages
[info] **************************************************************
[info] basic_st                       Elapsed: 1.41 secs          708,609/sec
[info] basic_st/backtrace-on          Elapsed: 1.43 secs          699,170/sec
[info] 
[info] rotating_st                    Elapsed: 1.39 secs          718,242/sec
[info] rotating_st/backtrace-on       Elapsed: 1.46 secs          682,742/sec
[info] 
[info] daily_st                       Elapsed: 1.42 secs          702,008/sec
[info] daily_st/backtrace-on          Elapsed: 1.47 secs          679,559/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs      224,660,891/sec
[info] level-off/backtrace-on         Elapsed: 1.32 secs          755,030/sec
[info] **************************************************************
[info] Multi threaded: 1 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 1.37 secs          730,721/sec
[info] basic_mt/backtrace-on          Elapsed: 1.46 secs          686,149/sec
[info] 
[info] rotating_mt                    Elapsed: 1.39 secs          718,780/sec
[info] rotating_mt/backtrace-on       Elapsed: 1.46 secs          683,318/sec
[info] 
[info] daily_mt                       Elapsed: 1.37 secs          729,685/sec
[info] daily_mt/backtrace-on          Elapsed: 1.46 secs          686,007/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs      251,844,065/sec
[info] level-off/backtrace-on         Elapsed: 1.33 secs          752,151/sec
[info] **************************************************************
[info] Multi threaded: 4 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt                       Elapsed: 0.73 secs        1,362,309/sec
[info] basic_mt/backtrace-on          Elapsed: 0.76 secs        1,312,190/sec
[info] 
[info] rotating_mt                    Elapsed: 0.77 secs        1,301,489/sec
[info] rotating_mt/backtrace-on       Elapsed: 0.80 secs        1,251,110/sec
[info] 
[info] daily_mt                       Elapsed: 0.73 secs        1,366,110/sec
[info] daily_mt/backtrace-on          Elapsed: 0.76 secs        1,307,378/sec
[info] 
[info] level-off                      Elapsed: 0.00 secs      254,974,423/sec
[info] level-off/backtrace-on         Elapsed: 1.34 secs          748,614/sec
[info] -------------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 8
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 416 = 3328 KB 
[info] Total iters  : 3
[info] -------------------------------------------------
[info] 
[info] *********************************
[info] Queue Overflow Policy: block
[info] *********************************
[info] Elapsed: 1.286889906 secs         777067/sec
[info] Elapsed: 1.122807193 secs         890624/sec
[info] Elapsed: 1.13701697 secs  879494/sec
[info] 
[info] *********************************
[info] Queue Overflow Policy: overrun
[info] *********************************
[info] Elapsed: 0.465029811 secs         2150399/sec
[info] Elapsed: 0.46910619 secs  2131713/sec
[info] Elapsed: 0.460721273 secs         2170509/sec
2024-10-17T14:08:38+01:00
Running ./latency
Run on (16 X 4463 MHz CPU s)
CPU Caches:
  L1 Data 32 KiB (x8)
  L1 Instruction 32 KiB (x8)
  L2 Unified 512 KiB (x8)
  L3 Unified 16384 KiB (x1)
Load Average: 3.09, 1.80, 1.12
***WARNING*** CPU scaling is enabled, the benchmark real time measurements may be noisy and will incur extra overhead.
***WARNING*** Library was built as DEBUG. Timings may be affected.
------------------------------------------------------------------------------------
Benchmark                                          Time             CPU   Iterations
------------------------------------------------------------------------------------
disabled-at-compile-time                       0.000 ns        0.000 ns   1000000000
disabled-at-compile-time (global logger)       0.000 ns        0.000 ns   1000000000
disabled-at-runtime                             3.53 ns         3.53 ns    199803563
disabled-at-runtime (global logger)             4.05 ns         4.05 ns    173305998
disabled-at-runtime/backtrace                   1298 ns         1297 ns       531307
null_sink_st (500_bytes c_str)                  1214 ns         1214 ns       576450
null_sink_st                                    1272 ns         1272 ns       554329
null_sink_st (global logger)                    1292 ns         1292 ns       543565
null_sink_st/backtrace                          1310 ns         1310 ns       529268
/dev/null_st/real_time                          1328 ns         1328 ns       520085
/dev/null_mt/real_time                          1357 ns         1356 ns       513604
async_logger/real_time/threads:16                641 ns         6434 ns      1094960
async_logger/tracing/real_time/threads:16        645 ns         6490 ns      1101456

[gabime]

Debug builds are irrelevant for performance. Is there a problem with the release performance or not?

[yuannan]

Yes, it's a problem with the release build. I only posted with DEBUG as you asked.

[tt4g]

There may be a problem with the optimization of the release build, but that would be a compiler issue and difficult to investigate.

[yuannan]

There may be a problem with the optimization of the release build, but that would be a compiler issue and difficult to investigate.

I've tested it with GCC and Clang on multiple packaged systems (NixOS, Arch, and Ubuntu). Could do a test on Red Hat systems as well.

The effect is consistent on my laptop with a fairly recent Ryzen CPU. I've been trying to get my hands on more hardware to test but my resources are limited.

This has the potential to affect a lot of users, not just myself.

[Novazhangquan]

@yuannan In virtual machine environment, from the measured results; Multithreading is far inferior to single-threading in performance. What are the possible or direct causes of the performance degradation?

[info] **************************************************************
[info] Single threaded: 1000000 messages
[info] **************************************************************
[info] basic_st Elapsed: 0.17 secs 5,806,606/sec
[info] basic_st/backtrace-on Elapsed: 0.18 secs 5,610,453/sec
[info]
[info] rotating_st Elapsed: 0.18 secs 5,418,181/sec
[info] rotating_st/backtrace-on Elapsed: 0.25 secs 4,014,341/sec
[info]
[info] daily_st Elapsed: 0.18 secs 5,448,967/sec
[info] daily_st/backtrace-on Elapsed: 0.24 secs 4,209,646/sec
[info]
[info] level-off Elapsed: 0.00 secs 562,105,331/sec
[info] level-off/backtrace-on Elapsed: 0.11 secs 9,012,754/sec
[info] **************************************************************
[info] Multi threaded: 1 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt Elapsed: 0.19 secs 5,293,845/sec
[info] basic_mt/backtrace-on Elapsed: 0.24 secs 4,102,611/sec
[info]
[info] rotating_mt Elapsed: 0.20 secs 4,964,396/sec
[info] rotating_mt/backtrace-on Elapsed: 0.26 secs 3,827,677/sec
[info]
[info] daily_mt Elapsed: 0.20 secs 5,090,385/sec
[info] daily_mt/backtrace-on Elapsed: 0.25 secs 3,941,150/sec
[info]
[info] level-off Elapsed: 0.00 secs 558,043,188/sec
[info] level-off/backtrace-on Elapsed: 0.11 secs 8,963,098/sec
[info] **************************************************************
[info] Multi threaded: 4 threads, 1,000,000 messages
[info] **************************************************************
[info] basic_mt Elapsed: 0.54 secs 1,868,053/sec
[info] basic_mt/backtrace-on Elapsed: 0.87 secs 1,150,336/sec
[info]
[info] rotating_mt Elapsed: 0.59 secs 1,706,231/sec
[info] rotating_mt/backtrace-on Elapsed: 0.88 secs 1,142,313/sec
[info]
[info] daily_mt Elapsed: 0.54 secs 1,842,403/sec
[info] daily_mt/backtrace-on Elapsed: 0.77 secs 1,298,580/sec
[info]
[info] level-off Elapsed: 0.00 secs 563,710,886/sec
[info] level-off/backtrace-on Elapsed: 0.11 secs 9,029,983/sec

[tt4g]

Make sure that the host machine is properly allocating CPU and disk I/O to the virtual machine.

• If not enough CPU is allocated, it will be slowed down by the context switches that occur due to thread switching
• Disk I/O can be slower if drivers (such as virtio) for virtual environments are not used

[yuannan]

I'm not running this in a virtual machine. What CPU do you have?

[Novazhangquan]

@yuannan Does it support bare metal?

[yuannan]

Yeah, I'm running NixOS, and ubuntu (live boot) on bare metal and it's showing the above results.

I don't think there is anything funny in my BIOS that is causing this.

[yuannan]

I could be wrong, if you have any hunches on what this might be, I would be happy to report back.