From f6c19c2a601e88727e73eec8734a81da037af6db Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 12 Sep 2026 13:35:10 +0300 Subject: [PATCH 1/5] perf(logger): reduce dispatch registry overhead Publish an immutable copy-on-write strategy snapshot so normal and targeted dispatches avoid registry locking and per-call vector copies. Make logger state flags atomic and add a concurrent hot-path regression test without relaxing the existing formatter/backend execution mutex. Align benchmark setup and documentation with the prepared-record pipeline, pin spdlog 1.17.0, use Release CI builds, add the 32-producer case, and label sink-entry latency accurately. --- .github/workflows/ci.yml | 2 +- bench/CMakeLists.txt | 2 +- bench/LatencyRecorder.hpp | 8 ++++ bench/adapters/LogItAdapter.cpp | 3 +- bench/adapters/SpdlogAdapter.cpp | 4 +- bench/logit_bench.cpp | 2 +- docs/benchmarks.md | 41 ++++++++++++++---- docs/comparison-RU.md | 14 ++++--- docs/comparison.md | 14 ++++--- include/logit_cpp/logit/Logger.hpp | 63 +++++++++++++++------------- tests/CMakeLists.txt | 1 + tests/logger_hot_path_state_test.cpp | 60 ++++++++++++++++++++++++++ 12 files changed, 161 insertions(+), 53 deletions(-) create mode 100644 tests/logger_hot_path_state_test.cpp diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 66ef7812..be0ef8fa 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -27,7 +27,7 @@ jobs: run: ctest --test-dir build --output-on-failure - name: Configure benchmarks # if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} - run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -DCMAKE_CXX_STANDARD=${{ matrix.std }} -DLOGIT_WITH_SYSLOG=ON -DLOGIT_WITH_WIN_EVENT_LOG=OFF + run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -DCMAKE_BUILD_TYPE=Release -DCMAKE_CXX_STANDARD=${{ matrix.std }} -DLOGIT_WITH_SYSLOG=ON -DLOGIT_WITH_WIN_EVENT_LOG=OFF - name: Build benchmarks # if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} run: cmake --build build-bench --target logit_bench diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index ebffc7cf..8af9055b 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -31,7 +31,7 @@ if(LOGIT_BENCH_WITH_SPDLOG) include(FetchContent) FetchContent_Declare(spdlog GIT_REPOSITORY https://github.com/gabime/spdlog.git - GIT_TAG v1.12.0 + GIT_TAG v1.17.0 ) FetchContent_MakeAvailable(spdlog) endif() diff --git a/bench/LatencyRecorder.hpp b/bench/LatencyRecorder.hpp index de990d4b..4eb23c09 100644 --- a/bench/LatencyRecorder.hpp +++ b/bench/LatencyRecorder.hpp @@ -1,5 +1,9 @@ #pragma once +#if defined(_WIN32) && !defined(NOMINMAX) +#define NOMINMAX +#endif + #include #include #include @@ -11,6 +15,10 @@ #include #include +#ifdef max +#undef max +#endif + namespace logit_bench { /** diff --git a/bench/adapters/LogItAdapter.cpp b/bench/adapters/LogItAdapter.cpp index d9dd1918..1a47b17d 100644 --- a/bench/adapters/LogItAdapter.cpp +++ b/bench/adapters/LogItAdapter.cpp @@ -105,7 +105,8 @@ namespace logit_bench { }; void consume(int slot_line, std::string_view text) { - // slot-only completion + // Record sink-entry latency; file I/O happens below and is not + // part of this completion marker. if (slot_line >= 0 && m_recorder) { m_recorder->complete_slot(static_cast(slot_line)); } diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index d0bd26a7..e68207c2 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -43,7 +43,9 @@ namespace logit_bench { } void log(const spdlog::details::log_msg& msg) override { - // slot is stored in msg.source.line + // Record sink-entry latency; file I/O happens below and is not + // part of this completion marker. The slot is stored in + // msg.source.line. const int line = msg.source.line; if (line >= 0 && m_recorder) { m_recorder->complete_slot(static_cast(line)); diff --git a/bench/logit_bench.cpp b/bench/logit_bench.cpp index ae48803c..db9cf351 100644 --- a/bench/logit_bench.cpp +++ b/bench/logit_bench.cpp @@ -361,7 +361,7 @@ int main() { // Matrix const std::array async_modes{false, true}; const std::array sinks{SinkKind::Null, SinkKind::File}; - const std::array producer_counts{1, 4, 16}; + const std::array producer_counts{1, 4, 16, 32}; const std::array message_sizes{40, 200, 1024}; // Totals (can be overridden by env): diff --git a/docs/benchmarks.md b/docs/benchmarks.md index 8c44151c..cec72480 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -12,19 +12,25 @@ cmake --build build --target logit_bench ./build/bench/logit_bench ``` -The harness records end-to-end latency from the logging call until delivery to -the sink, together with aggregate throughput. It compares synchronous and -asynchronous modes, null and file sinks, producer counts, and message sizes. +The harness records latency from the logging call until the adapter enters its +sink callback, together with aggregate throughput. This is a **sink-entry +latency** metric: for the file scenario the marker is recorded before the +`ofstream` write, so it is not a completed-write or durability measurement. +It compares synchronous and asynchronous modes, null and file sinks, producer +counts, and message sizes. Results are appended to `bench/results/latency.csv`; workload size can be reduced with `LOGIT_BENCH_TOTAL` and `LOGIT_BENCH_WARMUP`. ## Interpreting results -The benchmark measures the complete path, not just formatter throughput. A -LogIt++ call may parse argument names, build `args_array`, and optionally -format values, while another logger may receive an already formatted string. -Compare implementations within the same mode and configuration; these numbers -are not a universal speed ranking. +The default adapter measures a **prepared-record / dispatch pipeline**. It +constructs a `LogRecord` whose message is already prepared and calls the +dispatcher directly; it does not exercise the public `LOGIT_INFO(...)` macro +path, argument-name parsing, or `args_array` construction. A separate public +macro benchmark should be treated as a different scenario rather than mixed +into this comparison. The spdlog adapter likewise receives an already prepared +string. Compare implementations within the same mode and configuration; these +numbers are not a universal speed ranking. The asynchronous measurement includes enqueue, worker wake-up/scheduling, and sink time. Results are sensitive to queue capacity, overflow policy, worker @@ -52,3 +58,22 @@ library-selection decisions. producers and consumers. The LogIt adapter stores the benchmark slot in `LogRecord::line`; sinks call `LatencyRecorder::complete_slot()` when they observe a non-negative line number. + +The current matrix covers 1, 4, 16, and 32 producers. CI intentionally uses a +short Release smoke workload (`LOGIT_BENCH_TOTAL=20000`) for predictable run +time. Larger publication runs (for example, one million messages plus warmup) +belong on fixed or self-hosted hardware, where the results can be reproduced. + +The prepared-record/dispatch pipeline and a true public macro benchmark that +calls `LOGIT_INFO(...)` are separate scenarios with different work contracts; +their results must not be presented as one number. + +The prepared-record path is also the first target for the logger hot-path +regression checks. Logger strategy lists are published as an immutable +copy-on-write snapshot, so a normal dispatch no longer takes the registry lock +or allocates a temporary vector. `enabled` and `single_mode` are atomic state, +which keeps concurrent configuration changes defined without changing the +existing formatter/backend execution mutex. That mutex remains intentional: +custom formatters and backends are not assumed to be safe for concurrent +invocation. Any future lock-elision experiment must advertise and test an +explicit concurrency contract rather than infer one from a benchmark sink. diff --git a/docs/comparison-RU.md b/docs/comparison-RU.md index b8b8dd71..e59ae984 100644 --- a/docs/comparison-RU.md +++ b/docs/comparison-RU.md @@ -141,9 +141,11 @@ application diagnostics и severity/check macros. Это trade-offs област ## Снимок производительности -Сейчас в репозитории есть воспроизводимый adapter только для LogIt++ и spdlog, -а не для всех шести проектов. Поэтому таблица — **снимок LogIt++/spdlog -pipeline**, а не рейтинг всех библиотек. +Сейчас в репозитории есть воспроизводимый adapter для **pipeline подготовленной +записи/dispatch** только для LogIt++ и spdlog, а не для всех шести проектов. +Поэтому таблица — **снимок LogIt++/spdlog pipeline**, а не рейтинг всех +библиотек. Полный публичный macro-путь `LOGIT_INFO(...)` здесь не измеряется: +в частности, не учитываются разбор имён аргументов и построение `args_array`. | Режим | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | | --- | --- | ---: | ---: | ---: | ---: | @@ -153,9 +155,9 @@ pipeline**, а не рейтинг всех библиотек. | Async | File | 255 323 ns | 651 384 msg/s | 5 001 140 ns | 1 153 976 msg/s | Условия snapshot: Release build, четыре producer-а, сообщения по 200 байт, -`LOGIT_BENCH_TOTAL=10000`, fixture от 05.12.2025. Путь LogIt++ может включать -извлечение имён аргументов и упаковку structured values, а spdlog adapter получает -готовую строку. Async-результаты также включают enqueue, wake-up/scheduling worker-а +`LOGIT_BENCH_TOTAL=10000`, fixture от 05.12.2025. LogIt++ adapter получает +подготовленный `LogRecord`, а spdlog adapter — подготовленную строку. +Async-результаты также включают enqueue, wake-up/scheduling worker-а и работу sink-а. Методика описана в [`docs/benchmarks.md`](benchmarks.html), полный fixture — в diff --git a/docs/comparison.md b/docs/comparison.md index 133b82f2..a5460d5a 100644 --- a/docs/comparison.md +++ b/docs/comparison.md @@ -147,10 +147,12 @@ universally better. ## Performance snapshot -The repository currently has a reproducible adapter for LogIt++ and spdlog, -not for every project in the feature table. The historical fixture below is -therefore a **LogIt++/spdlog pipeline snapshot**, not a ranking of all six -projects. +The repository currently has a reproducible **prepared-record/dispatch +pipeline** adapter for LogIt++ and spdlog, not for every project in the feature +table. The historical fixture below is therefore a **LogIt++/spdlog pipeline +snapshot**, not a ranking of all six projects. It does not measure the full +public `LOGIT_INFO(...)` macro path; in particular, it omits argument-name +parsing and `args_array` construction. | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | | --- | --- | ---: | ---: | ---: | ---: | @@ -161,8 +163,8 @@ projects. Snapshot conditions: Release build, four producers, 200-byte messages, `LOGIT_BENCH_TOTAL=10000`, and the fixture recorded on 2025-12-05. The LogIt++ -path may include argument-name extraction and structured value packing, while -the spdlog adapter receives a prepared string. Async values also include +adapter receives a prepared `LogRecord`, while the spdlog adapter receives a +prepared string. Async values also include enqueue, worker wake-up/scheduling, and sink work. See [`docs/benchmarks.md`](benchmarks.html) for the methodology and diff --git a/include/logit_cpp/logit/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index ba0e1dcd..f7dc3d7a 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -70,6 +70,7 @@ namespace logit { LoggerWriteLock lock(m_loggers_mx); if (m_shutdown.load(std::memory_order_acquire)) return; m_loggers.push_back(std::move(strategy)); + publish_strategy_snapshot_locked(); } /// \brief Enables or disables a logger by index. @@ -79,7 +80,7 @@ namespace logit { if (m_shutdown) return; LoggerWriteLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { - m_loggers[logger_index]->enabled = enabled; + m_loggers[logger_index]->enabled.store(enabled, std::memory_order_relaxed); } } @@ -89,7 +90,7 @@ namespace logit { bool is_logger_enabled(int logger_index) const { LoggerReadLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { - return m_loggers[logger_index]->enabled; + return m_loggers[logger_index]->enabled.load(std::memory_order_relaxed); } return false; } @@ -101,7 +102,7 @@ namespace logit { if (m_shutdown) return; LoggerWriteLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { - m_loggers[logger_index]->single_mode = single_mode; + m_loggers[logger_index]->single_mode.store(single_mode, std::memory_order_relaxed); } } @@ -148,7 +149,7 @@ namespace logit { if (m_shutdown) return false; LoggerReadLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { - return m_loggers[logger_index]->single_mode; + return m_loggers[logger_index]->single_mode.load(std::memory_order_relaxed); } return false; } @@ -162,39 +163,31 @@ namespace logit { if (m_shutdown.load(std::memory_order_acquire)) return; const bool targeted = record.logger_index >= 0; - - std::vector> snapshot; - snapshot.reserve(targeted ? 1 : 0); - - LoggerReadLock lock(m_loggers_mx); - if (targeted) { - if (record.logger_index < static_cast(m_loggers.size())) - snapshot.push_back(m_loggers[record.logger_index]); - } else { - snapshot = m_loggers; // copy shared_ptrs - } - lock.unlock(); + const auto snapshot = std::atomic_load_explicit( + &m_loggers_snapshot, std::memory_order_acquire); + if (!snapshot) return; if (targeted) { - if (snapshot.empty() || !snapshot[0]) return; - auto& strategy = snapshot[0]; + if (record.logger_index >= static_cast(snapshot->size())) return; + const auto& strategy = (*snapshot)[record.logger_index]; + if (!strategy) return; std::lock_guard exec_lock(strategy->exec_mx); if (m_shutdown.load(std::memory_order_acquire)) return; - if (!strategy->enabled) return; + if (!strategy->enabled.load(std::memory_order_relaxed)) return; if (!record.raw_mode && static_cast(record.log_level) < static_cast(strategy->logger->get_log_level())) return; dispatch_to_strategy(*strategy, record); return; } - for (const auto& strategy : snapshot) { + for (const auto& strategy : *snapshot) { if (!strategy) continue; std::lock_guard exec_lock(strategy->exec_mx); if (m_shutdown.load(std::memory_order_acquire)) return; - if (strategy->single_mode) continue; - if (!strategy->enabled) continue; + if (strategy->single_mode.load(std::memory_order_relaxed)) continue; + if (!strategy->enabled.load(std::memory_order_relaxed)) continue; if (!record.raw_mode && static_cast(record.log_level) < static_cast(strategy->logger->get_log_level())) continue; @@ -529,8 +522,8 @@ namespace logit { struct LoggerStrategy { std::unique_ptr logger; ///< The logger instance. std::unique_ptr formatter; ///< The formatter instance. - bool single_mode = false; ///< Flag indicating if the logger is in single mode. - bool enabled = true; ///< Flag indicating if the logger is enabled. + std::atomic single_mode{false}; ///< Flag indicating if the logger is in single mode. + std::atomic enabled{true}; ///< Flag indicating if the logger is enabled. mutable std::mutex exec_mx; ///< Protects formatter+logger invocation. }; @@ -548,21 +541,31 @@ namespace logit { } std::shared_ptr get_strategy_snapshot(int logger_index) const { - LoggerReadLock lock(m_loggers_mx); + const auto snapshot = std::atomic_load_explicit( + &m_loggers_snapshot, std::memory_order_acquire); if (logger_index >= 0 && - logger_index < static_cast(m_loggers.size()) && - m_loggers[logger_index]) { - return m_loggers[logger_index]; + snapshot && logger_index < static_cast(snapshot->size()) && + (*snapshot)[logger_index]) { + return (*snapshot)[logger_index]; } return std::shared_ptr(); } + void publish_strategy_snapshot_locked() { + const std::shared_ptr snapshot( + new StrategyList(m_loggers)); + std::atomic_store_explicit( + &m_loggers_snapshot, snapshot, std::memory_order_release); + } + std::vector> get_all_strategy_snapshots() const { LoggerReadLock lock(m_loggers_mx); return m_loggers; } std::vector> m_loggers; ///< Container for logger-formatter pairs. + using StrategyList = std::vector>; + std::shared_ptr m_loggers_snapshot; ///< Immutable read-mostly strategy list. mutable LoggerMutex m_loggers_mx; ///< Protects access to logger strategies. std::atomic m_shutdown = ATOMIC_VAR_INIT(false); ///< Flag indicating if shutdown was requested. @@ -596,6 +599,10 @@ namespace logit { #endif Logger() { + std::atomic_store_explicit( + &m_loggers_snapshot, + std::shared_ptr(new StrategyList()), + std::memory_order_release); std::atexit(Logger::on_exit_handler); } diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 3c904e2d..35d082f2 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -45,6 +45,7 @@ else() include_utils_nhr_test.cpp log_filters_tags_test.cpp logger_shutdown_race_test.cpp + logger_hot_path_state_test.cpp logger_snapshot_read_path_test.cpp logger_clear_api_test.cpp memory_logger_backend_test.cpp diff --git a/tests/logger_hot_path_state_test.cpp b/tests/logger_hot_path_state_test.cpp new file mode 100644 index 00000000..5b2b04bd --- /dev/null +++ b/tests/logger_hot_path_state_test.cpp @@ -0,0 +1,60 @@ +#include +#include +#include +#include +#include + +#include + +namespace { +class CountingLogger final : public logit::ILogger { +public: + void log(const logit::LogRecord&, const std::string&) override { + count.fetch_add(1, std::memory_order_relaxed); + } + + std::string get_string_param(const logit::LoggerParam&) const override { return std::string(); } + int64_t get_int_param(const logit::LoggerParam&) const override { return 0; } + double get_float_param(const logit::LoggerParam&) const override { return 0.0; } + void set_log_level(logit::LogLevel level) override { + m_level.store(static_cast(level), std::memory_order_relaxed); + } + logit::LogLevel get_log_level() const override { + return static_cast(m_level.load(std::memory_order_relaxed)); + } + void wait() override {} + + std::atomic count{0}; + +private: + std::atomic m_level{static_cast(logit::LogLevel::LOG_LVL_TRACE)}; +}; +} // namespace + +int main() { + CountingLogger* backend = new CountingLogger(); + logit::Logger& logger = logit::Logger::get_instance(); + logger.add_logger( + std::unique_ptr(backend), + std::unique_ptr(new logit::SimpleLogFormatter("%v"))); + + const logit::LogRecord record( + logit::LogLevel::LOG_LVL_INFO, 0, std::string(), 0, std::string(), + std::string("hot-path"), std::string(), -1, false, false); + + std::thread producer([&]() { + for (int i = 0; i < 20000; ++i) { + logger.log(record); + } + }); + + for (int i = 0; i < 20000; ++i) { + logger.set_logger_enabled(0, (i & 1) == 0); + logger.set_logger_single_mode(0, false); + } + producer.join(); + + logger.set_logger_enabled(0, true); + logger.log(record); + return backend->count.load(std::memory_order_relaxed) == 0 ? 1 : 0; +} From f0f0723cfe0782906abdb7f670c5e3d80c43f3a7 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 12 Sep 2026 15:19:44 +0300 Subject: [PATCH 2/5] test(bench): make async comparisons drain equivalent Add a worker-side flush generation barrier for the spdlog async adapter and fail the workload when adapter.flush() returns before recorded sink completions. Use one explicit blocking queue capacity for both adapters and record it in CSV output. Add a focused spdlog flush regression executable and clarify the prepared-message contract and legacy fixture status in English and Russian benchmark documentation. --- bench/CMakeLists.txt | 10 +++++++ bench/Scenario.hpp | 1 + bench/adapters/SpdlogAdapter.cpp | 47 +++++++++++++++++++++++++------- bench/logit_bench.cpp | 22 +++++++++++++-- bench/spdlog_flush_test.cpp | 31 +++++++++++++++++++++ docs/benchmarks.md | 40 +++++++++++++++++---------- docs/comparison-RU.md | 23 +++++++++++----- docs/comparison.md | 24 ++++++++++------ 8 files changed, 156 insertions(+), 42 deletions(-) create mode 100644 bench/spdlog_flush_test.cpp diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index 8af9055b..14143ac9 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -36,4 +36,14 @@ if(LOGIT_BENCH_WITH_SPDLOG) FetchContent_MakeAvailable(spdlog) endif() target_link_libraries(logit_bench PRIVATE spdlog::spdlog) + + add_executable(logit_bench_flush_test + spdlog_flush_test.cpp + adapters/SpdlogAdapter.cpp + ) + target_compile_features(logit_bench_flush_test PRIVATE cxx_std_17) + target_include_directories(logit_bench_flush_test PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}) + target_compile_definitions(logit_bench_flush_test PRIVATE LOGIT_BENCH_HAVE_SPDLOG=1) + target_link_libraries(logit_bench_flush_test PRIVATE spdlog::spdlog) + add_test(NAME logit_bench_flush_test COMMAND logit_bench_flush_test) endif() diff --git a/bench/Scenario.hpp b/bench/Scenario.hpp index 3fe052a7..05dd1bd7 100644 --- a/bench/Scenario.hpp +++ b/bench/Scenario.hpp @@ -24,6 +24,7 @@ struct Scenario { std::size_t producers = 1; std::size_t message_bytes = 0; std::size_t total_messages = 0; + std::size_t queue_capacity = 0; }; } // namespace logit_bench diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index e68207c2..2d282e9f 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -9,6 +9,7 @@ #include #include #include +#include #include #include @@ -65,17 +66,37 @@ namespace logit_bench { void flush() override { std::lock_guard lock(m_mutex); + flush_file_locked(); + ++m_flush_generation; + m_flush_cv.notify_all(); + } + + std::uint64_t flush_generation() const { + std::lock_guard lock(m_mutex); + return m_flush_generation; + } + + void wait_for_flush(std::uint64_t generation) const { + std::unique_lock lock(m_mutex); + m_flush_cv.wait(lock, [&]() { + return m_flush_generation > generation; + }); + } + + private: + void flush_file_locked() { if (m_file.is_open()) { m_file.flush(); } } - - private: + SinkKind m_sink = SinkKind::Null; std::shared_ptr m_recorder; - + std::ofstream m_file; - std::mutex m_mutex; + mutable std::mutex m_mutex; + mutable std::condition_variable m_flush_cv; + std::uint64_t m_flush_generation = 0; }; SpdlogAdapter::SpdlogAdapter() = default; @@ -106,8 +127,9 @@ namespace logit_bench { std::string logger_name = m_async ? "logit_bench_async" : "logit_bench_sync"; if (m_async) { - const std::size_t queue_size = - std::max(kDefaultQueue, scenario.total_messages * 2); + const std::size_t queue_size = scenario.queue_capacity > 0 + ? scenario.queue_capacity + : kDefaultQueue; spdlog::init_thread_pool(queue_size, 1); @@ -148,10 +170,15 @@ namespace logit_bench { void SpdlogAdapter::flush() { if (m_logger) { - m_logger->flush(); - } - if (m_sink) { - m_sink->flush(); + if (m_async && m_sink) { + const auto generation = m_sink->flush_generation(); + m_logger->flush(); + // async_logger::flush() enqueues a marker. The sink-side + // generation is advanced only when the worker executes it. + m_sink->wait_for_flush(generation); + } else { + m_logger->flush(); + } } } diff --git a/bench/logit_bench.cpp b/bench/logit_bench.cpp index db9cf351..c88db2ca 100644 --- a/bench/logit_bench.cpp +++ b/bench/logit_bench.cpp @@ -1,4 +1,5 @@ #include +#include #include #include #include @@ -206,6 +207,11 @@ std::chrono::nanoseconds run_workload( adapter.flush(); touch_watchdog(); + if (record_latency && recorder.completed() != recorder.recorded()) { + throw std::runtime_error( + "adapter.flush() returned before all recorded messages reached the sink"); + } + if (!measure_duration) return std::chrono::nanoseconds(0); auto t1 = std::chrono::steady_clock::now(); return std::chrono::duration_cast(t1 - t0); @@ -307,7 +313,7 @@ void append_csv( if (!out) throw std::runtime_error("Failed to open latency.csv for writing"); if (write_header) { - out << "lib,async,sink,producers,msg_bytes,total,p50_ns,p99_ns,p999_ns,throughput\n"; + out << "lib,async,sink,producers,msg_bytes,total,queue_capacity,p50_ns,p99_ns,p999_ns,throughput\n"; } out << library << ',' << (scenario.async ? 1 : 0) << ',' @@ -315,6 +321,7 @@ void append_csv( << scenario.producers << ',' << scenario.message_bytes << ',' << scenario.total_messages << ',' + << scenario.queue_capacity << ',' << summary.p50_ns << ',' << summary.p99_ns << ',' << summary.p999_ns << ',' @@ -333,6 +340,7 @@ void print_summary( << " producers=" << scenario.producers << " bytes=" << scenario.message_bytes << " total=" << scenario.total_messages + << " queue=" << scenario.queue_capacity << " p50=" << result.summary.p50_ns << "ns p99=" << result.summary.p99_ns << "ns p999=" << result.summary.p999_ns @@ -368,10 +376,14 @@ int main() { const std::size_t total_messages = get_env_size_t("LOGIT_BENCH_TOTAL", 200000); const std::size_t warmup_messages = get_env_size_t("LOGIT_BENCH_WARMUP", 4096); const std::size_t timeout_seconds = get_env_size_t("LOGIT_BENCH_TIMEOUT_SEC", 1200); + const std::size_t queue_capacity = get_env_size_t( + "LOGIT_BENCH_QUEUE_CAPACITY", + std::max(8192, total_messages * 2)); const BenchFilter filter = load_filter(); - LOGIT_SET_MAX_QUEUE(total_messages); + LOGIT_SET_MAX_QUEUE(queue_capacity); + LOGIT_SET_QUEUE_POLICY(LOGIT_QUEUE_BLOCK); if (timeout_seconds > 0) { watchdog = std::thread([timeout_seconds, &watchdog_done, &watchdog_progress]() { @@ -405,6 +417,12 @@ int main() { scenario.producers = producers; scenario.message_bytes = msg_bytes; scenario.total_messages = total_messages; + scenario.queue_capacity = queue_capacity; + + // Keep the global LogIt executor on the same + // bounded/blocking contract as the spdlog adapter. + LOGIT_SET_MAX_QUEUE(scenario.queue_capacity); + LOGIT_SET_QUEUE_POLICY(LOGIT_QUEUE_BLOCK); { std::ostringstream oss; diff --git a/bench/spdlog_flush_test.cpp b/bench/spdlog_flush_test.cpp new file mode 100644 index 00000000..7def3fe9 --- /dev/null +++ b/bench/spdlog_flush_test.cpp @@ -0,0 +1,31 @@ +#include +#include +#include + +#include "LatencyRecorder.hpp" +#include "Scenario.hpp" +#include "adapters/SpdlogAdapter.hpp" + +int main() { + logit_bench::Scenario scenario; + scenario.async = true; + scenario.sink = logit_bench::SinkKind::Null; + scenario.producers = 1; + scenario.message_bytes = 1; + scenario.total_messages = 64; + scenario.queue_capacity = 8; + + logit_bench::SpdlogAdapter adapter; + auto recorder = std::make_shared( + scenario.total_messages); + adapter.set_recorder_handle(recorder); + adapter.prepare(scenario, *recorder); + + for (std::size_t i = 0; i < scenario.total_messages; ++i) { + const auto token = recorder->begin(true); + adapter.log(token, std::string_view("x", 1)); + } + + adapter.flush(); + return recorder->completed() == scenario.total_messages ? 0 : 1; +} diff --git a/docs/benchmarks.md b/docs/benchmarks.md index cec72480..fcd2051d 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -23,14 +23,16 @@ reduced with `LOGIT_BENCH_TOTAL` and `LOGIT_BENCH_WARMUP`. ## Interpreting results -The default adapter measures a **prepared-record / dispatch pipeline**. It -constructs a `LogRecord` whose message is already prepared and calls the -dispatcher directly; it does not exercise the public `LOGIT_INFO(...)` macro -path, argument-name parsing, or `args_array` construction. A separate public -macro benchmark should be treated as a different scenario rather than mixed -into this comparison. The spdlog adapter likewise receives an already prepared -string. Compare implementations within the same mode and configuration; these -numbers are not a universal speed ranking. +The default adapter measures a **prepared-message / direct-dispatch pipeline**. +It constructs a `LogRecord` inside the timed `adapter.log()` call, copies the +message into owned `std::string` storage, and calls the dispatcher directly. It +does not exercise the public `LOGIT_INFO(...)` macro path, argument-name +parsing, or `args_array` construction. The spdlog adapter receives a +`string_view` over the prepared message. This is a deliberate comparison of +these two call contracts, not a claim that they do identical work. A separate +public macro benchmark should be treated as a different scenario. +Compare implementations within the same mode and configuration; these numbers +are not a universal speed ranking. The asynchronous measurement includes enqueue, worker wake-up/scheduling, and sink time. Results are sensitive to queue capacity, overflow policy, worker @@ -38,7 +40,7 @@ count, filesystem cache state, compiler, operating system, and hardware. ## Historical snapshot -The repository includes a comparison snapshot from 2025-12-05 in +The repository includes a **legacy** comparison snapshot from 2025-12-05 in `bench/results/latency-2025-12-05-10k.csv`: - workload: `LOGIT_BENCH_TOTAL=10000`, four producers, 200-byte messages; @@ -46,9 +48,11 @@ The repository includes a comparison snapshot from 2025-12-05 in second; - timestamp: 2025-12-05 03:18 UTC. -This is a historical, reproducible fixture rather than a current performance -claim. Re-run the harness on the target hardware before making deployment or -library-selection decisions. +This fixture predates the current benchmark dependency metadata and does not +record the spdlog version, compiler/toolchain, or harness commit. Treat it as +legacy context rather than a reproducible current performance claim. New +published figures must include the dependency versions, toolchain, harness +commit, queue capacity, and flush semantics used for the run. ## Harness details @@ -63,12 +67,18 @@ The current matrix covers 1, 4, 16, and 32 producers. CI intentionally uses a short Release smoke workload (`LOGIT_BENCH_TOTAL=20000`) for predictable run time. Larger publication runs (for example, one million messages plus warmup) belong on fixed or self-hosted hardware, where the results can be reproduced. - -The prepared-record/dispatch pipeline and a true public macro benchmark that +Both adapters receive the same explicit blocking queue capacity, configurable +through `LOGIT_BENCH_QUEUE_CAPACITY` (default: `max(8192, 2 * total)`). In +async mode `adapter.flush()` is a drain barrier: the spdlog adapter waits for a +worker-side flush marker, matching LogIt++'s executor drain. The measured +throughput interval therefore ends only after all recorded messages reached the +sink callback. + +The prepared-message/direct-dispatch pipeline and a true public macro benchmark that calls `LOGIT_INFO(...)` are separate scenarios with different work contracts; their results must not be presented as one number. -The prepared-record path is also the first target for the logger hot-path +The prepared-message path is also the first target for the logger hot-path regression checks. Logger strategy lists are published as an immutable copy-on-write snapshot, so a normal dispatch no longer takes the registry lock or allocates a temporary vector. `enabled` and `single_mode` are atomic state, diff --git a/docs/comparison-RU.md b/docs/comparison-RU.md index e59ae984..e71fe228 100644 --- a/docs/comparison-RU.md +++ b/docs/comparison-RU.md @@ -141,11 +141,14 @@ application diagnostics и severity/check macros. Это trade-offs област ## Снимок производительности -Сейчас в репозитории есть воспроизводимый adapter для **pipeline подготовленной -записи/dispatch** только для LogIt++ и spdlog, а не для всех шести проектов. -Поэтому таблица — **снимок LogIt++/spdlog pipeline**, а не рейтинг всех -библиотек. Полный публичный macro-путь `LOGIT_INFO(...)` здесь не измеряется: -в частности, не учитываются разбор имён аргументов и построение `args_array`. +Сейчас в репозитории есть воспроизводимый adapter для **pipeline подготовленного +сообщения/direct dispatch** только для LogIt++ и spdlog, а не для всех шести +проектов. Поэтому таблица — **legacy-снимок LogIt++/spdlog pipeline**, а не +рейтинг всех библиотек. Полный публичный macro-путь `LOGIT_INFO(...)` здесь не +измеряется: в частности, не учитываются разбор имён аргументов и построение +`args_array`. В timed-вызове LogIt++ создаёт `LogRecord` и копирует сообщение в +`std::string`, а spdlog получает подготовленный `string_view`; эти контракты +намеренно описаны явно и не выдаются за одинаковый объём работы. | Режим | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | | --- | --- | ---: | ---: | ---: | ---: | @@ -155,11 +158,17 @@ application diagnostics и severity/check macros. Это trade-offs област | Async | File | 255 323 ns | 651 384 msg/s | 5 001 140 ns | 1 153 976 msg/s | Условия snapshot: Release build, четыре producer-а, сообщения по 200 байт, -`LOGIT_BENCH_TOTAL=10000`, fixture от 05.12.2025. LogIt++ adapter получает -подготовленный `LogRecord`, а spdlog adapter — подготовленную строку. +`LOGIT_BENCH_TOTAL=10000`, fixture от 05.12.2025. В timed-вызове LogIt++ +создаёт `LogRecord` и владеющую копию сообщения, а spdlog получает +подготовленный `string_view`. Async-результаты также включают enqueue, wake-up/scheduling worker-а и работу sink-а. +Это legacy-fixture: в CSV не записаны версия spdlog, compiler/toolchain, +commit harness, queue capacity и протокол async drain. Не используйте его как +актуальное числовое сравнение; после изменения протокола нужно создать новый +версионированный fixture. + Методика описана в [`docs/benchmarks.md`](benchmarks.html), полный fixture — в [`latency-2025-12-05-10k.csv`](https://github.com/LimiNode/log-it-cpp/blob/main/bench/results/latency-2025-12-05-10k.csv). Harness пока не измеряет allocations на сообщение, binary size, compile time или diff --git a/docs/comparison.md b/docs/comparison.md index a5460d5a..19c13df3 100644 --- a/docs/comparison.md +++ b/docs/comparison.md @@ -147,12 +147,15 @@ universally better. ## Performance snapshot -The repository currently has a reproducible **prepared-record/dispatch +The repository currently has a reproducible **prepared-message/direct-dispatch pipeline** adapter for LogIt++ and spdlog, not for every project in the feature -table. The historical fixture below is therefore a **LogIt++/spdlog pipeline -snapshot**, not a ranking of all six projects. It does not measure the full -public `LOGIT_INFO(...)` macro path; in particular, it omits argument-name -parsing and `args_array` construction. +table. The historical fixture below is therefore a **legacy LogIt++/spdlog +pipeline snapshot**, not a ranking of all six projects. It does not measure the +full public `LOGIT_INFO(...)` macro path; in particular, it omits argument-name +parsing and `args_array` construction. The LogIt++ adapter constructs its +`LogRecord` and copies the message into `std::string` during the timed call, +while spdlog receives a prepared `string_view`; those call contracts are +intentionally documented rather than presented as identical. | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | | --- | --- | ---: | ---: | ---: | ---: | @@ -162,11 +165,16 @@ parsing and `args_array` construction. | Async | File | 255,323 ns | 651,384 msg/s | 5,001,140 ns | 1,153,976 msg/s | Snapshot conditions: Release build, four producers, 200-byte messages, -`LOGIT_BENCH_TOTAL=10000`, and the fixture recorded on 2025-12-05. The LogIt++ -adapter receives a prepared `LogRecord`, while the spdlog adapter receives a -prepared string. Async values also include +`LOGIT_BENCH_TOTAL=10000`, and the fixture recorded on 2025-12-05. The timed +LogIt++ adapter constructs a `LogRecord` and owns a message copy, while the +spdlog adapter receives a prepared `string_view`. Async values also include enqueue, worker wake-up/scheduling, and sink work. +The CSV is a legacy fixture: its spdlog version, compiler/toolchain, harness +commit, queue capacity, and async drain protocol were not recorded. Do not use +it as a current numeric comparison; regenerate a versioned fixture after the +benchmark protocol changes. + See [`docs/benchmarks.md`](benchmarks.html) for the methodology and [`bench/results/latency-2025-12-05-10k.csv`](https://github.com/LimiNode/log-it-cpp/blob/main/bench/results/latency-2025-12-05-10k.csv) for the complete fixture. The harness does not currently measure allocations From 7637b6ea8bd058b1003028eeb6e9d345156d23b0 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 12 Sep 2026 15:34:03 +0300 Subject: [PATCH 3/5] ci(bench): execute async flush regression Build the spdlog flush barrier test into the benchmark output directory and run it in the Linux benchmark job so the worker-side drain contract is continuously exercised. --- .github/workflows/ci.yml | 2 ++ bench/CMakeLists.txt | 8 ++++++++ 2 files changed, 10 insertions(+) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index be0ef8fa..59998ed7 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -31,6 +31,8 @@ jobs: - name: Build benchmarks # if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} run: cmake --build build-bench --target logit_bench + - name: Run spdlog async flush regression + run: ./build-bench/logit_bench_flush_test - name: Run latency benchmarks # if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} timeout-minutes: 20 diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index 14143ac9..a7e94f63 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -45,5 +45,13 @@ if(LOGIT_BENCH_WITH_SPDLOG) target_include_directories(logit_bench_flush_test PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}) target_compile_definitions(logit_bench_flush_test PRIVATE LOGIT_BENCH_HAVE_SPDLOG=1) target_link_libraries(logit_bench_flush_test PRIVATE spdlog::spdlog) + set_target_properties(logit_bench_flush_test PROPERTIES + RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR} + ) + foreach(config IN ITEMS DEBUG RELEASE RELWITHDEBINFO MINSIZEREL) + set_target_properties(logit_bench_flush_test PROPERTIES + RUNTIME_OUTPUT_DIRECTORY_${config} ${CMAKE_BINARY_DIR} + ) + endforeach() add_test(NAME logit_bench_flush_test COMMAND logit_bench_flush_test) endif() From 1c1332b4b51e5db24fe0f22a2c6527b63ab0f99c Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 12 Sep 2026 15:34:19 +0300 Subject: [PATCH 4/5] ci(bench): build flush regression target Build the dedicated spdlog flush barrier executable before running it in the benchmark workflow. --- .github/workflows/ci.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 59998ed7..08a266a8 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -30,7 +30,7 @@ jobs: run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -DCMAKE_BUILD_TYPE=Release -DCMAKE_CXX_STANDARD=${{ matrix.std }} -DLOGIT_WITH_SYSLOG=ON -DLOGIT_WITH_WIN_EVENT_LOG=OFF - name: Build benchmarks # if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} - run: cmake --build build-bench --target logit_bench + run: cmake --build build-bench --target logit_bench logit_bench_flush_test - name: Run spdlog async flush regression run: ./build-bench/logit_bench_flush_test - name: Run latency benchmarks From 11185fb1b764725f969794bdb10d76f1b113529f Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 12 Sep 2026 16:47:16 +0300 Subject: [PATCH 5/5] fix(bench): reject mismatched queue and CSV schemas Reject zero comparative queue capacity instead of silently applying different LogIt++ and spdlog limits. Validate the latency CSV header before appending rows so legacy results cannot be mixed with the queue-capacity schema. --- bench/logit_bench.cpp | 26 +++++++++++++++++++++++++- docs/benchmarks.md | 9 ++++++++- 2 files changed, 33 insertions(+), 2 deletions(-) diff --git a/bench/logit_bench.cpp b/bench/logit_bench.cpp index c88db2ca..390e75ab 100644 --- a/bench/logit_bench.cpp +++ b/bench/logit_bench.cpp @@ -305,15 +305,34 @@ void append_csv( { namespace fs = std::filesystem; const fs::path csv_path{"bench/results/latency.csv"}; + const std::string expected_header = + "lib,async,sink,producers,msg_bytes,total,queue_capacity," + "p50_ns,p99_ns,p999_ns,throughput"; fs::create_directories(csv_path.parent_path()); const bool write_header = !fs::exists(csv_path) || fs::file_size(csv_path) == 0; + if (!write_header) { + std::ifstream in(csv_path); + std::string header; + if (!in || !std::getline(in, header)) { + throw std::runtime_error("Failed to read latency.csv schema header"); + } + if (!header.empty() && header.back() == '\r') { + header.pop_back(); + } + if (header != expected_header) { + throw std::runtime_error( + "Unsupported bench/results/latency.csv schema; rename or remove " + "the existing file before running this benchmark"); + } + } + std::ofstream out(csv_path, std::ios::app); if (!out) throw std::runtime_error("Failed to open latency.csv for writing"); if (write_header) { - out << "lib,async,sink,producers,msg_bytes,total,queue_capacity,p50_ns,p99_ns,p999_ns,throughput\n"; + out << expected_header << '\n'; } out << library << ',' << (scenario.async ? 1 : 0) << ',' @@ -379,6 +398,11 @@ int main() { const std::size_t queue_capacity = get_env_size_t( "LOGIT_BENCH_QUEUE_CAPACITY", std::max(8192, total_messages * 2)); + if (queue_capacity == 0) { + throw std::invalid_argument( + "LOGIT_BENCH_QUEUE_CAPACITY must be greater than zero for " + "a comparative benchmark"); + } const BenchFilter filter = load_filter(); diff --git a/docs/benchmarks.md b/docs/benchmarks.md index fcd2051d..9df75b80 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -72,7 +72,14 @@ through `LOGIT_BENCH_QUEUE_CAPACITY` (default: `max(8192, 2 * total)`). In async mode `adapter.flush()` is a drain barrier: the spdlog adapter waits for a worker-side flush marker, matching LogIt++'s executor drain. The measured throughput interval therefore ends only after all recorded messages reached the -sink callback. +sink callback. A queue capacity of `0` is rejected because it would mean an +unlimited LogIt++ queue but a bounded spdlog queue and invalidate the +comparison. + +The current CSV schema includes `queue_capacity`. Before appending, the harness +validates the existing `bench/results/latency.csv` header and fails with a +rename/remove instruction when it finds an older schema. Existing result files +are never silently rewritten or mixed with rows from a different schema. The prepared-message/direct-dispatch pipeline and a true public macro benchmark that calls `LOGIT_INFO(...)` are separate scenarios with different work contracts;