diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 66ef7812..08a266a8 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -27,10 +27,12 @@ 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 + 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 # 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 ebffc7cf..a7e94f63 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -31,9 +31,27 @@ 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() 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) + 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() 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/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/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..2d282e9f 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -9,6 +9,7 @@ #include #include #include +#include #include #include @@ -43,7 +44,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)); @@ -63,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; @@ -104,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); @@ -146,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 ae48803c..390e75ab 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); @@ -299,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,p50_ns,p99_ns,p999_ns,throughput\n"; + out << expected_header << '\n'; } out << library << ',' << (scenario.async ? 1 : 0) << ',' @@ -315,6 +340,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 +359,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 @@ -361,17 +388,26 @@ 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): 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)); + 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(); - 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 +441,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 8c44151c..9df75b80 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -12,17 +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. +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. @@ -32,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; @@ -40,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 @@ -52,3 +62,35 @@ 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. +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. 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; +their results must not be presented as one number. + +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, +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..e71fe228 100644 --- a/docs/comparison-RU.md +++ b/docs/comparison-RU.md @@ -141,9 +141,14 @@ application diagnostics и severity/check macros. Это trade-offs област ## Снимок производительности -Сейчас в репозитории есть воспроизводимый adapter только для LogIt++ и spdlog, -а не для всех шести проектов. Поэтому таблица — **снимок LogIt++/spdlog -pipeline**, а не рейтинг всех библиотек. +Сейчас в репозитории есть воспроизводимый 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 | | --- | --- | ---: | ---: | ---: | ---: | @@ -153,11 +158,17 @@ 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. В 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 133b82f2..19c13df3 100644 --- a/docs/comparison.md +++ b/docs/comparison.md @@ -147,10 +147,15 @@ 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-message/direct-dispatch +pipeline** adapter for LogIt++ and spdlog, not for every project in the feature +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 | | --- | --- | ---: | ---: | ---: | ---: | @@ -160,11 +165,16 @@ projects. | 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++ -path may include argument-name extraction and structured value packing, 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 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; +}