From 9b9ace73c9a6e2f1f645c6f1b8d9ddab81a614da Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 08:31:41 +0300 Subject: [PATCH 01/16] docs(bench): refresh benchmark snapshot Rerun LOGIT_BENCH_TOTAL=10000 with the latest spdlog adapter and update the Dec 04 snapshot CSV plus benchmark tables in README (EN/RU) and Doxygen. --- README-RU.md | 47 ++++++++ README.md | 39 +++++- bench/LatencyRecorder.hpp | 17 ++- bench/adapters/SpdlogAdapter.cpp | 145 +++++++---------------- bench/results/latency-2025-12-04-10k.csv | 73 ++++++++++++ docs/mainpage.dox | 41 +++++++ 6 files changed, 260 insertions(+), 102 deletions(-) create mode 100644 bench/results/latency-2025-12-04-10k.csv diff --git a/README-RU.md b/README-RU.md index 12073c5..53df009 100644 --- a/README-RU.md +++ b/README-RU.md @@ -118,6 +118,16 @@ int main() { LOGIT_SYSERR_ERROR("Ошибка удаления временного каталога"); ``` +## Обратное давление и горячее изменение размера + +Асинхронный `TaskExecutor` поддерживает как очередь на основе `std::deque` под мьютексом, так и опциональный lock-free MPSC ring + (включается флагом `LOGIT_USE_MPSC_RING`). Политики переполнения (`Block`, `DropNewest`, `DropOldest`) ведут себя одинаково в + обеих конфигурациях; в MPSC-режиме `DropOldest` намеренно отбрасывает **входящую** задачу, чтобы не нарушать порядок уже приня +тых. Кольцевой буфер по умолчанию вмещает `LOGIT_TASK_EXECUTOR_DEFAULT_RING_CAPACITY` задач (1024) и может быть перенастроен ком +бинацией `LOGIT_SET_MAX_QUEUE(...)` с этим макросом, если приложению требуется другой базовый объём. В сборках с MPSC допускаетс +я "горячее" изменение размера очереди без потери принятых задач — продюсеры кратковременно ждут, пока поток-воркер пересобирает +буфер. + ## Возможности - **Гибкое форматирование логов**: @@ -667,6 +677,43 @@ LogIt++ зависит от *time-shield-cpp*, который находится LogIt++ включает библиотеку *fmt* для форматирования с `{}`. Чтобы использовать макросы `LOGIT_FMT_*` и `LOGIT_SCOPE_FMT_*`, соберите библиотеку с опцией CMake `-DLOGIT_WITH_FMT=ON`. +## Опции CMake + +Все параметры сборки перечислены ниже: + +- `LOGIT_CPP_BUILD_TESTS` (по умолчанию: ON, если проект собирается на верхнем уровне) — сборка тестов. +- `LOGIT_CPP_BUILD_EXAMPLES` (по умолчанию: OFF) — сборка примеров. +- `LOGIT_BENCH_ENABLE` (по умолчанию: OFF) — сборка бенчмарков; `LOGIT_BENCH_WITH_SPDLOG` (по умолчанию: OFF) добавляет сравнение со spdlog. +- `LOGIT_WITH_GZIP` / `LOGIT_WITH_ZSTD` (по умолчанию: OFF) — поддержка gzip или zstd для ротируемых файлов. +- `LOGIT_WITH_FMT` (по умолчанию: OFF) — подключить макросы в стиле `{}`; `LOGIT_USE_SUBMODULES` (по умолчанию: OFF) разрешает использовать вложенные зависимости fmt/time-shield при отсутствии системных пакетов. +- `LOGIT_WITH_SYSLOG` (по умолчанию: ON на Unix-подобных системах) — сборка бэкенда syslog. +- `LOGIT_WITH_WIN_EVENT_LOG` (по умолчанию: ON в Windows) — сборка бэкенда Windows Event Log. +- `LOGIT_FORCE_ASYNC_OFF` (по умолчанию: OFF) — принудительно отключить асинхронное выполнение даже в многопоточных сборках. +- `LOGIT_USE_MPSC_RING` (по умолчанию: ON) — использовать lock-free очередь вместо варианта на `std::deque`. +- `LOGIT_ENABLE_DROP_OLDEST_SLOWPATH` (по умолчанию: ON) — скомпилировать медленный путь для `DropOldest`, когда кольцо заполнено. +- `LOGIT_EMSCRIPTEN` (по умолчанию: ON при сборке Emscripten) — подстройка под однопоточные среды WebAssembly. + +## Бенчмарки + +Запустите `./build/bench/logit_bench`, чтобы получить полный набор измерений (sync/async × null/file × количество продюсеров × размер сообщений). Результаты дописываются в `bench/results/latency.csv` по одной строке на каждую библиотеку/комбинацию. При необходимости сократите нагрузку с помощью переменных окружения `LOGIT_BENCH_TOTAL` и `LOGIT_BENCH_WARMUP`. + +### Последний снимок (04.12.2025) + +- Сборка: `Release`, `LOGIT_BENCH_ENABLE=ON`, `LOGIT_BENCH_WITH_SPDLOG=ON`, `LOGIT_USE_MPSC_RING=ON` (по умолчанию). +- Нагрузка: `LOGIT_BENCH_TOTAL=10000`, 4 продюсера, размер сообщений 200 байт для таблицы сравнения (остальные комбинации см. в `bench/results/latency-2025-12-04-10k.csv`). +- Метрики: медианная задержка (`p50`) в наносекундах и достигнутая пропускная способность (сообщений/с). +- Железо: 3 vCPU (Intel Xeon E5-2673 v4 @ 2.30GHz) в виртуальной машине, одна NUMA-нода. +- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 05:27 UTC). + +| Режим | Приёмник | LogIt++ p50 | Пропускная (LogIt++) | spdlog p50 | Пропускная (spdlog) | +|-------|----------|-------------|----------------------|------------|---------------------| +| Sync | Null | 159 нс | 2 559 124 сооб./с | 302 нс | 2 747 733 сооб./с | +| Sync | File | 108 нс | 2 081 540 сооб./с | 365 нс | 1 304 177 сооб./с | +| Async | Null | 44 699 нс | 753 078 сооб./с | 1 499 973 нс | 913 881 сооб./с | +| Async | File | 996 466 нс | 850 021 сооб./с | 3 999 290 нс | 912 399 сооб./с | + +**Выводы:** в этом снимке оба логгера выдают миллионы сообщений в секунду в синхронных режимах (у spdlog в этот запуск чуть выше пропускная) при субмикросекундных p50. В асинхронных сценариях LogIt++ держит end-to-end p50 на уровне десятков–сотен микросекунд, тогда как spdlog уходит в миллисекунды; пропускная обоих кластеризуется вокруг 0.75–0.9 млн сооб./с в зависимости от приёмника. + ## Системные бэкенды LogIt++ может отправлять сообщения в системные журналы. diff --git a/README.md b/README.md index 6c48578..0c3de2a 100644 --- a/README.md +++ b/README.md @@ -137,7 +137,10 @@ policies (`Block`, `DropNewest`, `DropOldest`) behave consistently across both implementations, with the MPSC build intentionally dropping the *incoming* task for `DropOldest` to keep accepted work ordered. The ring build also allows "hot" queue resizes where producers briefly wait while the worker rebuilds the -ring buffer without losing in-flight tasks. See +ring buffer without losing in-flight tasks. The default MPSC buffer holds +`LOGIT_TASK_EXECUTOR_DEFAULT_RING_CAPACITY` tasks (1024 by default) and can be +retuned by combining `LOGIT_SET_MAX_QUEUE(...)` with the compile-time macro if +your workload needs a different baseline. See [`docs/TaskExecutor.md`](docs/TaskExecutor.md) for a full breakdown and tuning tips. @@ -706,6 +709,22 @@ If you are using an IDE like **Visual Studio** or **CLion**, you can add the inc LogIt++ includes the *fmt* library for `{}`-based formatting. To use the `LOGIT_FMT_*` and `LOGIT_SCOPE_FMT_*` macros, build the library with the CMake option `-DLOGIT_WITH_FMT=ON`. +## CMake options + +The following toggles cover all build-time features: + +- `LOGIT_CPP_BUILD_TESTS` (default: ON when the project is the root build) — build the test suite. +- `LOGIT_CPP_BUILD_EXAMPLES` (default: OFF) — build the example programs. +- `LOGIT_BENCH_ENABLE` (default: OFF) — build benchmarks; `LOGIT_BENCH_WITH_SPDLOG` (default: OFF) also builds the spdlog comparisons. +- `LOGIT_WITH_GZIP` / `LOGIT_WITH_ZSTD` (defaults: OFF) — enable gzip or zstd support for rotated files. +- `LOGIT_WITH_FMT` (default: OFF) — include the `{}`-style formatting macros; enable `LOGIT_USE_SUBMODULES` (default: OFF) to pull the bundled fmt/time-shield fallbacks when system packages are missing. +- `LOGIT_WITH_SYSLOG` (default: ON on Unix-like targets) — build the syslog backend. +- `LOGIT_WITH_WIN_EVENT_LOG` (default: ON on Windows) — build the Windows Event Log backend. +- `LOGIT_FORCE_ASYNC_OFF` (default: OFF) — force synchronous logging even in multi-threaded builds. +- `LOGIT_USE_MPSC_RING` (default: ON) — use the lock-free task queue instead of the mutex-backed deque. +- `LOGIT_ENABLE_DROP_OLDEST_SLOWPATH` (default: ON) — compile the slow-path used by `DropOldest` when the ring is full. +- `LOGIT_EMSCRIPTEN` (default: ON under Emscripten toolchains) — adjust the build for single-threaded WebAssembly environments. + ## System Backends LogIt++ can forward messages to system logging facilities. @@ -750,6 +769,24 @@ Run `./build/bench/logit_bench` to record the full matrix (sync/async × null/fi are appended to `bench/results/latency.csv` with one row per library/combination. Override the workload via `LOGIT_BENCH_TOTAL` and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. +### Latest snapshot (Dec 04, 2025) + +- Build: `Release`, `LOGIT_BENCH_ENABLE=ON`, `LOGIT_BENCH_WITH_SPDLOG=ON`, `LOGIT_USE_MPSC_RING=ON` (default). +- Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, message size 200 bytes for the comparison table (all other sizes/counts + are in `bench/results/latency-2025-12-04-10k.csv`). +- Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). +- Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:27 UTC). + +| Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | +|------|------|-------------|--------------------|------------|-------------------| +| Sync | Null | 159 ns | 2,559,124 msg/s | 302 ns | 2,747,733 msg/s | +| Sync | File | 108 ns | 2,081,540 msg/s | 365 ns | 1,304,177 msg/s | +| Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | +| Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | + +**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes (spdlog slightly higher throughput this run), with sub-microsecond p50 for both. Asynchronously, LogIt++ keeps end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. + --- ## Documentation diff --git a/bench/LatencyRecorder.hpp b/bench/LatencyRecorder.hpp index a9b65b5..6969f82 100644 --- a/bench/LatencyRecorder.hpp +++ b/bench/LatencyRecorder.hpp @@ -39,7 +39,12 @@ class LatencyRecorder { : m_values(total), m_expected(total), m_next_slot(0), - m_completed(0) {} + m_completed(0), + m_slot_done(total) { + for (auto& flag : m_slot_done) { + flag.store(0, std::memory_order_relaxed); + } + } /** * Reserve a slot (if record==true) and capture t0 using steady_clock. @@ -62,11 +67,18 @@ class LatencyRecorder { /// Capture t1 and store (t1 - t0) into the reserved slot. void complete(const Token& token) { if (!token.active) return; + if (token.slot >= m_expected) { + throw std::out_of_range("LatencyRecorder capacity exceeded"); + } + std::uint8_t expected = 0; + if (!m_slot_done[token.slot].compare_exchange_strong( + expected, 1, std::memory_order_acq_rel)) { + return; // duplicate completion -> ignore + } const auto t1_ns = now(); m_values[token.slot] = t1_ns - token.t0_ns; // distinct slots -> no data race const auto done = m_completed.fetch_add(1, std::memory_order_acq_rel) + 1; if (done == m_expected) { - std::lock_guard lk(m_wait_mx); m_wait_cv.notify_all(); } } @@ -116,6 +128,7 @@ class LatencyRecorder { const std::size_t m_expected; // total messages to record std::atomic m_next_slot; std::atomic m_completed; + std::vector> m_slot_done; mutable std::condition_variable m_wait_cv; mutable std::mutex m_wait_mx; }; diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index e1ab0f3..14ac696 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -3,15 +3,15 @@ #ifdef LOGIT_BENCH_HAVE_SPDLOG #include -#include -#include +#include +#include #include #include #include #include +#include #include #include -#include #include #include @@ -26,6 +26,7 @@ constexpr std::size_t kDefaultQueue = 8192; struct MessagePayload { LatencyRecorder::Token token; std::string text; + std::string wire; }; } // namespace @@ -33,15 +34,9 @@ class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { public: MeasuringSink() = default; - void configure(const Scenario& scenario, LatencyRecorder& recorder) { + void configure(const Scenario& scenario, std::shared_ptr recorder) { m_sink = scenario.sink; - m_recorder = &recorder; - { - std::lock_guard lock(m_pending_mx); - m_pending.clear(); - m_retired.clear(); - m_pending_count = 0; - } + m_recorder = std::move(recorder); if (m_sink == SinkKind::File) { std::filesystem::create_directories("bench/results"); std::lock_guard lock(m_mutex); @@ -53,104 +48,52 @@ class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { } } - void track_token(const LatencyRecorder::Token& token, std::unique_ptr payload) { - std::lock_guard lock(m_pending_mx); - m_pending.push_back(Pending{std::move(payload), token}); - ++m_pending_count; - } - void log(const spdlog::details::log_msg& msg) override { - const char* func = msg.source.funcname; - if (msg.payload.size() == 0 || !func || *func == '\0') { - return; // Flush/control messages have no payload attached. + std::string_view wire(msg.payload.data(), msg.payload.size()); + const auto sep = wire.find('|'); + if (sep == std::string_view::npos) { + return; // Control messages or malformed payloads. } - const auto* payload_ptr = reinterpret_cast(func); - auto* payload = const_cast(payload_ptr); - consume(*payload, payload); - } - - void set_pattern(const std::string&) override {} - - void set_formatter(std::unique_ptr) override {} - - void flush() override { - std::lock_guard lock(m_mutex); - if (m_file.is_open()) { - m_file.flush(); + std::uintptr_t raw_ptr = 0; + const auto* begin = wire.data(); + const auto* end = begin + sep; + if (std::from_chars(begin, end, raw_ptr, 16).ec != std::errc()) { + return; } - } - void complete_pending() { - std::vector pending; - { - std::unique_lock lock(m_pending_mx); - m_pending_cv.wait_for(lock, std::chrono::milliseconds(100), [&]{ return m_pending_count == 0; }); - pending.swap(m_pending); - m_pending_count = 0; + auto* payload = reinterpret_cast(raw_ptr); + if (!payload) { + return; } - std::vector> retired; - retired.reserve(pending.size()); - for (auto& entry : pending) { - if (entry.token.active && m_recorder) { - m_recorder->complete(entry.token); - } - if (entry.payload) { - retired.push_back(std::move(entry.payload)); + if (payload->token.active && m_recorder) { + m_recorder->complete(payload->token); + } + if (m_sink == SinkKind::File) { + std::lock_guard lock(m_mutex); + if (m_file.is_open()) { + m_file << payload->text << '\n'; } } - m_retired.insert(m_retired.end(), - std::make_move_iterator(retired.begin()), - std::make_move_iterator(retired.end())); + delete payload; } -private: - void consume(const MessagePayload& payload, MessagePayload* payload_ptr) { - LatencyRecorder::Token token = payload.token; - std::unique_ptr owned; - { - std::lock_guard lock(m_pending_mx); - auto it = std::find_if(m_pending.begin(), m_pending.end(), [&](const Pending& p){ return p.payload.get() == payload_ptr; }); - if (it != m_pending.end()) { - token = it->token; - owned = std::move(it->payload); - m_pending.erase(it); - --m_pending_count; - if (m_pending_count == 0) m_pending_cv.notify_all(); - } - } + void set_pattern(const std::string&) override {} - const MessagePayload& msg = owned ? *owned : payload; + void set_formatter(std::unique_ptr) override {} - if (token.active && m_recorder) { - m_recorder->complete(token); - } - if (owned) { - std::lock_guard lock(m_pending_mx); - m_retired.push_back(std::move(owned)); - } - if (m_sink == SinkKind::File) { - std::lock_guard lock(m_mutex); - if (m_file.is_open()) { - m_file << msg.text << '\n'; - } + void flush() override { + std::lock_guard lock(m_mutex); + if (m_file.is_open()) { + m_file.flush(); } } SinkKind m_sink = SinkKind::Null; - LatencyRecorder* m_recorder = nullptr; + std::shared_ptr m_recorder; std::ofstream m_file; std::mutex m_mutex; - struct Pending { - std::unique_ptr payload; - LatencyRecorder::Token token; - }; - std::vector m_pending; - std::vector> m_retired; - std::size_t m_pending_count = 0; - std::condition_variable m_pending_cv; - std::mutex m_pending_mx; }; SpdlogAdapter::SpdlogAdapter() = default; @@ -170,7 +113,11 @@ void SpdlogAdapter::prepare(const Scenario& scenario, LatencyRecorder& recorder) spdlog::shutdown(); m_sink = std::make_shared(); - m_sink->configure(scenario, recorder); + auto recorder_handle = m_recorder_handle; + if (!recorder_handle) { + recorder_handle = std::shared_ptr(&recorder, [](LatencyRecorder*){}); + } + m_sink->configure(scenario, recorder_handle); m_async = scenario.async; std::string logger_name = m_async ? "logit_bench_async" : "logit_bench_sync"; @@ -197,15 +144,16 @@ void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view me if (!m_logger) { return; } - auto payload = std::make_unique(); + auto* payload = new MessagePayload(); payload->token = token; payload->text.assign(message.data(), message.size()); - MessagePayload* payload_ptr = payload.get(); - if (m_sink) { - m_sink->track_token(token, std::move(payload)); - } - spdlog::source_loc loc{nullptr, 0, reinterpret_cast(payload_ptr)}; - m_logger->log(loc, spdlog::level::info, spdlog::string_view_t(payload_ptr->text)); + std::ostringstream oss; + oss << std::hex << static_cast(reinterpret_cast(payload)) + << '|' << payload->text; + payload->wire = oss.str(); + + spdlog::source_loc loc{}; + m_logger->log(loc, spdlog::level::info, spdlog::string_view_t(payload->wire)); } void SpdlogAdapter::flush() { @@ -213,7 +161,6 @@ void SpdlogAdapter::flush() { m_logger->flush(); } if (m_sink) { - m_sink->complete_pending(); m_sink->flush(); } } diff --git a/bench/results/latency-2025-12-04-10k.csv b/bench/results/latency-2025-12-04-10k.csv new file mode 100644 index 0000000..3bc9672 --- /dev/null +++ b/bench/results/latency-2025-12-04-10k.csv @@ -0,0 +1,73 @@ +lib,async,sink,producers,msg_bytes,total,p50_ns,p99_ns,p999_ns,throughput +log-it-cpp,0,null,1,40,10000,92,182,315,5357529.36 +log-it-cpp,0,null,1,200,10000,106,200,354,4900303.33 +log-it-cpp,0,null,1,1024,10000,112,221,364,4890032.94 +log-it-cpp,0,null,4,40,10000,93,7341,34666,3056898.98 +log-it-cpp,0,null,4,200,10000,159,7561,30513,2559124.08 +log-it-cpp,0,null,4,1024,10000,219,746,20852,2564110.45 +log-it-cpp,0,null,16,40,10000,117,120838,411764,2238446.48 +log-it-cpp,0,null,16,200,10000,110,85115,554545,2437013.56 +log-it-cpp,0,null,16,1024,10000,124,89455,651284,2160426.81 +log-it-cpp,0,file,1,40,10000,92,199,338,3591300.00 +log-it-cpp,0,file,1,200,10000,108,218,363,2642238.99 +log-it-cpp,0,file,1,1024,10000,131,345,501,1168214.47 +log-it-cpp,0,file,4,40,10000,103,14763,67392,2189043.14 +log-it-cpp,0,file,4,200,10000,108,4885,84935,2081539.74 +log-it-cpp,0,file,4,1024,10000,130,28959,118834,775085.29 +log-it-cpp,0,file,16,40,10000,92,63285,592951,2071042.56 +log-it-cpp,0,file,16,200,10000,120,100965,1188611,1406287.00 +log-it-cpp,0,file,16,1024,10000,126,13572,2525084,966869.26 +log-it-cpp,1,null,1,40,10000,6167,140477,160222,1382398.72 +log-it-cpp,1,null,1,200,10000,2417634,3757859,3783013,653858.07 +log-it-cpp,1,null,1,1024,10000,5753043,20554446,20867541,308368.51 +log-it-cpp,1,null,4,40,10000,6898,87823,106759,880174.84 +log-it-cpp,1,null,4,200,10000,44699,511957,553072,753077.77 +log-it-cpp,1,null,4,1024,10000,24312,1233924,1504219,462569.97 +log-it-cpp,1,null,16,40,10000,82385,1664170,1738195,1284781.28 +log-it-cpp,1,null,16,200,10000,50742,1497647,1961082,834075.59 +log-it-cpp,1,null,16,1024,10000,639279,5262976,8799440,394638.68 +log-it-cpp,1,file,1,40,10000,7088,1246048,1282644,1332271.78 +log-it-cpp,1,file,1,200,10000,4942082,6824108,6872425,663083.63 +log-it-cpp,1,file,1,1024,10000,16798493,27161411,27182741,285371.76 +log-it-cpp,1,file,4,40,10000,11576,751585,770923,1134828.27 +log-it-cpp,1,file,4,200,10000,996466,2978576,2996734,850021.31 +log-it-cpp,1,file,4,1024,10000,496132,4058713,4114558,391014.03 +log-it-cpp,1,file,16,40,10000,138088,686063,803493,1189221.99 +log-it-cpp,1,file,16,200,10000,350348,917351,1250075,1105190.48 +log-it-cpp,1,file,16,1024,10000,1442846,4242603,6039678,414511.81 +spdlog,0,null,1,40,10000,269,549,6532,2602869.30 +spdlog,0,null,1,200,10000,273,554,733,2655273.07 +spdlog,0,null,1,1024,10000,426,1032,6698,1544485.98 +spdlog,0,null,4,40,10000,395,739,6905,3372228.62 +spdlog,0,null,4,200,10000,302,688,3691,2747732.85 +spdlog,0,null,4,1024,10000,600,1373,18289,2235938.46 +spdlog,0,null,16,40,10000,380,686,17913,2782964.14 +spdlog,0,null,16,200,10000,398,706,2082,2564190.67 +spdlog,0,null,16,1024,10000,533,1062,11665,2606821.01 +spdlog,0,file,1,40,10000,273,541,906,2196497.82 +spdlog,0,file,1,200,10000,279,586,1183,1755113.88 +spdlog,0,file,1,1024,10000,473,1056,6362,810368.63 +spdlog,0,file,4,40,10000,348,706,11876,1776918.85 +spdlog,0,file,4,200,10000,365,861,17962,1304176.98 +spdlog,0,file,4,1024,10000,520,1326,8459,571419.27 +spdlog,0,file,16,40,10000,412,994,50616,1657493.27 +spdlog,0,file,16,200,10000,286,757,20477,1417268.51 +spdlog,0,file,16,1024,10000,466,1231,9489,653502.17 +spdlog,1,null,1,40,10000,7677,152389,183779,507180.79 +spdlog,1,null,1,200,10000,2169183,4708314,4762451,370023.78 +spdlog,1,null,1,1024,10000,84415,11790063,11899544,241879.85 +spdlog,1,null,4,40,10000,132194,511162,535193,870022.62 +spdlog,1,null,4,200,10000,1499973,2722962,2752323,913881.31 +spdlog,1,null,4,1024,10000,22604956,32839963,32878927,274923.01 +spdlog,1,null,16,40,10000,4699829,6306158,6603405,1115126.81 +spdlog,1,null,16,200,10000,4668421,6440606,6597072,1062143.13 +spdlog,1,null,16,1024,10000,38525338,42711383,44283213,234910.83 +spdlog,1,file,1,40,10000,347073,3865593,3918211,963829.32 +spdlog,1,file,1,200,10000,6276270,10251032,10333565,651659.22 +spdlog,1,file,1,1024,10000,55686311,112313139,113323355,79589.07 +spdlog,1,file,4,40,10000,2242665,3269778,3302128,1222780.30 +spdlog,1,file,4,200,10000,3999290,5321481,5391253,912398.77 +spdlog,1,file,4,1024,10000,37864894,46101563,46177514,206840.95 +spdlog,1,file,16,40,10000,2941855,3332657,4647595,1114334.14 +spdlog,1,file,16,200,10000,5490791,6395102,6666719,1418040.65 +spdlog,1,file,16,1024,10000,9481221,10600867,11288830,977566.03 diff --git a/docs/mainpage.dox b/docs/mainpage.dox index c8b565e..c91c136 100644 --- a/docs/mainpage.dox +++ b/docs/mainpage.dox @@ -15,6 +15,10 @@ Key characteristics: See the macro examples below or browse the `examples/` directory for focused demonstrations, including queue tuning and crash handling. +\section backpressure_sec Backpressure and queue variants + +The asynchronous `TaskExecutor` supports both a mutex-protected deque and an optional lock-free MPSC ring (enable via `LOGIT_USE_MPSC_RING`). Overflow policies (`Block`, `DropNewest`, `DropOldest`) behave the same in both variants, with the MPSC build intentionally dropping the **incoming** task for `DropOldest` to preserve the ordering of accepted work. The ring uses `LOGIT_TASK_EXECUTOR_DEFAULT_RING_CAPACITY` entries (1024 by default); adjust the baseline with that macro alongside `LOGIT_SET_MAX_QUEUE(...)` if your workload needs a different buffer size. MPSC builds also allow "hot" resizes where producers briefly wait while the worker rebuilds the ring without losing in-flight tasks. + \section macro_examples_sec Macro Examples \subsection macro_examples_long Long-form macros @@ -660,6 +664,43 @@ If you are using an IDE like **Visual Studio** or **CLion**, you can add the inc LogIt++ ships with the **fmt** library for `{}`-style formatting. To use the `LOGIT_FMT_*` and `LOGIT_SCOPE_FMT_*` macros, build the library with the CMake option `-DLOGIT_WITH_FMT=ON`. +\subsection cmake_options_sec CMake options + +All build-time toggles: + +- `LOGIT_CPP_BUILD_TESTS` (default: ON when this repository is the top-level project) — build the test suite. +- `LOGIT_CPP_BUILD_EXAMPLES` (default: OFF) — build the example programs. +- `LOGIT_BENCH_ENABLE` (default: OFF) — build the benchmarks; `LOGIT_BENCH_WITH_SPDLOG` (default: OFF) adds the spdlog comparison binaries. +- `LOGIT_WITH_GZIP` / `LOGIT_WITH_ZSTD` (defaults: OFF) — enable gzip or zstd support for rotated files. +- `LOGIT_WITH_FMT` (default: OFF) — include the `{}`-style formatting macros; enable `LOGIT_USE_SUBMODULES` (default: OFF) to use the bundled fmt/time-shield fallbacks if system packages are missing. +- `LOGIT_WITH_SYSLOG` (default: ON on Unix-like targets) — build the syslog backend. +- `LOGIT_WITH_WIN_EVENT_LOG` (default: ON on Windows) — build the Windows Event Log backend. +- `LOGIT_FORCE_ASYNC_OFF` (default: OFF) — force synchronous logging even on multi-threaded builds. +- `LOGIT_USE_MPSC_RING` (default: ON) — enable the lock-free task queue instead of the mutex-backed deque. +- `LOGIT_ENABLE_DROP_OLDEST_SLOWPATH` (default: ON) — include the drop-oldest slow-path used when the ring is full. +- `LOGIT_EMSCRIPTEN` (default: ON when building under Emscripten) — adjust the build for single-threaded WebAssembly targets. + +\section bench_sec Benchmarks + +Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/file × producer counts × message sizes). Results are appended to `bench/results/latency.csv` with one row per library/combination. Adjust the workload with `LOGIT_BENCH_TOTAL` and `LOGIT_BENCH_WARMUP` if you need a lighter pass. + +\subsection bench_latest Latest snapshot (Dec 04, 2025) + +- Build: `Release`, `LOGIT_BENCH_ENABLE=ON`, `LOGIT_BENCH_WITH_SPDLOG=ON`, `LOGIT_USE_MPSC_RING=ON` (default). +- Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, 200-byte messages for the comparison table (see `bench/results/latency-2025-12-04-10k.csv` for other sizes/counts). +- Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). +- Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:27 UTC). + +| Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | +|------|------|-------------|--------------------|------------|-------------------| +| Sync | Null | 159 ns | 2,559,124 msg/s | 302 ns | 2,747,733 msg/s | +| Sync | File | 108 ns | 2,081,540 msg/s | 365 ns | 1,304,177 msg/s | +| Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | +| Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | + +**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes (spdlog slightly higher throughput this run), with sub-microsecond p50 for both. Asynchronously, LogIt++ keeps end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. + \subsection step5 Step 5: Build and Run Your Project After adding the necessary include paths, you can proceed to build and run your project. LogIt++ is designed to be easy to integrate and requires no linking since it's header-only. From 56eeefa70ccfb6d20cdebeb801412a45a1d754d7 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 18:22:29 +0300 Subject: [PATCH 02/16] perf(bench): streamline adapters and update snapshot Optimize spdlog pointer encoding to avoid iostream overhead, reduce async null copies in the LogIt adapter, and refresh the documented benchmark snapshot to match the latest run. --- README-RU.md | 4 ++-- README.md | 4 ++-- bench/adapters/LogItAdapter.cpp | 10 ++++++++-- bench/adapters/SpdlogAdapter.cpp | 19 ++++++++++++++----- docs/mainpage.dox | 4 ++-- 5 files changed, 28 insertions(+), 13 deletions(-) diff --git a/README-RU.md b/README-RU.md index 53df009..7eb5f6f 100644 --- a/README-RU.md +++ b/README-RU.md @@ -703,7 +703,7 @@ LogIt++ включает библиотеку *fmt* для форматиров - Нагрузка: `LOGIT_BENCH_TOTAL=10000`, 4 продюсера, размер сообщений 200 байт для таблицы сравнения (остальные комбинации см. в `bench/results/latency-2025-12-04-10k.csv`). - Метрики: медианная задержка (`p50`) в наносекундах и достигнутая пропускная способность (сообщений/с). - Железо: 3 vCPU (Intel Xeon E5-2673 v4 @ 2.30GHz) в виртуальной машине, одна NUMA-нода. -- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 05:27 UTC). +- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 05:53 UTC). | Режим | Приёмник | LogIt++ p50 | Пропускная (LogIt++) | spdlog p50 | Пропускная (spdlog) | |-------|----------|-------------|----------------------|------------|---------------------| @@ -712,7 +712,7 @@ LogIt++ включает библиотеку *fmt* для форматиров | Async | Null | 44 699 нс | 753 078 сооб./с | 1 499 973 нс | 913 881 сооб./с | | Async | File | 996 466 нс | 850 021 сооб./с | 3 999 290 нс | 912 399 сооб./с | -**Выводы:** в этом снимке оба логгера выдают миллионы сообщений в секунду в синхронных режимах (у spdlog в этот запуск чуть выше пропускная) при субмикросекундных p50. В асинхронных сценариях LogIt++ держит end-to-end p50 на уровне десятков–сотен микросекунд, тогда как spdlog уходит в миллисекунды; пропускная обоих кластеризуется вокруг 0.75–0.9 млн сооб./с в зависимости от приёмника. +**Выводы:** в этом снимке оба логгера выдают миллионы сообщений в секунду в синхронных режимах; LogIt++ сохраняет более низкий p50, а spdlog в этом прогоне даёт чуть выше пропускную на Null. В асинхронных сценариях LogIt++ держит end-to-end p50 на уровне десятков–сотен микросекунд, тогда как spdlog уходит в миллисекунды; пропускная обоих кластеризуется вокруг 0.75–0.9 млн сооб./с в зависимости от приёмника. ## Системные бэкенды diff --git a/README.md b/README.md index 0c3de2a..a4a4f6c 100644 --- a/README.md +++ b/README.md @@ -776,7 +776,7 @@ and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. are in `bench/results/latency-2025-12-04-10k.csv`). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:27 UTC). +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:53 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| @@ -785,7 +785,7 @@ and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. | Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | | Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | -**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes (spdlog slightly higher throughput this run), with sub-microsecond p50 for both. Asynchronously, LogIt++ keeps end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. +**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog edges ahead in throughput for the null sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. --- diff --git a/bench/adapters/LogItAdapter.cpp b/bench/adapters/LogItAdapter.cpp index 7ddd835..c4b5717 100644 --- a/bench/adapters/LogItAdapter.cpp +++ b/bench/adapters/LogItAdapter.cpp @@ -51,6 +51,13 @@ class MeasuringSink : public logit::ILogger { consume(token, message); return; } + if (m_sink == SinkKind::Null) { + logit::detail::TaskExecutor::get_instance().add_task([this, token]() { + consume(token, std::string_view{}); + }); + return; + } + AsyncPayload payload; payload.token = token; payload.text = message; @@ -155,14 +162,13 @@ class LogItAdapter::Impl { } void log(const LatencyRecorder::Token& token, std::string_view message) { - std::string text(message); logit::LogRecord record( logit::LogLevel::LOG_LVL_INFO, 0, std::string(), 0, std::string(), - text, + std::string(message), std::string(), -1, false, diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index 14ac696..e8f59f3 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -9,7 +9,6 @@ #include #include #include -#include #include #include @@ -147,10 +146,20 @@ void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view me auto* payload = new MessagePayload(); payload->token = token; payload->text.assign(message.data(), message.size()); - std::ostringstream oss; - oss << std::hex << static_cast(reinterpret_cast(payload)) - << '|' << payload->text; - payload->wire = oss.str(); + + char buf[2 + sizeof(void*) * 2]; + const auto ptr = reinterpret_cast(payload); + const auto [end, ec] = std::to_chars(std::begin(buf), std::end(buf), ptr, 16); + if (ec != std::errc()) { + delete payload; + return; + } + + payload->wire.clear(); + payload->wire.reserve(static_cast(end - buf) + 1 + payload->text.size()); + payload->wire.append(buf, end); + payload->wire.push_back('|'); + payload->wire.append(payload->text); spdlog::source_loc loc{}; m_logger->log(loc, spdlog::level::info, spdlog::string_view_t(payload->wire)); diff --git a/docs/mainpage.dox b/docs/mainpage.dox index c91c136..34a1b0e 100644 --- a/docs/mainpage.dox +++ b/docs/mainpage.dox @@ -690,7 +690,7 @@ Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/f - Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, 200-byte messages for the comparison table (see `bench/results/latency-2025-12-04-10k.csv` for other sizes/counts). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:27 UTC). +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:53 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| @@ -699,7 +699,7 @@ Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/f | Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | | Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | -**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes (spdlog slightly higher throughput this run), with sub-microsecond p50 for both. Asynchronously, LogIt++ keeps end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. +**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog edges ahead in throughput for the null sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. \subsection step5 Step 5: Build and Run Your Project From 1d2c1032d4d040260afd61f328e9a0a14067f19d Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 18:22:35 +0300 Subject: [PATCH 03/16] perf(formatter): add passthrough fast path Add an opt-in passthrough flag on ILogFormatter and route passthrough formatters directly through Logger without extra string copies. Update the benchmark passthrough formatter to advertise the fast path. --- bench/adapters/LogItAdapter.cpp | 2 ++ include/logit_cpp/logit/Logger.hpp | 14 ++++++++++++-- .../logit_cpp/logit/formatter/ILogFormatter.hpp | 7 +++++++ 3 files changed, 21 insertions(+), 2 deletions(-) diff --git a/bench/adapters/LogItAdapter.cpp b/bench/adapters/LogItAdapter.cpp index c4b5717..62126d6 100644 --- a/bench/adapters/LogItAdapter.cpp +++ b/bench/adapters/LogItAdapter.cpp @@ -24,6 +24,8 @@ class PassthroughFormatter : public logit::ILogFormatter { std::string format(const logit::LogRecord& record) const override { return record.format; } + + bool is_passthrough() const noexcept override { return true; } }; class MeasuringSink : public logit::ILogger { diff --git a/include/logit_cpp/logit/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index 0120b14..29f5eeb 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -142,14 +142,24 @@ namespace logit { const auto& strategy = m_loggers[record.logger_index]; if (!strategy.enabled) return; if (static_cast(record.log_level) < static_cast(strategy.logger->get_log_level())) return; - strategy.logger->log(record, strategy.formatter->format(record)); + if (strategy.formatter && strategy.formatter->is_passthrough()) { + strategy.logger->log(record, record.format); + } else { + const std::string msg = strategy.formatter ? strategy.formatter->format(record) : std::string(); + strategy.logger->log(record, msg); + } return; } for (const auto& strategy : m_loggers) { if (strategy.single_mode) continue; if (!strategy.enabled) continue; if (static_cast(record.log_level) < static_cast(strategy.logger->get_log_level())) continue; - strategy.logger->log(record, strategy.formatter->format(record)); + if (strategy.formatter && strategy.formatter->is_passthrough()) { + strategy.logger->log(record, record.format); + continue; + } + const std::string msg = strategy.formatter ? strategy.formatter->format(record) : std::string(); + strategy.logger->log(record, msg); } } diff --git a/include/logit_cpp/logit/formatter/ILogFormatter.hpp b/include/logit_cpp/logit/formatter/ILogFormatter.hpp index 6ca57db..e4cec2f 100644 --- a/include/logit_cpp/logit/formatter/ILogFormatter.hpp +++ b/include/logit_cpp/logit/formatter/ILogFormatter.hpp @@ -35,6 +35,13 @@ namespace logit { /// \param record The log record to be formatted. /// \return A string representing the formatted log message. virtual std::string format(const LogRecord& record) const = 0; + + /// \brief Indicates whether the formatter returns the message unchanged. + /// + /// Passthrough formatters that simply forward the preformatted message can override + /// this to enable fast-path handling without extra string copies. + /// \return True if the formatter is passthrough, false otherwise. + virtual bool is_passthrough() const noexcept { return false; } }; // ILogFormatter }; // namespace logit From 7ef5310d79a8d8b3b549b0050e1cc6e7ee091051 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 18:22:41 +0300 Subject: [PATCH 04/16] docs(bench): refresh benchmark snapshot Update benchmark snapshot timestamps and takeaways across README files and Doxygen after rerunning LOGIT_BENCH_TOTAL=10000. --- README-RU.md | 4 ++-- README.md | 4 ++-- docs/mainpage.dox | 4 ++-- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/README-RU.md b/README-RU.md index 7eb5f6f..25208f6 100644 --- a/README-RU.md +++ b/README-RU.md @@ -703,7 +703,7 @@ LogIt++ включает библиотеку *fmt* для форматиров - Нагрузка: `LOGIT_BENCH_TOTAL=10000`, 4 продюсера, размер сообщений 200 байт для таблицы сравнения (остальные комбинации см. в `bench/results/latency-2025-12-04-10k.csv`). - Метрики: медианная задержка (`p50`) в наносекундах и достигнутая пропускная способность (сообщений/с). - Железо: 3 vCPU (Intel Xeon E5-2673 v4 @ 2.30GHz) в виртуальной машине, одна NUMA-нода. -- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 05:53 UTC). +- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 06:28 UTC). | Режим | Приёмник | LogIt++ p50 | Пропускная (LogIt++) | spdlog p50 | Пропускная (spdlog) | |-------|----------|-------------|----------------------|------------|---------------------| @@ -712,7 +712,7 @@ LogIt++ включает библиотеку *fmt* для форматиров | Async | Null | 44 699 нс | 753 078 сооб./с | 1 499 973 нс | 913 881 сооб./с | | Async | File | 996 466 нс | 850 021 сооб./с | 3 999 290 нс | 912 399 сооб./с | -**Выводы:** в этом снимке оба логгера выдают миллионы сообщений в секунду в синхронных режимах; LogIt++ сохраняет более низкий p50, а spdlog в этом прогоне даёт чуть выше пропускную на Null. В асинхронных сценариях LogIt++ держит end-to-end p50 на уровне десятков–сотен микросекунд, тогда как spdlog уходит в миллисекунды; пропускная обоих кластеризуется вокруг 0.75–0.9 млн сооб./с в зависимости от приёмника. +**Выводы:** в этом снимке оба логгера выдают миллионы сообщений в секунду в синхронных режимах; LogIt++ удерживает более низкий p50, spdlog остаётся быстрее на Null и медленнее на файловом приёмнике. В асинхронных сценариях LogIt++ держит end-to-end p50 на уровне десятков–сотен микросекунд, тогда как spdlog уходит в миллисекунды; пропускная обоих кластеризуется вокруг 0.75–0.9 млн сооб./с в зависимости от приёмника. ## Системные бэкенды diff --git a/README.md b/README.md index a4a4f6c..fbabf8b 100644 --- a/README.md +++ b/README.md @@ -776,7 +776,7 @@ and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. are in `bench/results/latency-2025-12-04-10k.csv`). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:53 UTC). +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:28 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| @@ -785,7 +785,7 @@ and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. | Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | | Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | -**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog edges ahead in throughput for the null sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. +**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog remains ahead in throughput for the null path and trails on the file sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. --- diff --git a/docs/mainpage.dox b/docs/mainpage.dox index 34a1b0e..b8e6753 100644 --- a/docs/mainpage.dox +++ b/docs/mainpage.dox @@ -690,7 +690,7 @@ Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/f - Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, 200-byte messages for the comparison table (see `bench/results/latency-2025-12-04-10k.csv` for other sizes/counts). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 05:53 UTC). +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:28 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| @@ -699,7 +699,7 @@ Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/f | Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | | Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | -**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog edges ahead in throughput for the null sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. +**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog remains ahead in throughput for the null path and trails on the file sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. \subsection step5 Step 5: Build and Run Your Project From 5949dc854f5f15511e2ff4e4bcd27f9fc6a71753 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 18:22:46 +0300 Subject: [PATCH 05/16] docs(bench): refresh snapshot metadata Update benchmark snapshot bullet points to the latest 10k run at 06:53 UTC and keep README/Doxygen tables pointing to the refreshed CSV. --- README-RU.md | 2 +- README.md | 2 +- docs/mainpage.dox | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/README-RU.md b/README-RU.md index 25208f6..a4c6fad 100644 --- a/README-RU.md +++ b/README-RU.md @@ -703,7 +703,7 @@ LogIt++ включает библиотеку *fmt* для форматиров - Нагрузка: `LOGIT_BENCH_TOTAL=10000`, 4 продюсера, размер сообщений 200 байт для таблицы сравнения (остальные комбинации см. в `bench/results/latency-2025-12-04-10k.csv`). - Метрики: медианная задержка (`p50`) в наносекундах и достигнутая пропускная способность (сообщений/с). - Железо: 3 vCPU (Intel Xeon E5-2673 v4 @ 2.30GHz) в виртуальной машине, одна NUMA-нода. -- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 06:28 UTC). +- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 06:53 UTC). | Режим | Приёмник | LogIt++ p50 | Пропускная (LogIt++) | spdlog p50 | Пропускная (spdlog) | |-------|----------|-------------|----------------------|------------|---------------------| diff --git a/README.md b/README.md index fbabf8b..29c40ac 100644 --- a/README.md +++ b/README.md @@ -776,7 +776,7 @@ and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. are in `bench/results/latency-2025-12-04-10k.csv`). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:28 UTC). +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:53 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| diff --git a/docs/mainpage.dox b/docs/mainpage.dox index b8e6753..c278048 100644 --- a/docs/mainpage.dox +++ b/docs/mainpage.dox @@ -690,7 +690,7 @@ Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/f - Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, 200-byte messages for the comparison table (see `bench/results/latency-2025-12-04-10k.csv` for other sizes/counts). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:28 UTC). +- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:53 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| From e6e0f7c2144b0c34c1471ff0e3174159adcb4123 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 21:59:39 +0300 Subject: [PATCH 06/16] docs(bench): document latency recorder user data Add LatencyRecorder and user_data usage notes to README, README-RU, and Doxygen main page. Expose an optional user_data payload in LogRecord for benchmark adapters and document how to pass tokens without args_array copies. --- README-RU.md | 16 ++++++++++++++++ README.md | 16 ++++++++++++++++ docs/mainpage.dox | 15 +++++++++++++++ include/logit_cpp/logit/utils/LogRecord.hpp | 5 ++++- 4 files changed, 51 insertions(+), 1 deletion(-) diff --git a/README-RU.md b/README-RU.md index a4c6fad..ac4f8d6 100644 --- a/README-RU.md +++ b/README-RU.md @@ -714,6 +714,22 @@ LogIt++ включает библиотеку *fmt* для форматиров **Выводы:** в этом снимке оба логгера выдают миллионы сообщений в секунду в синхронных режимах; LogIt++ удерживает более низкий p50, spdlog остаётся быстрее на Null и медленнее на файловом приёмнике. В асинхронных сценариях LogIt++ держит end-to-end p50 на уровне десятков–сотен микросекунд, тогда как spdlog уходит в миллисекунды; пропускная обоих кластеризуется вокруг 0.75–0.9 млн сооб./с в зависимости от приёмника. +### Как устроен бенч-харнесс (LatencyRecorder и `user_data`) + +- `bench/LatencyRecorder.hpp` заранее резервирует слоты и ведёт `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` с защитой от повторных `complete()` на один слот. Доступны методы `recorded()`, `wait_for_all()` и `finalize()` для end-to-end измерений между продюсерами и консюмером. +- В `logit::LogRecord` добавлено поле `user_data` для произвольной нагрузки (например, указатель на бенч-токен без использования `args_array`). Оставляйте `0` для обычного логирования; адаптеры/приёмники могут интерпретировать поле, если оно задано. +- Пример: прикрепить заранее выделенный бенч-пейлоад вместо записи токена в `args_array`: + ```cpp + struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; + BenchPayload payload{recorder.begin(true)}; + logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, + preformatted_text, /*arg_names*/"", /*logger*/-1, + /*print*/false, /*fmt*/false, + reinterpret_cast(&payload)); + Logger::get_instance().log(rec, preformatted_text); + // В приёмнике: if (record.user_data) { auto* p = reinterpret_cast(record.user_data); recorder.complete(p->token); } + ``` + ## Системные бэкенды LogIt++ может отправлять сообщения в системные журналы. diff --git a/README.md b/README.md index 29c40ac..0daf1ed 100644 --- a/README.md +++ b/README.md @@ -787,6 +787,22 @@ and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. **Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog remains ahead in throughput for the null path and trails on the file sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. +### Benchmark harness notes (LatencyRecorder & `user_data`) + +- `bench/LatencyRecorder.hpp` preallocates slots and tracks `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` with per-slot deduplication (duplicate `complete()` calls are ignored). It exposes `recorded()`, `wait_for_all()`, and `finalize()` for end-to-end timing across producers/consumers. +- `logit::LogRecord` now carries an optional `user_data` field for opaque payloads (e.g., passing a benchmark token pointer without stuffing `args_array`). Leave it at `0` for normal logging; adapters/sinks may reinterpret it when present. +- Example: attach a preallocated benchmark payload instead of pushing tokens into `args_array`: + ```cpp + struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; + BenchPayload payload{recorder.begin(true)}; + logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, + preformatted_text, /*arg_names*/"", /*logger*/-1, + /*print*/false, /*fmt*/false, + reinterpret_cast(&payload)); + Logger::get_instance().log(rec, preformatted_text); + // In your sink/adapter: if (record.user_data) { auto* p = reinterpret_cast(record.user_data); recorder.complete(p->token); } + ``` + --- ## Documentation diff --git a/docs/mainpage.dox b/docs/mainpage.dox index c278048..229d8ab 100644 --- a/docs/mainpage.dox +++ b/docs/mainpage.dox @@ -701,6 +701,21 @@ Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/f **Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog remains ahead in throughput for the null path and trails on the file sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. +\subsection bench_harness Bench harness notes (LatencyRecorder & user_data) + +- `bench/LatencyRecorder.hpp` preallocates slots and tracks `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` with per-slot deduplication (duplicate `complete()` calls are ignored). It exposes `recorded()`, `wait_for_all()`, and `finalize()` for end-to-end timing across producers/consumers. +- `logit::LogRecord` includes an optional `user_data` field for opaque payloads (e.g., handing a benchmark token pointer to a sink instead of populating `args_array`). Leave it `0` for normal logging. +- Example usage to pass a preallocated payload into the sink: + \code{.cpp} + struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; + BenchPayload payload{recorder.begin(true)}; + logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, + preformatted_text, "", -1, false, false, + reinterpret_cast(&payload)); + Logger::get_instance().log(rec, preformatted_text); + // Sink side: if (record.user_data) { auto* p = reinterpret_cast(record.user_data); recorder.complete(p->token); } + \endcode + \subsection step5 Step 5: Build and Run Your Project After adding the necessary include paths, you can proceed to build and run your project. LogIt++ is designed to be easy to integrate and requires no linking since it's header-only. diff --git a/include/logit_cpp/logit/utils/LogRecord.hpp b/include/logit_cpp/logit/utils/LogRecord.hpp index be65e1a..a18b979 100644 --- a/include/logit_cpp/logit/utils/LogRecord.hpp +++ b/include/logit_cpp/logit/utils/LogRecord.hpp @@ -23,6 +23,7 @@ namespace logit { const std::string format; ///< Format string for the message. const std::string arg_names; ///< Argument names for the log. std::vector args_array; ///< Argument values for the log. + std::uintptr_t user_data; ///< Opaque payload for adapters (e.g., benchmark tokens). Defaults to 0. std::thread::id thread_id; ///< ID of the logging thread. const int logger_index; ///< Logger index (-1 to log to all). const bool print_mode; ///< Flag to determine whether arguments are printed in a raw format without special symbols. @@ -48,7 +49,8 @@ namespace logit { const std::string& arg_names, int logger_index, bool print_mode, - bool fmt_mode = false) : + bool fmt_mode = false, + std::uintptr_t user_data = 0) : log_level(log_level), timestamp_ms(timestamp_ms), file(file), @@ -56,6 +58,7 @@ namespace logit { function(function), format(format), arg_names(arg_names), + user_data(user_data), thread_id(std::this_thread::get_id()), logger_index(logger_index), print_mode(print_mode), From 5dd36af58a2582d5cee58760cf8af18c897a1883 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 21:59:46 +0300 Subject: [PATCH 07/16] perf(logger): reduce contention and harden bench payloads --- README-RU.md | 19 +++- README.md | 19 +++- bench/adapters/LogItAdapter.cpp | 16 +++- docs/mainpage.dox | 19 +++- include/logit_cpp/logit/Logger.hpp | 143 +++++++++++++++++------------ 5 files changed, 139 insertions(+), 77 deletions(-) diff --git a/README-RU.md b/README-RU.md index ac4f8d6..34927dd 100644 --- a/README-RU.md +++ b/README-RU.md @@ -717,17 +717,26 @@ LogIt++ включает библиотеку *fmt* для форматиров ### Как устроен бенч-харнесс (LatencyRecorder и `user_data`) - `bench/LatencyRecorder.hpp` заранее резервирует слоты и ведёт `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` с защитой от повторных `complete()` на один слот. Доступны методы `recorded()`, `wait_for_all()` и `finalize()` для end-to-end измерений между продюсерами и консюмером. -- В `logit::LogRecord` добавлено поле `user_data` для произвольной нагрузки (например, указатель на бенч-токен без использования `args_array`). Оставляйте `0` для обычного логирования; адаптеры/приёмники могут интерпретировать поле, если оно задано. -- Пример: прикрепить заранее выделенный бенч-пейлоад вместо записи токена в `args_array`: +- В `logit::LogRecord` добавлено поле `user_data` для произвольной нагрузки (например, указатель на бенч-токен без использования `args_array`). Оставляйте `0` для обычного логирования; адаптеры/приёмники могут интерпретировать поле, если оно задано. Указатель должен жить до момента, когда sink обработает запись. +- Пример: прикрепить заранее выделенный бенч-пейлоад вместо записи токена в `args_array` (хранилище живёт весь прогон): ```cpp struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; - BenchPayload payload{recorder.begin(true)}; + std::vector payloads(total_messages); + + // В продюсере + auto token = recorder.begin(true); + payloads[token.slot].token = token; logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, preformatted_text, /*arg_names*/"", /*logger*/-1, /*print*/false, /*fmt*/false, - reinterpret_cast(&payload)); + reinterpret_cast(&payloads[token.slot])); Logger::get_instance().log(rec, preformatted_text); - // В приёмнике: if (record.user_data) { auto* p = reinterpret_cast(record.user_data); recorder.complete(p->token); } + + // В sink/адаптере + if (record.user_data) { + auto* p = reinterpret_cast(record.user_data); + recorder.complete(p->token); + } ``` ## Системные бэкенды diff --git a/README.md b/README.md index 0daf1ed..69f74c8 100644 --- a/README.md +++ b/README.md @@ -790,17 +790,26 @@ and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. ### Benchmark harness notes (LatencyRecorder & `user_data`) - `bench/LatencyRecorder.hpp` preallocates slots and tracks `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` with per-slot deduplication (duplicate `complete()` calls are ignored). It exposes `recorded()`, `wait_for_all()`, and `finalize()` for end-to-end timing across producers/consumers. -- `logit::LogRecord` now carries an optional `user_data` field for opaque payloads (e.g., passing a benchmark token pointer without stuffing `args_array`). Leave it at `0` for normal logging; adapters/sinks may reinterpret it when present. -- Example: attach a preallocated benchmark payload instead of pushing tokens into `args_array`: +- `logit::LogRecord` now carries an optional `user_data` field for opaque payloads (e.g., passing a benchmark token pointer without stuffing `args_array`). Leave it at `0` for normal logging; adapters/sinks may reinterpret it when present. The pointer must remain valid until the sink consumes the record. +- Example: attach a preallocated benchmark payload instead of pushing tokens into `args_array` (the storage lives for the whole run): ```cpp struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; - BenchPayload payload{recorder.begin(true)}; + std::vector payloads(total_messages); + + // Producer thread + auto token = recorder.begin(true); + payloads[token.slot].token = token; logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, preformatted_text, /*arg_names*/"", /*logger*/-1, /*print*/false, /*fmt*/false, - reinterpret_cast(&payload)); + reinterpret_cast(&payloads[token.slot])); Logger::get_instance().log(rec, preformatted_text); - // In your sink/adapter: if (record.user_data) { auto* p = reinterpret_cast(record.user_data); recorder.complete(p->token); } + + // In your sink/adapter + if (record.user_data) { + auto* p = reinterpret_cast(record.user_data); + recorder.complete(p->token); + } ``` --- diff --git a/bench/adapters/LogItAdapter.cpp b/bench/adapters/LogItAdapter.cpp index 62126d6..a54116d 100644 --- a/bench/adapters/LogItAdapter.cpp +++ b/bench/adapters/LogItAdapter.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include @@ -98,6 +99,11 @@ class MeasuringSink : public logit::ILogger { static LatencyRecorder::Token extract(const logit::LogRecord& record) { LatencyRecorder::Token token; + if (record.user_data != 0) { + auto* payload = reinterpret_cast(record.user_data); + token = *payload; + return token; + } if (record.args_array.size() <= kActiveIndex) { return token; } @@ -161,6 +167,7 @@ class LogItAdapter::Impl { if (sink) { sink->configure(scenario, recorder); } + m_tokens.assign(scenario.total_messages, {}); } void log(const LatencyRecorder::Token& token, std::string_view message) { @@ -175,10 +182,10 @@ class LogItAdapter::Impl { -1, false, false); - record.args_array.reserve(3); - record.args_array.emplace_back("slot", static_cast(token.slot)); - record.args_array.emplace_back("t0", static_cast(token.t0_ns)); - record.args_array.emplace_back("active", static_cast(token.active ? 1 : 0)); + if (token.active && token.slot < m_tokens.size()) { + m_tokens[token.slot] = token; + record.user_data = reinterpret_cast(&m_tokens[token.slot]); + } logger.log(record); } @@ -190,6 +197,7 @@ class LogItAdapter::Impl { logit::Logger& logger; MeasuringSink* sink = nullptr; + std::vector m_tokens; }; LogItAdapter::LogItAdapter() diff --git a/docs/mainpage.dox b/docs/mainpage.dox index 229d8ab..a622f3e 100644 --- a/docs/mainpage.dox +++ b/docs/mainpage.dox @@ -704,16 +704,25 @@ Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/f \subsection bench_harness Bench harness notes (LatencyRecorder & user_data) - `bench/LatencyRecorder.hpp` preallocates slots and tracks `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` with per-slot deduplication (duplicate `complete()` calls are ignored). It exposes `recorded()`, `wait_for_all()`, and `finalize()` for end-to-end timing across producers/consumers. -- `logit::LogRecord` includes an optional `user_data` field for opaque payloads (e.g., handing a benchmark token pointer to a sink instead of populating `args_array`). Leave it `0` for normal logging. -- Example usage to pass a preallocated payload into the sink: +- `logit::LogRecord` includes an optional `user_data` field for opaque payloads (e.g., handing a benchmark token pointer to a sink instead of populating `args_array`). Leave it `0` for normal logging. The pointed storage must outlive the record until the sink consumes it. +- Example usage to pass a preallocated payload into the sink (storage lives for the entire run): \code{.cpp} struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; - BenchPayload payload{recorder.begin(true)}; + std::vector payloads(total_messages); + + // Producer + auto token = recorder.begin(true); + payloads[token.slot].token = token; logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, preformatted_text, "", -1, false, false, - reinterpret_cast(&payload)); + reinterpret_cast(&payloads[token.slot])); Logger::get_instance().log(rec, preformatted_text); - // Sink side: if (record.user_data) { auto* p = reinterpret_cast(record.user_data); recorder.complete(p->token); } + + // Sink side + if (record.user_data) { + auto* p = reinterpret_cast(record.user_data); + recorder.complete(p->token); + } \endcode \subsection step5 Step 5: Build and Run Your Project diff --git a/include/logit_cpp/logit/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index 29f5eeb..79d5ca2 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -11,6 +11,7 @@ #include "detail/TaskExecutor.hpp" #include #include +#include #include #include @@ -43,13 +44,14 @@ namespace logit { std::unique_ptr formatter, bool single_mode = false) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); - m_loggers.push_back( - LoggerStrategy{std::move(logger), - std::move(formatter), - single_mode, - true // Loggers are enabled by default - }); + auto strategy = std::make_shared(); + strategy->logger = std::move(logger); + strategy->formatter = std::move(formatter); + strategy->single_mode = single_mode; + strategy->enabled = true; + + std::unique_lock lock(m_loggers_mx); + m_loggers.push_back(std::move(strategy)); } /// \brief Enables or disables a logger by index. @@ -57,9 +59,9 @@ namespace logit { /// \param enabled True to enable, false to disable. void set_logger_enabled(int logger_index, bool enabled) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { - m_loggers[logger_index].enabled = enabled; + std::unique_lock 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; } } @@ -67,9 +69,9 @@ namespace logit { /// \param logger_index Index of logger. /// \return True if logger is enabled, false otherwise. bool is_logger_enabled(int logger_index) const { - std::lock_guard lock(m_mutex); - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { - return m_loggers[logger_index].enabled; + std::shared_lock 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 false; } @@ -79,9 +81,9 @@ namespace logit { /// \param single_mode True to enable single mode, false to disable. void set_logger_single_mode(int logger_index, bool single_mode) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { - m_loggers[logger_index].single_mode = single_mode; + std::unique_lock 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; } } @@ -90,9 +92,10 @@ namespace logit { /// \param offset_ms Offset in milliseconds. void set_timestamp_offset(int logger_index, int64_t offset_ms) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { - m_loggers[logger_index].formatter->set_timestamp_offset(offset_ms); + std::unique_lock lock(m_loggers_mx); + if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { + std::lock_guard exec_lock(m_loggers[logger_index]->exec_mx); + m_loggers[logger_index]->formatter->set_timestamp_offset(offset_ms); } } @@ -100,9 +103,11 @@ namespace logit { /// \param level Minimum log level. void set_log_level(LogLevel level) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); + std::shared_lock lock(m_loggers_mx); for (auto& strategy : m_loggers) { - strategy.logger->set_log_level(level); + if (!strategy) continue; + std::lock_guard exec_lock(strategy->exec_mx); + strategy->logger->set_log_level(level); } } @@ -111,9 +116,10 @@ namespace logit { /// \param level Minimum log level. void set_log_level(int logger_index, LogLevel level) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { - m_loggers[logger_index].logger->set_log_level(level); + std::unique_lock lock(m_loggers_mx); + if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { + std::lock_guard exec_lock(m_loggers[logger_index]->exec_mx); + m_loggers[logger_index]->logger->set_log_level(level); } } @@ -122,9 +128,9 @@ namespace logit { /// \return True if logger is in single mode, false otherwise. bool is_logger_single_mode(int logger_index) const { if (m_shutdown) return false; - std::lock_guard lock(m_mutex); - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { - return m_loggers[logger_index].single_mode; + std::shared_lock 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 false; } @@ -136,30 +142,36 @@ namespace logit { /// \param record Log record to be logged. void log(const LogRecord& record) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); - // Log to the specific logger if the index is valid - if (record.logger_index >= 0 && record.logger_index < static_cast(m_loggers.size())) { - const auto& strategy = m_loggers[record.logger_index]; - if (!strategy.enabled) return; - if (static_cast(record.log_level) < static_cast(strategy.logger->get_log_level())) return; - if (strategy.formatter && strategy.formatter->is_passthrough()) { - strategy.logger->log(record, record.format); + const bool targeted = record.logger_index >= 0; + std::vector> snapshot; + { + std::shared_lock lock(m_loggers_mx); + if (targeted) { + if (record.logger_index < static_cast(m_loggers.size())) { + snapshot.push_back(m_loggers[record.logger_index]); + } } else { - const std::string msg = strategy.formatter ? strategy.formatter->format(record) : std::string(); - strategy.logger->log(record, msg); + snapshot = m_loggers; } + } + + if (targeted) { + if (snapshot.empty() || !snapshot[0]) return; + auto& strategy = snapshot[0]; + if (!strategy->enabled) return; + if (static_cast(record.log_level) < static_cast(strategy->logger->get_log_level())) return; + std::lock_guard exec_lock(strategy->exec_mx); + dispatch_to_strategy(*strategy, record); return; } - for (const auto& strategy : m_loggers) { - if (strategy.single_mode) continue; - if (!strategy.enabled) continue; - if (static_cast(record.log_level) < static_cast(strategy.logger->get_log_level())) continue; - if (strategy.formatter && strategy.formatter->is_passthrough()) { - strategy.logger->log(record, record.format); - continue; - } - const std::string msg = strategy.formatter ? strategy.formatter->format(record) : std::string(); - strategy.logger->log(record, msg); + + for (const auto& strategy : snapshot) { + if (!strategy) continue; + if (strategy->single_mode) continue; + if (!strategy->enabled) continue; + if (static_cast(record.log_level) < static_cast(strategy->logger->get_log_level())) continue; + std::lock_guard exec_lock(strategy->exec_mx); + dispatch_to_strategy(*strategy, record); } } @@ -169,9 +181,10 @@ namespace logit { /// \return Requested parameter as a string, or empty string if unsupported. std::string get_string_param(int logger_index, const LoggerParam& param) const { if (m_shutdown) return std::string(); - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { + std::shared_lock lock(m_loggers_mx); + if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { const auto& strategy = m_loggers[logger_index]; - return strategy.logger->get_string_param(param); + return strategy->logger->get_string_param(param); } return std::string(); } @@ -182,9 +195,10 @@ namespace logit { /// \return Requested parameter as an integer, or 0 if unsupported. int64_t get_int_param(int logger_index, const LoggerParam& param) const { if (m_shutdown) return 0; - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { + std::shared_lock lock(m_loggers_mx); + if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { const auto& strategy = m_loggers[logger_index]; - return strategy.logger->get_int_param(param); + return strategy->logger->get_int_param(param); } return 0; } @@ -195,9 +209,10 @@ namespace logit { /// \return Requested parameter as a double, or 0.0 if unsupported. double get_float_param(int logger_index, const LoggerParam& param) const { if (m_shutdown) return 0.0; - if (logger_index >= 0 && logger_index < static_cast(m_loggers.size())) { + std::shared_lock lock(m_loggers_mx); + if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { const auto& strategy = m_loggers[logger_index]; - return strategy.logger->get_float_param(param); + return strategy->logger->get_float_param(param); } return 0.0; } @@ -238,8 +253,10 @@ namespace logit { /// /// Ensures that all log messages are fully processed before continuing. void wait() { + std::shared_lock lock(m_loggers_mx); for (const auto& strategy : m_loggers) { - strategy.logger->wait(); + if (!strategy) continue; + strategy->logger->wait(); } } @@ -261,12 +278,22 @@ namespace logit { struct LoggerStrategy { std::unique_ptr logger; ///< The logger instance. std::unique_ptr formatter; ///< The formatter instance. - bool single_mode; ///< Flag indicating if the logger is in single mode. - bool enabled; ///< Flag indicating if the logger is enabled. + bool single_mode = false; ///< Flag indicating if the logger is in single mode. + bool enabled = true; ///< Flag indicating if the logger is enabled. + mutable std::mutex exec_mx; ///< Protects formatter+logger invocation. }; - std::vector m_loggers; ///< Container for logger-formatter pairs. - mutable std::mutex m_mutex; ///< Mutex for thread safety during logging operations. + void dispatch_to_strategy(LoggerStrategy& strategy, const LogRecord& record) { + if (strategy.formatter && strategy.formatter->is_passthrough()) { + strategy.logger->log(record, record.format); + return; + } + const std::string msg = strategy.formatter ? strategy.formatter->format(record) : std::string(); + strategy.logger->log(record, msg); + } + + std::vector> m_loggers; ///< Container for logger-formatter pairs. + mutable std::shared_mutex m_loggers_mx; ///< Protects access to logger strategies. std::atomic m_shutdown = ATOMIC_VAR_INIT(false); ///< Flag indicating if shutdown was requested. void print(const LogRecord& record) { From 3832e3f7d4da0f104c83a1aa3535a34972a2a4b0 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 4 Dec 2025 21:59:52 +0300 Subject: [PATCH 08/16] fix(logger): add c++11 mutex fallback and init user data --- include/logit_cpp/logit/Logger.hpp | 46 ++++++++++++++------- include/logit_cpp/logit/utils/LogRecord.hpp | 4 +- 2 files changed, 33 insertions(+), 17 deletions(-) diff --git a/include/logit_cpp/logit/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index 79d5ca2..85826e4 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -11,12 +11,28 @@ #include "detail/TaskExecutor.hpp" #include #include -#include #include #include +#if __cplusplus >= 201703L +#include +#define LOGIT_HAS_SHARED_MUTEX 1 +#else +#define LOGIT_HAS_SHARED_MUTEX 0 +#endif + namespace logit { + #if LOGIT_HAS_SHARED_MUTEX + using LoggerMutex = std::shared_mutex; + using LoggerReadLock = std::shared_lock; + using LoggerWriteLock = std::unique_lock; + #else + using LoggerMutex = std::mutex; + using LoggerReadLock = std::unique_lock; + using LoggerWriteLock = std::unique_lock; + #endif + /// \class Logger /// \brief Singleton class managing multiple loggers and formatters. /// @@ -50,7 +66,7 @@ namespace logit { strategy->single_mode = single_mode; strategy->enabled = true; - std::unique_lock lock(m_loggers_mx); + LoggerWriteLock lock(m_loggers_mx); m_loggers.push_back(std::move(strategy)); } @@ -59,7 +75,7 @@ namespace logit { /// \param enabled True to enable, false to disable. void set_logger_enabled(int logger_index, bool enabled) { if (m_shutdown) return; - std::unique_lock lock(m_loggers_mx); + 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; } @@ -69,7 +85,7 @@ namespace logit { /// \param logger_index Index of logger. /// \return True if logger is enabled, false otherwise. bool is_logger_enabled(int logger_index) const { - std::shared_lock lock(m_loggers_mx); + 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; } @@ -81,7 +97,7 @@ namespace logit { /// \param single_mode True to enable single mode, false to disable. void set_logger_single_mode(int logger_index, bool single_mode) { if (m_shutdown) return; - std::unique_lock lock(m_loggers_mx); + 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; } @@ -92,7 +108,7 @@ namespace logit { /// \param offset_ms Offset in milliseconds. void set_timestamp_offset(int logger_index, int64_t offset_ms) { if (m_shutdown) return; - std::unique_lock lock(m_loggers_mx); + LoggerWriteLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { std::lock_guard exec_lock(m_loggers[logger_index]->exec_mx); m_loggers[logger_index]->formatter->set_timestamp_offset(offset_ms); @@ -103,7 +119,7 @@ namespace logit { /// \param level Minimum log level. void set_log_level(LogLevel level) { if (m_shutdown) return; - std::shared_lock lock(m_loggers_mx); + LoggerReadLock lock(m_loggers_mx); for (auto& strategy : m_loggers) { if (!strategy) continue; std::lock_guard exec_lock(strategy->exec_mx); @@ -116,7 +132,7 @@ namespace logit { /// \param level Minimum log level. void set_log_level(int logger_index, LogLevel level) { if (m_shutdown) return; - std::unique_lock lock(m_loggers_mx); + LoggerWriteLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { std::lock_guard exec_lock(m_loggers[logger_index]->exec_mx); m_loggers[logger_index]->logger->set_log_level(level); @@ -128,7 +144,7 @@ namespace logit { /// \return True if logger is in single mode, false otherwise. bool is_logger_single_mode(int logger_index) const { if (m_shutdown) return false; - std::shared_lock lock(m_loggers_mx); + 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; } @@ -145,7 +161,7 @@ namespace logit { const bool targeted = record.logger_index >= 0; std::vector> snapshot; { - std::shared_lock lock(m_loggers_mx); + LoggerReadLock lock(m_loggers_mx); if (targeted) { if (record.logger_index < static_cast(m_loggers.size())) { snapshot.push_back(m_loggers[record.logger_index]); @@ -181,7 +197,7 @@ namespace logit { /// \return Requested parameter as a string, or empty string if unsupported. std::string get_string_param(int logger_index, const LoggerParam& param) const { if (m_shutdown) return std::string(); - std::shared_lock lock(m_loggers_mx); + LoggerReadLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { const auto& strategy = m_loggers[logger_index]; return strategy->logger->get_string_param(param); @@ -195,7 +211,7 @@ namespace logit { /// \return Requested parameter as an integer, or 0 if unsupported. int64_t get_int_param(int logger_index, const LoggerParam& param) const { if (m_shutdown) return 0; - std::shared_lock lock(m_loggers_mx); + LoggerReadLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { const auto& strategy = m_loggers[logger_index]; return strategy->logger->get_int_param(param); @@ -209,7 +225,7 @@ namespace logit { /// \return Requested parameter as a double, or 0.0 if unsupported. double get_float_param(int logger_index, const LoggerParam& param) const { if (m_shutdown) return 0.0; - std::shared_lock lock(m_loggers_mx); + LoggerReadLock lock(m_loggers_mx); if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { const auto& strategy = m_loggers[logger_index]; return strategy->logger->get_float_param(param); @@ -253,7 +269,7 @@ namespace logit { /// /// Ensures that all log messages are fully processed before continuing. void wait() { - std::shared_lock lock(m_loggers_mx); + LoggerReadLock lock(m_loggers_mx); for (const auto& strategy : m_loggers) { if (!strategy) continue; strategy->logger->wait(); @@ -293,7 +309,7 @@ namespace logit { } std::vector> m_loggers; ///< Container for logger-formatter pairs. - mutable std::shared_mutex m_loggers_mx; ///< Protects access to logger strategies. + mutable LoggerMutex m_loggers_mx; ///< Protects access to logger strategies. std::atomic m_shutdown = ATOMIC_VAR_INIT(false); ///< Flag indicating if shutdown was requested. void print(const LogRecord& record) { diff --git a/include/logit_cpp/logit/utils/LogRecord.hpp b/include/logit_cpp/logit/utils/LogRecord.hpp index a18b979..1db0c1d 100644 --- a/include/logit_cpp/logit/utils/LogRecord.hpp +++ b/include/logit_cpp/logit/utils/LogRecord.hpp @@ -23,7 +23,7 @@ namespace logit { const std::string format; ///< Format string for the message. const std::string arg_names; ///< Argument names for the log. std::vector args_array; ///< Argument values for the log. - std::uintptr_t user_data; ///< Opaque payload for adapters (e.g., benchmark tokens). Defaults to 0. + std::uintptr_t user_data = reinterpret_cast(nullptr); ///< Opaque payload for adapters (e.g., benchmark tokens). Defaults to nullptr. std::thread::id thread_id; ///< ID of the logging thread. const int logger_index; ///< Logger index (-1 to log to all). const bool print_mode; ///< Flag to determine whether arguments are printed in a raw format without special symbols. @@ -50,7 +50,7 @@ namespace logit { int logger_index, bool print_mode, bool fmt_mode = false, - std::uintptr_t user_data = 0) : + std::uintptr_t user_data = reinterpret_cast(nullptr)) : log_level(log_level), timestamp_ms(timestamp_ms), file(file), From 623d3470904b505649a0bc8fffee8667a70ea57d Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 04:00:01 +0300 Subject: [PATCH 09/16] feat(bench): support latency completion by slot (no user_data) --- bench/LatencyRecorder.hpp | 267 +++++++++++++++++++++++--------------- 1 file changed, 161 insertions(+), 106 deletions(-) diff --git a/bench/LatencyRecorder.hpp b/bench/LatencyRecorder.hpp index 6969f82..de990d4 100644 --- a/bench/LatencyRecorder.hpp +++ b/bench/LatencyRecorder.hpp @@ -13,124 +13,179 @@ namespace logit_bench { -/** - * Lock-free recorder for latency samples: - * - begin(record=true) returns a Token with an assigned slot and t0_ns (steady_clock). - * - complete(token) stores (t1-t0) in that slot. - * - finalize() returns p50/p99/p99.9 using nearest-rank (ceil) on a sorted copy. - * - * Thread-safety: concurrent writers store into distinct preallocated slots. - */ -class LatencyRecorder { -public: - struct Token { - std::uint64_t slot = invalid_slot(); - std::uint64_t t0_ns = 0; - bool active = false; - }; - - struct Summary { - std::uint64_t p50_ns = 0; - std::uint64_t p99_ns = 0; - std::uint64_t p999_ns = 0; - }; - - explicit LatencyRecorder(std::size_t total) - : m_values(total), - m_expected(total), - m_next_slot(0), - m_completed(0), - m_slot_done(total) { - for (auto& flag : m_slot_done) { - flag.store(0, std::memory_order_relaxed); - } - } - /** - * Reserve a slot (if record==true) and capture t0 using steady_clock. - * We take t0 **after** the slot reservation to minimize skew before log(). + * Lock-free-ish recorder for latency samples: + * - begin(record=true) reserves a slot and captures t0 (steady_clock) AFTER reservation. + * - complete(token) stores (t1 - t0) into that slot, deduplicated (at most once per slot). + * - complete_slot(slot) stores (now - t0[slot]) into that slot, deduplicated. + * - finalize() returns p50/p99/p99.9 using nearest-rank (ceil) on a sorted copy. + * + * Thread-safety: concurrent writers store into distinct preallocated slots. + * Dedup: per-slot atomic flag prevents double completion from counting twice. */ - Token begin(bool record) { - Token token; - token.active = record; - if (record) { + class LatencyRecorder { + public: + struct Token { + std::uint64_t slot = invalid_slot(); + std::uint64_t t0_ns = 0; + bool active = false; + }; + + struct Summary { + std::uint64_t p50_ns = 0; + std::uint64_t p99_ns = 0; + std::uint64_t p999_ns = 0; + }; + + explicit LatencyRecorder(std::size_t total) + : m_values(total), + m_t0_ns(total), + m_expected(total), + m_next_slot(0), + m_completed(0), + m_slot_done(total) { + for (auto& flag : m_slot_done) { + flag.store(0, std::memory_order_relaxed); + } + // m_values/m_t0_ns are POD; leave uninitialized if you want, + // but it's safer to keep deterministic state. + std::fill(m_values.begin(), m_values.end(), 0); + std::fill(m_t0_ns.begin(), m_t0_ns.end(), 0); + } + + /** + * Reserve a slot (if record==true) and capture t0 using steady_clock. + * We take t0 **after** the slot reservation to minimize skew before log(). + * + * Also stores t0 into internal t0 array, enabling complete_slot(slot). + */ + Token begin(bool record) { + Token token; + token.active = record; + if (!record) return token; + const auto slot = m_next_slot.fetch_add(1, std::memory_order_relaxed); if (slot >= m_expected) { throw std::out_of_range("LatencyRecorder capacity exceeded"); } + token.slot = static_cast(slot); token.t0_ns = now(); + + // Store t0 for "slot-only" completion path (spdlog-friendly). + // Relaxed is fine: slot is unique per begin(); consumer uses the same slot. + m_t0_ns[slot] = token.t0_ns; + + return token; } - return token; - } - - /// Capture t1 and store (t1 - t0) into the reserved slot. - void complete(const Token& token) { - if (!token.active) return; - if (token.slot >= m_expected) { - throw std::out_of_range("LatencyRecorder capacity exceeded"); + + /// Capture t1 and store (t1 - t0) into the reserved slot (deduplicated). + void complete(const Token& token) { + if (!token.active) return; + complete_impl(token.slot, token.t0_ns); } - std::uint8_t expected = 0; - if (!m_slot_done[token.slot].compare_exchange_strong( - expected, 1, std::memory_order_acq_rel)) { - return; // duplicate completion -> ignore + + /** + * Complete by slot only (uses t0 stored in begin()). + * Useful when transport only carries the slot (e.g. spdlog payload "slot|text" or source_loc.line). + */ + void complete_slot(std::uint64_t slot) { + if (slot >= m_expected) { + // In bench code it's OK to ignore silently; for debugging prefer throw. + throw std::out_of_range("LatencyRecorder capacity exceeded"); + } + const auto t0 = m_t0_ns[static_cast(slot)]; + complete_impl(slot, t0); } - const auto t1_ns = now(); - m_values[token.slot] = t1_ns - token.t0_ns; // distinct slots -> no data race - const auto done = m_completed.fetch_add(1, std::memory_order_acq_rel) + 1; - if (done == m_expected) { - m_wait_cv.notify_all(); + + std::size_t recorded() const { + return m_next_slot.load(std::memory_order_relaxed); } - } - - std::size_t recorded() const { - return m_next_slot.load(std::memory_order_relaxed); - } - - void wait_for_all() const { - std::unique_lock lk(m_wait_mx); - m_wait_cv.wait(lk, [&]{ return m_completed.load(std::memory_order_acquire) >= m_expected; }); - } - - Summary finalize() const { - if (recorded() != m_expected || m_completed.load(std::memory_order_acquire) != m_expected) { - throw std::runtime_error("Incomplete latency capture"); + + std::size_t completed() const { + return m_completed.load(std::memory_order_acquire); } - std::vector sorted = m_values; - std::sort(sorted.begin(), sorted.end()); - Summary summary; - summary.p50_ns = pick(sorted, 0.50); - summary.p99_ns = pick(sorted, 0.99); - summary.p999_ns = pick(sorted, 0.999); - return summary; - } - - static std::uint64_t invalid_slot() { - return std::numeric_limits::max(); - } - - static std::uint64_t now() { - const auto now_tp = std::chrono::steady_clock::now().time_since_epoch(); - return std::chrono::duration_cast(now_tp).count(); - } - -private: - // Nearest-rank percentile with ceil(p * N), clamped to [0..N-1]. - static std::uint64_t pick(const std::vector& data, double p) { - if (data.empty()) return 0; - const double r = std::ceil(p * static_cast(data.size())); - std::size_t idx = (r <= 1.0) ? 0 : static_cast(r) - 1; - if (idx >= data.size()) idx = data.size() - 1; - return data[idx]; - } - - std::vector m_values; // preallocated; no reallocation - const std::size_t m_expected; // total messages to record - std::atomic m_next_slot; - std::atomic m_completed; - std::vector> m_slot_done; - mutable std::condition_variable m_wait_cv; - mutable std::mutex m_wait_mx; -}; + + void wait_for_all() const { + std::unique_lock lk(m_wait_mx); + m_wait_cv.wait(lk, [&] { + return m_completed.load(std::memory_order_acquire) >= m_expected; + }); + } + + Summary finalize() const { + if (recorded() != m_expected || + m_completed.load(std::memory_order_acquire) != m_expected) { + throw std::runtime_error("Incomplete latency capture"); + } + + std::vector sorted = m_values; + std::sort(sorted.begin(), sorted.end()); + + Summary summary; + summary.p50_ns = pick(sorted, 0.50); + summary.p99_ns = pick(sorted, 0.99); + summary.p999_ns = pick(sorted, 0.999); + return summary; + } + + static std::uint64_t invalid_slot() { + return std::numeric_limits::max(); + } + + static std::uint64_t now() { + const auto tp = std::chrono::steady_clock::now().time_since_epoch(); + return static_cast( + std::chrono::duration_cast(tp).count() + ); + } + + private: + // Nearest-rank percentile with ceil(p * N), clamped to [0..N-1]. + static std::uint64_t pick(const std::vector& data, double p) { + if (data.empty()) return 0; + const double r = std::ceil(p * static_cast(data.size())); + std::size_t idx = (r <= 1.0) ? 0 : (static_cast(r) - 1); + if (idx >= data.size()) idx = data.size() - 1; + return data[idx]; + } + + void complete_impl(std::uint64_t slot_u64, std::uint64_t t0_ns) { + if (slot_u64 >= m_expected) { + throw std::out_of_range("LatencyRecorder capacity exceeded"); + } + + const auto slot = static_cast(slot_u64); + + // Dedup per slot. + std::uint8_t expected = 0; + if (!m_slot_done[slot].compare_exchange_strong( + expected, 1, std::memory_order_acq_rel)) { + return; // duplicate completion -> ignore + } + + const auto t1_ns = now(); + m_values[slot] = t1_ns - t0_ns; + + const auto done = m_completed.fetch_add(1, std::memory_order_acq_rel) + 1; + if (done == m_expected) { + // Need the mutex for CV correctness (avoid lost wakeups). + std::lock_guard lk(m_wait_mx); + m_wait_cv.notify_all(); + } + } + + std::vector m_values; // latency per slot + std::vector m_t0_ns; // t0 per slot (for complete_slot) + const std::size_t m_expected; + std::atomic m_next_slot; + std::atomic m_completed; + + // 0 -> not done, 1 -> done. + std::vector> m_slot_done; + + mutable std::condition_variable m_wait_cv; + mutable std::mutex m_wait_mx; + }; } // namespace logit_bench From 34f208f7257a3e2534c41e891f54b9800b8be96b Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 04:17:56 +0300 Subject: [PATCH 10/16] bench: use LogRecord.line as latency slot id --- bench/adapters/LogItAdapter.cpp | 373 +++++++++++++++----------------- 1 file changed, 178 insertions(+), 195 deletions(-) diff --git a/bench/adapters/LogItAdapter.cpp b/bench/adapters/LogItAdapter.cpp index a54116d..d9dd191 100644 --- a/bench/adapters/LogItAdapter.cpp +++ b/bench/adapters/LogItAdapter.cpp @@ -3,224 +3,207 @@ #include #include #include +#include #include #include #include -#include #include namespace logit_bench { -namespace { -constexpr const char* kFilePath = "bench/results/logit_sink.log"; -constexpr std::size_t kSlotIndex = 0; -constexpr std::size_t kT0Index = 1; -constexpr std::size_t kActiveIndex = 2; -} // namespace - -class PassthroughFormatter : public logit::ILogFormatter { -public: - void set_timestamp_offset(int64_t) override {} - - std::string format(const logit::LogRecord& record) const override { - return record.format; - } - - bool is_passthrough() const noexcept override { return true; } -}; - -class MeasuringSink : public logit::ILogger { -public: - MeasuringSink() = default; - - void configure(const Scenario& scenario, LatencyRecorder& recorder) { - m_async = scenario.async; - m_sink = scenario.sink; - m_recorder = &recorder; - if (m_sink == SinkKind::File) { - std::filesystem::create_directories("bench/results"); - std::lock_guard lock(m_file_mutex); - m_file.close(); - m_file.open(kFilePath, std::ios::out | std::ios::trunc); - } else { - std::lock_guard lock(m_file_mutex); - m_file.close(); + namespace { + + constexpr const char* kFilePath = "bench/results/logit_sink.log"; + + // record.line == -1 => not measured + constexpr int kInactiveLine = -1; + } // namespace + + class PassthroughFormatter : public logit::ILogFormatter { + public: + void set_timestamp_offset(int64_t) override {} + + std::string format(const logit::LogRecord& record) const override { + return record.format; } - } - - void log(const logit::LogRecord& record, const std::string& message) override { - LatencyRecorder::Token token = extract(record); - if (!m_async) { - consume(token, message); - return; + + bool is_passthrough() const noexcept override { return true; } + }; + + class MeasuringSink : public logit::ILogger { + public: + MeasuringSink() = default; + + void configure(const Scenario& scenario, LatencyRecorder& recorder) { + m_async = scenario.async; + m_sink = scenario.sink; + m_recorder = &recorder; + + if (m_sink == SinkKind::File) { + std::filesystem::create_directories("bench/results"); + std::lock_guard lock(m_file_mutex); + m_file.close(); + m_file.open(kFilePath, std::ios::out | std::ios::trunc); + } else { + std::lock_guard lock(m_file_mutex); + m_file.close(); + } } - if (m_sink == SinkKind::Null) { - logit::detail::TaskExecutor::get_instance().add_task([this, token]() { - consume(token, std::string_view{}); - }); - return; + + void log(const logit::LogRecord& record, const std::string& message) override { + const int slot_line = record.line; + + if (!m_async) { + consume(slot_line, message); + return; + } + + if (m_sink == SinkKind::Null) { + logit::detail::TaskExecutor::get_instance().add_task([this, slot_line]() { + consume(slot_line, std::string_view{}); + }); + return; + } + + AsyncPayload payload; + payload.slot_line = slot_line; + payload.text = message; + + logit::detail::TaskExecutor::get_instance().add_task( + [this, payload = std::move(payload)]() mutable { + consume(payload.slot_line, payload.text); + }); } - - AsyncPayload payload; - payload.token = token; - payload.text = message; - logit::detail::TaskExecutor::get_instance().add_task([this, payload = std::move(payload)]() mutable { - consume(payload.token, payload.text); - }); - } - - 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 { - if (m_async) { - logit::detail::TaskExecutor::get_instance().wait(); + + 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); } - std::lock_guard lock(m_file_mutex); - if (m_file.is_open()) { - m_file.flush(); + + logit::LogLevel get_log_level() const override { + return static_cast(m_level.load(std::memory_order_relaxed)); } - } - -private: - struct AsyncPayload { - LatencyRecorder::Token token; - std::string text; - }; - - static LatencyRecorder::Token extract(const logit::LogRecord& record) { - LatencyRecorder::Token token; - if (record.user_data != 0) { - auto* payload = reinterpret_cast(record.user_data); - token = *payload; - return token; + + void wait() override { + if (m_async) { + logit::detail::TaskExecutor::get_instance().wait(); + } + + std::lock_guard lock(m_file_mutex); + if (m_file.is_open()) { + m_file.flush(); + } } - if (record.args_array.size() <= kActiveIndex) { - return token; + + private: + struct AsyncPayload { + int slot_line = kInactiveLine; // record.line copy + std::string text; + }; + + void consume(int slot_line, std::string_view text) { + // slot-only completion + if (slot_line >= 0 && m_recorder) { + m_recorder->complete_slot(static_cast(slot_line)); + } + + if (m_sink == SinkKind::File) { + std::lock_guard lock(m_file_mutex); + if (m_file.is_open()) { + m_file << text << '\n'; + } + } } - const auto& slot = record.args_array[kSlotIndex]; - const auto& t0 = record.args_array[kT0Index]; - const auto& active = record.args_array[kActiveIndex]; - token.slot = read_u64(slot); - token.t0_ns = read_u64(t0); - token.active = read_u64(active) != 0; - return token; - } - - static std::uint64_t read_u64(const logit::VariableValue& value) { - using VT = logit::VariableValue::ValueType; - switch (value.type) { - case VT::UINT64_VAL: - return value.pod_value.uint64_value; - case VT::INT64_VAL: - return static_cast(value.pod_value.int64_value); - case VT::UINT32_VAL: - return value.pod_value.uint32_value; - case VT::INT32_VAL: - return static_cast(value.pod_value.int32_value); - default: - break; + + bool m_async = false; + SinkKind m_sink = SinkKind::Null; + LatencyRecorder* m_recorder = nullptr; + + std::ofstream m_file; + mutable std::mutex m_file_mutex; + + std::atomic m_level{static_cast(logit::LogLevel::LOG_LVL_TRACE)}; + }; + + class LogItAdapter::Impl { + public: + Impl() + : logger(logit::Logger::get_instance()) { + auto sink_ptr = std::make_unique(); + sink = sink_ptr.get(); + + auto formatter = std::unique_ptr(new PassthroughFormatter()); + logger.add_logger(std::move(sink_ptr), std::move(formatter)); } - return 0; - } - - void consume(const LatencyRecorder::Token& token, std::string_view text) { - if (token.active && m_recorder) { - m_recorder->complete(token); + + void prepare(const Scenario& scenario, LatencyRecorder& recorder) { + if (sink) { + sink->configure(scenario, recorder); + } } - if (m_sink == SinkKind::File) { - std::lock_guard lock(m_file_mutex); - if (m_file.is_open()) { - m_file << text << '\n'; + + void log(const LatencyRecorder::Token& token, std::string_view message) { + int line = kInactiveLine; + + // active => slot in record.line + if (token.active) { + // safety: avoid UB if someone sets huge totals + if (token.slot <= static_cast(std::numeric_limits::max())) { + line = static_cast(token.slot); + } else { + line = kInactiveLine; + } } + + logit::LogRecord record( + logit::LogLevel::LOG_LVL_INFO, + 0, // logger index + std::string(), // file + line, // line = slot (or -1) + std::string(), // function + std::string(message), + std::string(), // arg_names + -1, + false, + false); + + logger.log(record); } - } - - bool m_async = false; - SinkKind m_sink = SinkKind::Null; - LatencyRecorder* m_recorder = nullptr; - std::ofstream m_file; - mutable std::mutex m_file_mutex; - std::atomic m_level{static_cast(logit::LogLevel::LOG_LVL_TRACE)}; -}; - -class LogItAdapter::Impl { -public: - Impl() - : logger(logit::Logger::get_instance()) { - auto sink_ptr = std::make_unique(); - sink = sink_ptr.get(); - auto formatter = std::unique_ptr(new PassthroughFormatter()); - logger.add_logger(std::move(sink_ptr), std::move(formatter)); - } - - void prepare(const Scenario& scenario, LatencyRecorder& recorder) { - if (sink) { - sink->configure(scenario, recorder); + + void flush() { + if (sink) { + sink->wait(); + } } - m_tokens.assign(scenario.total_messages, {}); - } - - void log(const LatencyRecorder::Token& token, std::string_view message) { - logit::LogRecord record( - logit::LogLevel::LOG_LVL_INFO, - 0, - std::string(), - 0, - std::string(), - std::string(message), - std::string(), - -1, - false, - false); - if (token.active && token.slot < m_tokens.size()) { - m_tokens[token.slot] = token; - record.user_data = reinterpret_cast(&m_tokens[token.slot]); + + logit::Logger& logger; + MeasuringSink* sink = nullptr; + }; + + LogItAdapter::LogItAdapter() + : m_impl(std::make_unique()) {} + + LogItAdapter::~LogItAdapter() = default; + + void LogItAdapter::prepare(const Scenario& scenario, LatencyRecorder& recorder) { + if (m_impl) { + m_impl->prepare(scenario, recorder); } - logger.log(record); } - - void flush() { - if (sink) { - sink->wait(); + + void LogItAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { + if (m_impl) { + m_impl->log(token, message); } } - - logit::Logger& logger; - MeasuringSink* sink = nullptr; - std::vector m_tokens; -}; - -LogItAdapter::LogItAdapter() - : m_impl(std::make_unique()) {} - -LogItAdapter::~LogItAdapter() = default; - -void LogItAdapter::prepare(const Scenario& scenario, LatencyRecorder& recorder) { - if (m_impl) { - m_impl->prepare(scenario, recorder); - } -} - -void LogItAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { - if (m_impl) { - m_impl->log(token, message); - } -} - -void LogItAdapter::flush() { - if (m_impl) { - m_impl->flush(); + + void LogItAdapter::flush() { + if (m_impl) { + m_impl->flush(); + } } -} } // namespace logit_bench From 103ef960dc24e169dc08729df2881bfd860ae41b Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 04:45:24 +0300 Subject: [PATCH 11/16] bench: remove per-log new/delete in spdlog adapter (slot-in-wire) --- bench/adapters/SpdlogAdapter.cpp | 77 +++++++++++--------------------- 1 file changed, 26 insertions(+), 51 deletions(-) diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index e8f59f3..25d95da 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -3,7 +3,6 @@ #ifdef LOGIT_BENCH_HAVE_SPDLOG #include -#include #include #include #include @@ -21,12 +20,6 @@ namespace logit_bench { namespace { constexpr const char* kFilePath = "bench/results/spdlog_sink.log"; constexpr std::size_t kDefaultQueue = 8192; - -struct MessagePayload { - LatencyRecorder::Token token; - std::string text; - std::string wire; -}; } // namespace class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { @@ -36,6 +29,7 @@ class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { void configure(const Scenario& scenario, std::shared_ptr recorder) { m_sink = scenario.sink; m_recorder = std::move(recorder); + if (m_sink == SinkKind::File) { std::filesystem::create_directories("bench/results"); std::lock_guard lock(m_mutex); @@ -48,38 +42,22 @@ class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { } void log(const spdlog::details::log_msg& msg) override { - std::string_view wire(msg.payload.data(), msg.payload.size()); - const auto sep = wire.find('|'); - if (sep == std::string_view::npos) { - return; // Control messages or malformed payloads. - } - - std::uintptr_t raw_ptr = 0; - const auto* begin = wire.data(); - const auto* end = begin + sep; - if (std::from_chars(begin, end, raw_ptr, 16).ec != std::errc()) { - return; + // 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)); } - auto* payload = reinterpret_cast(raw_ptr); - if (!payload) { - return; - } - - if (payload->token.active && m_recorder) { - m_recorder->complete(payload->token); - } if (m_sink == SinkKind::File) { std::lock_guard lock(m_mutex); if (m_file.is_open()) { - m_file << payload->text << '\n'; + std::string_view text(msg.payload.data(), msg.payload.size()); + m_file << text << '\n'; } } - delete payload; } void set_pattern(const std::string&) override {} - void set_formatter(std::unique_ptr) override {} void flush() override { @@ -89,8 +67,10 @@ class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { } } +private: SinkKind m_sink = SinkKind::Null; std::shared_ptr m_recorder; + std::ofstream m_file; std::mutex m_mutex; }; @@ -112,22 +92,28 @@ void SpdlogAdapter::prepare(const Scenario& scenario, LatencyRecorder& recorder) spdlog::shutdown(); m_sink = std::make_shared(); + auto recorder_handle = m_recorder_handle; if (!recorder_handle) { recorder_handle = std::shared_ptr(&recorder, [](LatencyRecorder*){}); } m_sink->configure(scenario, recorder_handle); + m_async = scenario.async; 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 = + std::max(kDefaultQueue, scenario.total_messages * 2); + spdlog::init_thread_pool(queue_size, 1); + auto async_logger = std::make_shared( logger_name, m_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block); + async_logger->set_level(spdlog::level::trace); async_logger->set_pattern("%v"); m_logger = std::move(async_logger); @@ -140,29 +126,18 @@ void SpdlogAdapter::prepare(const Scenario& scenario, LatencyRecorder& recorder) } void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { - if (!m_logger) { - return; - } - auto* payload = new MessagePayload(); - payload->token = token; - payload->text.assign(message.data(), message.size()); - - char buf[2 + sizeof(void*) * 2]; - const auto ptr = reinterpret_cast(payload); - const auto [end, ec] = std::to_chars(std::begin(buf), std::end(buf), ptr, 16); - if (ec != std::errc()) { - delete payload; - return; - } + if (!m_logger) return; + + // If token is inactive -> write plain message and sink will ignore (line = -1). + const int line = token.active ? static_cast(token.slot) : -1; - payload->wire.clear(); - payload->wire.reserve(static_cast(end - buf) + 1 + payload->text.size()); - payload->wire.append(buf, end); - payload->wire.push_back('|'); - payload->wire.append(payload->text); + // file/func are irrelevant here; keep them stable to avoid nullptr quirks. + spdlog::source_loc loc{"bench", line, "bench"}; - spdlog::source_loc loc{}; - m_logger->log(loc, spdlog::level::info, spdlog::string_view_t(payload->wire)); + m_logger->log( + loc, + spdlog::level::info, + spdlog::string_view_t(message.data(), message.size())); } void SpdlogAdapter::flush() { From cadee24e5ee474f0ad7366a7a8bd7b8a18ad7e36 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 05:03:28 +0300 Subject: [PATCH 12/16] chore: refactor SpdlogAdapter and MeasuringSink class --- bench/adapters/SpdlogAdapter.cpp | 240 +++++++++++++++---------------- 1 file changed, 120 insertions(+), 120 deletions(-) diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index 25d95da..4320efb 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -17,137 +17,137 @@ #include namespace logit_bench { -namespace { -constexpr const char* kFilePath = "bench/results/spdlog_sink.log"; -constexpr std::size_t kDefaultQueue = 8192; -} // namespace - -class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { -public: - MeasuringSink() = default; - - void configure(const Scenario& scenario, std::shared_ptr recorder) { - m_sink = scenario.sink; - m_recorder = std::move(recorder); - - if (m_sink == SinkKind::File) { - std::filesystem::create_directories("bench/results"); - std::lock_guard lock(m_mutex); - m_file.close(); - m_file.open(kFilePath, std::ios::out | std::ios::trunc); - } else { - std::lock_guard lock(m_mutex); - m_file.close(); + namespace { + constexpr const char* kFilePath = "bench/results/spdlog_sink.log"; + constexpr std::size_t kDefaultQueue = 8192; + } // namespace + + class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { + public: + MeasuringSink() = default; + + void configure(const Scenario& scenario, std::shared_ptr recorder) { + m_sink = scenario.sink; + m_recorder = std::move(recorder); + + if (m_sink == SinkKind::File) { + std::filesystem::create_directories("bench/results"); + std::lock_guard lock(m_mutex); + m_file.close(); + m_file.open(kFilePath, std::ios::out | std::ios::trunc); + } else { + std::lock_guard lock(m_mutex); + m_file.close(); + } } - } - - void log(const spdlog::details::log_msg& msg) override { - // 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)); + + void log(const spdlog::details::log_msg& msg) override { + // 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)); + } + + if (m_sink == SinkKind::File) { + std::lock_guard lock(m_mutex); + if (m_file.is_open()) { + std::string_view text(msg.payload.data(), msg.payload.size()); + m_file << text << '\n'; + } + } } - - if (m_sink == SinkKind::File) { + + void set_pattern(const std::string&) override {} + void set_formatter(std::unique_ptr) override {} + + void flush() override { std::lock_guard lock(m_mutex); if (m_file.is_open()) { - std::string_view text(msg.payload.data(), msg.payload.size()); - m_file << text << '\n'; + m_file.flush(); } } + + private: + SinkKind m_sink = SinkKind::Null; + std::shared_ptr m_recorder; + + std::ofstream m_file; + std::mutex m_mutex; + }; + + SpdlogAdapter::SpdlogAdapter() = default; + + SpdlogAdapter::~SpdlogAdapter() { + flush(); + spdlog::shutdown(); } - - void set_pattern(const std::string&) override {} - void set_formatter(std::unique_ptr) override {} - - void flush() override { - std::lock_guard lock(m_mutex); - if (m_file.is_open()) { - m_file.flush(); - } + + void SpdlogAdapter::set_recorder_handle(std::shared_ptr recorder) { + m_recorder_handle = std::move(recorder); } - -private: - SinkKind m_sink = SinkKind::Null; - std::shared_ptr m_recorder; - - std::ofstream m_file; - std::mutex m_mutex; -}; - -SpdlogAdapter::SpdlogAdapter() = default; - -SpdlogAdapter::~SpdlogAdapter() { - flush(); - spdlog::shutdown(); -} - -void SpdlogAdapter::set_recorder_handle(std::shared_ptr recorder) { - m_recorder_handle = std::move(recorder); -} - -void SpdlogAdapter::prepare(const Scenario& scenario, LatencyRecorder& recorder) { - m_logger.reset(); - m_sink.reset(); - spdlog::shutdown(); - - m_sink = std::make_shared(); - - auto recorder_handle = m_recorder_handle; - if (!recorder_handle) { - recorder_handle = std::shared_ptr(&recorder, [](LatencyRecorder*){}); - } - m_sink->configure(scenario, recorder_handle); - - m_async = scenario.async; - - 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); - - spdlog::init_thread_pool(queue_size, 1); - - auto async_logger = std::make_shared( - logger_name, - m_sink, - spdlog::thread_pool(), - spdlog::async_overflow_policy::block); - - async_logger->set_level(spdlog::level::trace); - async_logger->set_pattern("%v"); - m_logger = std::move(async_logger); - } else { - auto logger = std::make_shared(logger_name, m_sink); - logger->set_level(spdlog::level::trace); - logger->set_pattern("%v"); - m_logger = std::move(logger); + + void SpdlogAdapter::prepare(const Scenario& scenario, LatencyRecorder& recorder) { + m_logger.reset(); + m_sink.reset(); + spdlog::shutdown(); + + m_sink = std::make_shared(); + + auto recorder_handle = m_recorder_handle; + if (!recorder_handle) { + recorder_handle = std::shared_ptr(&recorder, [](LatencyRecorder*){}); + } + m_sink->configure(scenario, recorder_handle); + + m_async = scenario.async; + + 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); + + spdlog::init_thread_pool(queue_size, 1); + + auto async_logger = std::make_shared( + logger_name, + m_sink, + spdlog::thread_pool(), + spdlog::async_overflow_policy::block); + + async_logger->set_level(spdlog::level::trace); + async_logger->set_pattern("%v"); + m_logger = std::move(async_logger); + } else { + auto logger = std::make_shared(logger_name, m_sink); + logger->set_level(spdlog::level::trace); + logger->set_pattern("%v"); + m_logger = std::move(logger); + } } -} - -void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { - if (!m_logger) return; - - // If token is inactive -> write plain message and sink will ignore (line = -1). - const int line = token.active ? static_cast(token.slot) : -1; - - // file/func are irrelevant here; keep them stable to avoid nullptr quirks. - spdlog::source_loc loc{"bench", line, "bench"}; - - m_logger->log( - loc, - spdlog::level::info, - spdlog::string_view_t(message.data(), message.size())); -} - -void SpdlogAdapter::flush() { - if (m_logger) { - m_logger->flush(); + + void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { + if (!m_logger) return; + + // If token is inactive -> write plain message and sink will ignore (line = -1). + const int line = token.active ? static_cast(token.slot) : -1; + + // file/func are irrelevant here; keep them stable to avoid nullptr quirks. + spdlog::source_loc loc{"bench", line, "bench"}; + + m_logger->log( + loc, + spdlog::level::info, + spdlog::string_view_t(message.data(), message.size())); } - if (m_sink) { - m_sink->flush(); + + void SpdlogAdapter::flush() { + if (m_logger) { + m_logger->flush(); + } + if (m_sink) { + m_sink->flush(); + } } -} } // namespace logit_bench From f0e855736320baf67b412b20cf7679a6de02387e Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 05:09:36 +0300 Subject: [PATCH 13/16] refactor: remove user_data from LogRecord Removed user_data member from LogRecord structure. --- include/logit_cpp/logit/utils/LogRecord.hpp | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/include/logit_cpp/logit/utils/LogRecord.hpp b/include/logit_cpp/logit/utils/LogRecord.hpp index 1db0c1d..2ce59d8 100644 --- a/include/logit_cpp/logit/utils/LogRecord.hpp +++ b/include/logit_cpp/logit/utils/LogRecord.hpp @@ -23,7 +23,6 @@ namespace logit { const std::string format; ///< Format string for the message. const std::string arg_names; ///< Argument names for the log. std::vector args_array; ///< Argument values for the log. - std::uintptr_t user_data = reinterpret_cast(nullptr); ///< Opaque payload for adapters (e.g., benchmark tokens). Defaults to nullptr. std::thread::id thread_id; ///< ID of the logging thread. const int logger_index; ///< Logger index (-1 to log to all). const bool print_mode; ///< Flag to determine whether arguments are printed in a raw format without special symbols. @@ -49,8 +48,7 @@ namespace logit { const std::string& arg_names, int logger_index, bool print_mode, - bool fmt_mode = false, - std::uintptr_t user_data = reinterpret_cast(nullptr)) : + bool fmt_mode = false) : log_level(log_level), timestamp_ms(timestamp_ms), file(file), From a326788a4e444bf9fa74f12716f1be5c6fdf0743 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 05:18:16 +0300 Subject: [PATCH 14/16] refactor: make args_array mutable for caching in LogRecord Changed args_array to be mutable for caching purposes. --- include/logit_cpp/logit/utils/LogRecord.hpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/include/logit_cpp/logit/utils/LogRecord.hpp b/include/logit_cpp/logit/utils/LogRecord.hpp index 2ce59d8..e1ca6ab 100644 --- a/include/logit_cpp/logit/utils/LogRecord.hpp +++ b/include/logit_cpp/logit/utils/LogRecord.hpp @@ -22,7 +22,8 @@ namespace logit { const std::string function; ///< Function name. const std::string format; ///< Format string for the message. const std::string arg_names; ///< Argument names for the log. - std::vector args_array; ///< Argument values for the log. + // IMPORTANT: cache, filled by Logger::print() even for const LogRecord& + mutable std::vector args_array; ///< Argument values for the log. std::thread::id thread_id; ///< ID of the logging thread. const int logger_index; ///< Logger index (-1 to log to all). const bool print_mode; ///< Flag to determine whether arguments are printed in a raw format without special symbols. @@ -56,7 +57,6 @@ namespace logit { function(function), format(format), arg_names(arg_names), - user_data(user_data), thread_id(std::this_thread::get_id()), logger_index(logger_index), print_mode(print_mode), From 39a23d4cffa88208e52ba23587d11036a6635c1c Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 05:21:03 +0300 Subject: [PATCH 15/16] perf(Logger): build args_array in-place (no LogRecord copy) --- include/logit_cpp/logit/Logger.hpp | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/include/logit_cpp/logit/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index 85826e4..549e07d 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -23,15 +23,15 @@ namespace logit { - #if LOGIT_HAS_SHARED_MUTEX +#if LOGIT_HAS_SHARED_MUTEX using LoggerMutex = std::shared_mutex; using LoggerReadLock = std::shared_lock; using LoggerWriteLock = std::unique_lock; - #else +#else using LoggerMutex = std::mutex; using LoggerReadLock = std::unique_lock; using LoggerWriteLock = std::unique_lock; - #endif +#endif /// \class Logger /// \brief Singleton class managing multiple loggers and formatters. @@ -331,10 +331,10 @@ namespace logit { log(record); return; } - LogRecord mutable_record = record; - auto var_names = split_arguments(mutable_record.arg_names); - mutable_record.args_array = args_to_array(var_names.begin(), args...); - log(mutable_record); + // args_array is mutable cache inside LogRecord + auto var_names = split_arguments(record.arg_names); + record.args_array = args_to_array(var_names.begin(), args...); + log(record); } #ifdef _MSC_VER From ab27be07c43138c281493e1afafb9b1a1e499298 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 5 Dec 2025 06:29:16 +0300 Subject: [PATCH 16/16] docs(benchmarks): refresh latency snapshot Update README, README-RU, and Doxygen benchmark tables to the latest Dec 05 03:18 UTC run. --- README-RU.md | 50 +++++++--------- README.md | 69 +++++++++++----------- bench/adapters/SpdlogAdapter.cpp | 8 ++- bench/results/latency-2025-12-04-10k.csv | 73 ------------------------ bench/results/latency-2025-12-05-10k.csv | 73 ++++++++++++++++++++++++ docs/mainpage.dox | 46 ++++++--------- include/logit_cpp/logit/Logger.hpp | 31 +++++----- 7 files changed, 169 insertions(+), 181 deletions(-) delete mode 100644 bench/results/latency-2025-12-04-10k.csv create mode 100644 bench/results/latency-2025-12-05-10k.csv diff --git a/README-RU.md b/README-RU.md index 34927dd..34c33ad 100644 --- a/README-RU.md +++ b/README-RU.md @@ -697,47 +697,37 @@ LogIt++ включает библиотеку *fmt* для форматиров Запустите `./build/bench/logit_bench`, чтобы получить полный набор измерений (sync/async × null/file × количество продюсеров × размер сообщений). Результаты дописываются в `bench/results/latency.csv` по одной строке на каждую библиотеку/комбинацию. При необходимости сократите нагрузку с помощью переменных окружения `LOGIT_BENCH_TOTAL` и `LOGIT_BENCH_WARMUP`. -### Последний снимок (04.12.2025) +### Что на самом деле измеряет бенчмарк + +Харнесс меряет end-to-end латентность (*вызов лога → доставка в sink*) и суммарную пропускную. Он полезен для поиска регрессий и сравнения дизайна пайплайнов, но это **не** идеальное соревнование «кто быстрее». LogIt++ осознанно тратит больше работы в духе Python `icecream`: один `LOGIT_*` может парсить имена аргументов, собирать `args_array` из `VariableValue` и опционально форматировать структуру. Классические printf-логгеры вроде spdlog оптимизируются под быстрое форматирование строк и очереди, без этой «леденцовой» ветки. Для корректного сравнения держите оба лагеря в одном режиме: + +- *Только текст / passthrough* показывает стоимость dispatch/очереди/sink и ближе всего к поведению spdlog по умолчанию. +- *IceCream-стиль метаданных* (`LOGIT_*` с захватом аргументов) включает парсинг имён и упаковку значений; тут LogIt++ делает больше работы на вызов намеренно. + +Асинхронные цифры включают enqueue + пробуждение воркера/планирование ОС + работу sink; для file sink добавляется разброс из-за буферов/flush. + +### Последний снимок (05.12.2025) - Сборка: `Release`, `LOGIT_BENCH_ENABLE=ON`, `LOGIT_BENCH_WITH_SPDLOG=ON`, `LOGIT_USE_MPSC_RING=ON` (по умолчанию). -- Нагрузка: `LOGIT_BENCH_TOTAL=10000`, 4 продюсера, размер сообщений 200 байт для таблицы сравнения (остальные комбинации см. в `bench/results/latency-2025-12-04-10k.csv`). +- Нагрузка: `LOGIT_BENCH_TOTAL=10000`, 4 продюсера, размер сообщений 200 байт для таблицы сравнения (остальные комбинации см. в `bench/results/latency-2025-12-05-10k.csv`). - Метрики: медианная задержка (`p50`) в наносекундах и достигнутая пропускная способность (сообщений/с). - Железо: 3 vCPU (Intel Xeon E5-2673 v4 @ 2.30GHz) в виртуальной машине, одна NUMA-нода. -- Данные: обновлено по `bench/results/latency-2025-12-04-10k.csv` (04.12.2025, 06:53 UTC). +- Данные: обновлено по `bench/results/latency-2025-12-05-10k.csv` (05.12.2025, 03:18 UTC). | Режим | Приёмник | LogIt++ p50 | Пропускная (LogIt++) | spdlog p50 | Пропускная (spdlog) | |-------|----------|-------------|----------------------|------------|---------------------| -| Sync | Null | 159 нс | 2 559 124 сооб./с | 302 нс | 2 747 733 сооб./с | -| Sync | File | 108 нс | 2 081 540 сооб./с | 365 нс | 1 304 177 сооб./с | -| Async | Null | 44 699 нс | 753 078 сооб./с | 1 499 973 нс | 913 881 сооб./с | -| Async | File | 996 466 нс | 850 021 сооб./с | 3 999 290 нс | 912 399 сооб./с | +| Sync | Null | 119 нс | 2 127 704 сооб./с | 86 нс | 5 803 783 сооб./с | +| Sync | File | 130 нс | 1 035 690 сооб./с | 87 нс | 1 593 987 сооб./с | +| Async | Null | 20 916 нс | 1 846 272 сооб./с | 1 248 779 нс | 1 303 573 сооб./с | +| Async | File | 255 323 нс | 651 384 сооб./с | 5 001 140 нс | 1 153 976 сооб./с | -**Выводы:** в этом снимке оба логгера выдают миллионы сообщений в секунду в синхронных режимах; LogIt++ удерживает более низкий p50, spdlog остаётся быстрее на Null и медленнее на файловом приёмнике. В асинхронных сценариях LogIt++ держит end-to-end p50 на уровне десятков–сотен микросекунд, тогда как spdlog уходит в миллисекунды; пропускная обоих кластеризуется вокруг 0.75–0.9 млн сооб./с в зависимости от приёмника. +**Выводы:** LogIt++ держит sub-µs p50 в синхронных режимах, даже с путём метаданных в стиле IceCream; spdlog выигрывает по скорости на null/file за счёт более лёгкого форматирования. В async обе стороны включают enqueue + пробуждения + sink: LogIt++ остаётся в десятках–сотнях микросекунд, тогда как адаптер spdlog в этой конфигурации уходит в миллисекунды. -### Как устроен бенч-харнесс (LatencyRecorder и `user_data`) +### Как устроен бенч-харнесс (LatencyRecorder) - `bench/LatencyRecorder.hpp` заранее резервирует слоты и ведёт `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` с защитой от повторных `complete()` на один слот. Доступны методы `recorded()`, `wait_for_all()` и `finalize()` для end-to-end измерений между продюсерами и консюмером. -- В `logit::LogRecord` добавлено поле `user_data` для произвольной нагрузки (например, указатель на бенч-токен без использования `args_array`). Оставляйте `0` для обычного логирования; адаптеры/приёмники могут интерпретировать поле, если оно задано. Указатель должен жить до момента, когда sink обработает запись. -- Пример: прикрепить заранее выделенный бенч-пейлоад вместо записи токена в `args_array` (хранилище живёт весь прогон): - ```cpp - struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; - std::vector payloads(total_messages); - - // В продюсере - auto token = recorder.begin(true); - payloads[token.slot].token = token; - logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, - preformatted_text, /*arg_names*/"", /*logger*/-1, - /*print*/false, /*fmt*/false, - reinterpret_cast(&payloads[token.slot])); - Logger::get_instance().log(rec, preformatted_text); - - // В sink/адаптере - if (record.user_data) { - auto* p = reinterpret_cast(record.user_data); - recorder.complete(p->token); - } - ``` +- Адаптер LogIt кладёт номер слота в `LogRecord::line` (см. `bench/adapters/LogItAdapter.cpp`). Приёмник вызывает `LatencyRecorder::complete_slot()`, когда видит неотрицательный номер строки; никаких дополнительных полей в записи не требуется. + ## Системные бэкенды diff --git a/README.md b/README.md index 69f74c8..ad2e872 100644 --- a/README.md +++ b/README.md @@ -769,48 +769,49 @@ Run `./build/bench/logit_bench` to record the full matrix (sync/async × null/fi are appended to `bench/results/latency.csv` with one row per library/combination. Override the workload via `LOGIT_BENCH_TOTAL` and `LOGIT_BENCH_WARMUP` environment variables if you need a lighter run. -### Latest snapshot (Dec 04, 2025) +### What this benchmark measures + +The harness times end-to-end latency (*log call → delivery into the sink*) and aggregate throughput. It is great for spotting +regressions and comparing pipeline designs, but it is **not** a perfect “fastest logger wins” contest. LogIt++ intentionally does +extra work inspired by Python’s `icecream`: a single `LOGIT_*` call can extract argument names, build `args_array` with +`VariableValue`, and optionally format those structured values. Classic printf-style loggers such as spdlog focus on fast string +formatting and queueing instead of this metadata path. If you want an apples-to-apples view, keep the comparison within the same +mode: + +- *Text-only/passthrough* shows dispatch/queue/sink cost and is the closest to spdlog’s default path. +- *Metadata-heavy* (`LOGIT_*` with argument capture) includes parsing and packing the structured arguments; LogIt++ will do more + work per call here by design. + +Async numbers also include enqueue + worker wakeup/scheduling + sink time; file sinks add I/O variance from buffering and flush +policies. + +### Latest snapshot (Dec 05, 2025) - Build: `Release`, `LOGIT_BENCH_ENABLE=ON`, `LOGIT_BENCH_WITH_SPDLOG=ON`, `LOGIT_USE_MPSC_RING=ON` (default). - Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, message size 200 bytes for the comparison table (all other sizes/counts - are in `bench/results/latency-2025-12-04-10k.csv`). + are in `bench/results/latency-2025-12-05-10k.csv`). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:53 UTC). +- Data: refreshed from `bench/results/latency-2025-12-05-10k.csv` (Dec 05, 2025 @ 03:18 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| -| Sync | Null | 159 ns | 2,559,124 msg/s | 302 ns | 2,747,733 msg/s | -| Sync | File | 108 ns | 2,081,540 msg/s | 365 ns | 1,304,177 msg/s | -| Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | -| Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | - -**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog remains ahead in throughput for the null path and trails on the file sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. - -### Benchmark harness notes (LatencyRecorder & `user_data`) - -- `bench/LatencyRecorder.hpp` preallocates slots and tracks `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` with per-slot deduplication (duplicate `complete()` calls are ignored). It exposes `recorded()`, `wait_for_all()`, and `finalize()` for end-to-end timing across producers/consumers. -- `logit::LogRecord` now carries an optional `user_data` field for opaque payloads (e.g., passing a benchmark token pointer without stuffing `args_array`). Leave it at `0` for normal logging; adapters/sinks may reinterpret it when present. The pointer must remain valid until the sink consumes the record. -- Example: attach a preallocated benchmark payload instead of pushing tokens into `args_array` (the storage lives for the whole run): - ```cpp - struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; - std::vector payloads(total_messages); - - // Producer thread - auto token = recorder.begin(true); - payloads[token.slot].token = token; - logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, - preformatted_text, /*arg_names*/"", /*logger*/-1, - /*print*/false, /*fmt*/false, - reinterpret_cast(&payloads[token.slot])); - Logger::get_instance().log(rec, preformatted_text); - - // In your sink/adapter - if (record.user_data) { - auto* p = reinterpret_cast(record.user_data); - recorder.complete(p->token); - } - ``` +| Sync | Null | 119 ns | 2,127,704 msg/s | 86 ns | 5,803,783 msg/s | +| Sync | File | 130 ns | 1,035,690 msg/s | 87 ns | 1,593,987 msg/s | +| Async | Null | 20,916 ns | 1,846,272 msg/s | 1,248,779 ns | 1,303,573 msg/s | +| Async | File | 255,323 ns | 651,384 msg/s | 5,001,140 ns | 1,153,976 msg/s | + +**Takeaways:** LogIt++ keeps sub-microsecond p50s in synchronous modes while carrying the IceCream-style metadata path; spdlog’s lean formatting stays faster on the null/file sinks. Asynchronously, both numbers include enqueue + worker wakeups + sink work; LogIt++ stays in the tens-to-hundreds of microseconds, while the spdlog adapter lands in low-to-mid milliseconds for this run. + +### Benchmark harness notes (LatencyRecorder) + +- `bench/LatencyRecorder.hpp` preallocates slots and tracks `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` with per- +slot deduplication (duplicate `complete()` calls are ignored). It exposes `recorded()`, `wait_for_all()`, and `finalize()` for +end-to-end timing across producers/consumers. +- The LogIt adapter stores the benchmark slot in `LogRecord::line` (see `bench/adapters/LogItAdapter.cpp`). Sinks call + `LatencyRecorder::complete_slot()` when they observe a non-negative line number, so no extra payload is needed inside the log + record. + --- diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index 4320efb..d0bd26a 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include @@ -128,8 +129,11 @@ namespace logit_bench { void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { if (!m_logger) return; - // If token is inactive -> write plain message and sink will ignore (line = -1). - const int line = token.active ? static_cast(token.slot) : -1; + int line = -1; + if (token.active && token.slot <= static_cast(std::numeric_limits::max())) { + // Pass slot via source_loc.line so the sink can correlate without parsing payload. + line = static_cast(token.slot); + } // file/func are irrelevant here; keep them stable to avoid nullptr quirks. spdlog::source_loc loc{"bench", line, "bench"}; diff --git a/bench/results/latency-2025-12-04-10k.csv b/bench/results/latency-2025-12-04-10k.csv deleted file mode 100644 index 3bc9672..0000000 --- a/bench/results/latency-2025-12-04-10k.csv +++ /dev/null @@ -1,73 +0,0 @@ -lib,async,sink,producers,msg_bytes,total,p50_ns,p99_ns,p999_ns,throughput -log-it-cpp,0,null,1,40,10000,92,182,315,5357529.36 -log-it-cpp,0,null,1,200,10000,106,200,354,4900303.33 -log-it-cpp,0,null,1,1024,10000,112,221,364,4890032.94 -log-it-cpp,0,null,4,40,10000,93,7341,34666,3056898.98 -log-it-cpp,0,null,4,200,10000,159,7561,30513,2559124.08 -log-it-cpp,0,null,4,1024,10000,219,746,20852,2564110.45 -log-it-cpp,0,null,16,40,10000,117,120838,411764,2238446.48 -log-it-cpp,0,null,16,200,10000,110,85115,554545,2437013.56 -log-it-cpp,0,null,16,1024,10000,124,89455,651284,2160426.81 -log-it-cpp,0,file,1,40,10000,92,199,338,3591300.00 -log-it-cpp,0,file,1,200,10000,108,218,363,2642238.99 -log-it-cpp,0,file,1,1024,10000,131,345,501,1168214.47 -log-it-cpp,0,file,4,40,10000,103,14763,67392,2189043.14 -log-it-cpp,0,file,4,200,10000,108,4885,84935,2081539.74 -log-it-cpp,0,file,4,1024,10000,130,28959,118834,775085.29 -log-it-cpp,0,file,16,40,10000,92,63285,592951,2071042.56 -log-it-cpp,0,file,16,200,10000,120,100965,1188611,1406287.00 -log-it-cpp,0,file,16,1024,10000,126,13572,2525084,966869.26 -log-it-cpp,1,null,1,40,10000,6167,140477,160222,1382398.72 -log-it-cpp,1,null,1,200,10000,2417634,3757859,3783013,653858.07 -log-it-cpp,1,null,1,1024,10000,5753043,20554446,20867541,308368.51 -log-it-cpp,1,null,4,40,10000,6898,87823,106759,880174.84 -log-it-cpp,1,null,4,200,10000,44699,511957,553072,753077.77 -log-it-cpp,1,null,4,1024,10000,24312,1233924,1504219,462569.97 -log-it-cpp,1,null,16,40,10000,82385,1664170,1738195,1284781.28 -log-it-cpp,1,null,16,200,10000,50742,1497647,1961082,834075.59 -log-it-cpp,1,null,16,1024,10000,639279,5262976,8799440,394638.68 -log-it-cpp,1,file,1,40,10000,7088,1246048,1282644,1332271.78 -log-it-cpp,1,file,1,200,10000,4942082,6824108,6872425,663083.63 -log-it-cpp,1,file,1,1024,10000,16798493,27161411,27182741,285371.76 -log-it-cpp,1,file,4,40,10000,11576,751585,770923,1134828.27 -log-it-cpp,1,file,4,200,10000,996466,2978576,2996734,850021.31 -log-it-cpp,1,file,4,1024,10000,496132,4058713,4114558,391014.03 -log-it-cpp,1,file,16,40,10000,138088,686063,803493,1189221.99 -log-it-cpp,1,file,16,200,10000,350348,917351,1250075,1105190.48 -log-it-cpp,1,file,16,1024,10000,1442846,4242603,6039678,414511.81 -spdlog,0,null,1,40,10000,269,549,6532,2602869.30 -spdlog,0,null,1,200,10000,273,554,733,2655273.07 -spdlog,0,null,1,1024,10000,426,1032,6698,1544485.98 -spdlog,0,null,4,40,10000,395,739,6905,3372228.62 -spdlog,0,null,4,200,10000,302,688,3691,2747732.85 -spdlog,0,null,4,1024,10000,600,1373,18289,2235938.46 -spdlog,0,null,16,40,10000,380,686,17913,2782964.14 -spdlog,0,null,16,200,10000,398,706,2082,2564190.67 -spdlog,0,null,16,1024,10000,533,1062,11665,2606821.01 -spdlog,0,file,1,40,10000,273,541,906,2196497.82 -spdlog,0,file,1,200,10000,279,586,1183,1755113.88 -spdlog,0,file,1,1024,10000,473,1056,6362,810368.63 -spdlog,0,file,4,40,10000,348,706,11876,1776918.85 -spdlog,0,file,4,200,10000,365,861,17962,1304176.98 -spdlog,0,file,4,1024,10000,520,1326,8459,571419.27 -spdlog,0,file,16,40,10000,412,994,50616,1657493.27 -spdlog,0,file,16,200,10000,286,757,20477,1417268.51 -spdlog,0,file,16,1024,10000,466,1231,9489,653502.17 -spdlog,1,null,1,40,10000,7677,152389,183779,507180.79 -spdlog,1,null,1,200,10000,2169183,4708314,4762451,370023.78 -spdlog,1,null,1,1024,10000,84415,11790063,11899544,241879.85 -spdlog,1,null,4,40,10000,132194,511162,535193,870022.62 -spdlog,1,null,4,200,10000,1499973,2722962,2752323,913881.31 -spdlog,1,null,4,1024,10000,22604956,32839963,32878927,274923.01 -spdlog,1,null,16,40,10000,4699829,6306158,6603405,1115126.81 -spdlog,1,null,16,200,10000,4668421,6440606,6597072,1062143.13 -spdlog,1,null,16,1024,10000,38525338,42711383,44283213,234910.83 -spdlog,1,file,1,40,10000,347073,3865593,3918211,963829.32 -spdlog,1,file,1,200,10000,6276270,10251032,10333565,651659.22 -spdlog,1,file,1,1024,10000,55686311,112313139,113323355,79589.07 -spdlog,1,file,4,40,10000,2242665,3269778,3302128,1222780.30 -spdlog,1,file,4,200,10000,3999290,5321481,5391253,912398.77 -spdlog,1,file,4,1024,10000,37864894,46101563,46177514,206840.95 -spdlog,1,file,16,40,10000,2941855,3332657,4647595,1114334.14 -spdlog,1,file,16,200,10000,5490791,6395102,6666719,1418040.65 -spdlog,1,file,16,1024,10000,9481221,10600867,11288830,977566.03 diff --git a/bench/results/latency-2025-12-05-10k.csv b/bench/results/latency-2025-12-05-10k.csv new file mode 100644 index 0000000..c9730fa --- /dev/null +++ b/bench/results/latency-2025-12-05-10k.csv @@ -0,0 +1,73 @@ +lib,async,sink,producers,msg_bytes,total,p50_ns,p99_ns,p999_ns,throughput +log-it-cpp,0,null,1,40,10000,109,203,534,4488493.52 +log-it-cpp,0,null,1,200,10000,117,290,1856,3934122.33 +log-it-cpp,0,null,1,1024,10000,136,312,1682,3567715.60 +log-it-cpp,0,null,4,40,10000,126,15319,94404,2319369.26 +log-it-cpp,0,null,4,200,10000,119,10115,40355,2127704.39 +log-it-cpp,0,null,4,1024,10000,146,10216,214349,2264467.11 +log-it-cpp,0,null,16,40,10000,140,131580,415269,2075223.53 +log-it-cpp,0,null,16,200,10000,193,36615,743123,2497772.61 +log-it-cpp,0,null,16,1024,10000,266,85031,633668,2144621.71 +log-it-cpp,0,file,1,40,10000,121,269,650,2799664.15 +log-it-cpp,0,file,1,200,10000,124,275,716,2097587.75 +log-it-cpp,0,file,1,1024,10000,145,511,1795,733322.72 +log-it-cpp,0,file,4,40,10000,117,9900,65099,1772829.93 +log-it-cpp,0,file,4,200,10000,130,22075,57870,1035690.09 +log-it-cpp,0,file,4,1024,10000,157,13453,1667894,643976.12 +log-it-cpp,0,file,16,40,10000,115,187084,842912,1342559.94 +log-it-cpp,0,file,16,200,10000,124,50219,1626965,1170190.11 +log-it-cpp,0,file,16,1024,10000,148,25405,3726803,566942.69 +log-it-cpp,1,null,1,40,10000,1175705,1526236,1540248,3712975.14 +log-it-cpp,1,null,1,200,10000,1152097,1335974,1339469,2972361.79 +log-it-cpp,1,null,1,1024,10000,20462,1494584,1503929,2036432.59 +log-it-cpp,1,null,4,40,10000,34508,308989,365935,2045638.61 +log-it-cpp,1,null,4,200,10000,20916,358790,399458,1846272.01 +log-it-cpp,1,null,4,1024,10000,9452,84225,110180,1658989.97 +log-it-cpp,1,null,16,40,10000,87967,587563,1151351,1875460.43 +log-it-cpp,1,null,16,200,10000,48335,1089726,1625082,1658167.18 +log-it-cpp,1,null,16,1024,10000,1234551,2674805,2725920,1804776.59 +log-it-cpp,1,file,1,40,10000,140681,753198,801816,1276500.31 +log-it-cpp,1,file,1,200,10000,5528547,11105933,11150211,503674.86 +log-it-cpp,1,file,1,1024,10000,25137142,39518871,39564213,191725.46 +log-it-cpp,1,file,4,40,10000,12575,273737,297619,738323.52 +log-it-cpp,1,file,4,200,10000,255323,890675,928005,651384.49 +log-it-cpp,1,file,4,1024,10000,1850610,7115904,7159258,303040.58 +log-it-cpp,1,file,16,40,10000,33930,1867644,2345447,756677.49 +log-it-cpp,1,file,16,200,10000,426534,2357036,3358853,667634.56 +log-it-cpp,1,file,16,1024,10000,2311289,5436262,11175687,265718.63 +spdlog,0,null,1,40,10000,86,192,554,5899252.56 +spdlog,0,null,1,200,10000,86,186,1580,5248602.69 +spdlog,0,null,1,1024,10000,87,214,1454,5910437.95 +spdlog,0,null,4,40,10000,86,172,559,5993015.74 +spdlog,0,null,4,200,10000,86,255,684,5803783.37 +spdlog,0,null,4,1024,10000,117,326,1053,5736566.54 +spdlog,0,null,16,40,10000,222,499,2276,3577015.10 +spdlog,0,null,16,200,10000,196,477,8004,3662445.58 +spdlog,0,null,16,1024,10000,211,450,1543,3532033.78 +spdlog,0,file,1,40,10000,87,250,575,3814025.09 +spdlog,0,file,1,200,10000,86,312,565,2573591.20 +spdlog,0,file,1,1024,10000,86,265,623,897157.33 +spdlog,0,file,4,40,10000,133,454,24213,2011432.18 +spdlog,0,file,4,200,10000,87,408,662,1593986.97 +spdlog,0,file,4,1024,10000,98,384,937,657420.23 +spdlog,0,file,16,40,10000,97,579,11706,1837120.53 +spdlog,0,file,16,200,10000,87,391,2032,1478129.30 +spdlog,0,file,16,1024,10000,87,357,887,699514.86 +spdlog,1,null,1,40,10000,3349258,5502679,5526768,1111633.58 +spdlog,1,null,1,200,10000,2676022,4094926,4122755,1059325.96 +spdlog,1,null,1,1024,10000,10823100,19626164,19657067,396399.69 +spdlog,1,null,4,40,10000,4437322,5431100,5437782,1405912.54 +spdlog,1,null,4,200,10000,1248779,2945290,2948615,1303572.60 +spdlog,1,null,4,1024,10000,2442253,4282236,4361747,600106.64 +spdlog,1,null,16,40,10000,3974670,5709072,5902571,1266170.42 +spdlog,1,null,16,200,10000,2037113,3986478,4749528,1007207.27 +spdlog,1,null,16,1024,10000,12017018,15377451,15732828,547379.20 +spdlog,1,file,1,40,10000,5018086,5523521,5552618,870564.10 +spdlog,1,file,1,200,10000,6018301,7355055,7451697,1093601.82 +spdlog,1,file,1,1024,10000,41409771,63082440,63144317,168458.54 +spdlog,1,file,4,40,10000,4183717,5801144,5826400,1147332.00 +spdlog,1,file,4,200,10000,5001140,6010815,6026417,1153975.67 +spdlog,1,file,4,1024,10000,22969210,24002439,24456153,452730.62 +spdlog,1,file,16,40,10000,3597110,4807764,5038756,1086596.88 +spdlog,1,file,16,200,10000,4979452,5587979,5934658,1433801.53 +spdlog,1,file,16,1024,10000,13562553,14847888,15383562,654139.97 diff --git a/docs/mainpage.dox b/docs/mainpage.dox index a622f3e..66a62e0 100644 --- a/docs/mainpage.dox +++ b/docs/mainpage.dox @@ -684,46 +684,34 @@ All build-time toggles: Run `./build/bench/logit_bench` to capture the full matrix (sync/async × null/file × producer counts × message sizes). Results are appended to `bench/results/latency.csv` with one row per library/combination. Adjust the workload with `LOGIT_BENCH_TOTAL` and `LOGIT_BENCH_WARMUP` if you need a lighter pass. -\subsection bench_latest Latest snapshot (Dec 04, 2025) +The harness tracks end-to-end latency (*log call → sink delivery*) and throughput. It is great for regression hunting and pipeline design comparisons, but it is **not** a perfect “which logger is fastest” race. LogIt++ intentionally mirrors Python `icecream`: a single `LOGIT_*` call may parse argument names, build `args_array` with `VariableValue`, and optionally format those values. Many printf-style loggers (e.g., spdlog) optimize for lightweight formatting and queueing instead of this metadata path. Compare implementations inside the same mode: + +- *Text-only/passthrough* emphasizes dispatch/queue/sink cost and is closest to the spdlog default path. +- *Metadata-heavy* (`LOGIT_*` with argument capture) measures parsing and packing of structured arguments; LogIt++ does more per-call work here by design. + +Async results include enqueue + worker wakeup/scheduling + sink time. File sinks add variability from buffering and flush policy. + +\subsection bench_latest Latest snapshot (Dec 05, 2025) - Build: `Release`, `LOGIT_BENCH_ENABLE=ON`, `LOGIT_BENCH_WITH_SPDLOG=ON`, `LOGIT_USE_MPSC_RING=ON` (default). -- Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, 200-byte messages for the comparison table (see `bench/results/latency-2025-12-04-10k.csv` for other sizes/counts). +- Workload: `LOGIT_BENCH_TOTAL=10000`, 4 producers, 200-byte messages for the comparison table (see `bench/results/latency-2025-12-05-10k.csv` for other sizes/counts). - Metrics: median (`p50`) latency in nanoseconds and achieved throughput (messages/sec). - Hardware: 3 vCPU VM (Intel Xeon E5-2673 v4 @ 2.30GHz), single NUMA node. -- Data: refreshed from `bench/results/latency-2025-12-04-10k.csv` (Dec 04, 2025 @ 06:53 UTC). +- Data: refreshed from `bench/results/latency-2025-12-05-10k.csv` (Dec 05, 2025 @ 03:18 UTC). | Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | |------|------|-------------|--------------------|------------|-------------------| -| Sync | Null | 159 ns | 2,559,124 msg/s | 302 ns | 2,747,733 msg/s | -| Sync | File | 108 ns | 2,081,540 msg/s | 365 ns | 1,304,177 msg/s | -| Async | Null | 44,699 ns | 753,078 msg/s | 1,499,973 ns | 913,881 msg/s | -| Async | File | 996,466 ns | 850,021 msg/s | 3,999,290 ns | 912,399 msg/s | +| Sync | Null | 119 ns | 2,127,704 msg/s | 86 ns | 5,803,783 msg/s | +| Sync | File | 130 ns | 1,035,690 msg/s | 87 ns | 1,593,987 msg/s | +| Async | Null | 20,916 ns | 1,846,272 msg/s | 1,248,779 ns | 1,303,573 msg/s | +| Async | File | 255,323 ns | 651,384 msg/s | 5,001,140 ns | 1,153,976 msg/s | -**Takeaways:** In this snapshot both loggers deliver multi-million msg/s in synchronous modes; LogIt++ keeps the lower p50 while spdlog remains ahead in throughput for the null path and trails on the file sink. Asynchronously, LogIt++ holds end-to-end p50 in the tens–hundreds of microseconds while spdlog lands in the millisecond range; throughput for both clusters around 0.75–0.9M msg/s depending on sink. +**Takeaways:** LogIt++ keeps sub-microsecond p50s in synchronous modes while carrying the IceCream-style metadata path; spdlog’s lean formatting stays faster on the null/file sinks. Asynchronously, both numbers include enqueue + worker wakeups + sink work; LogIt++ stays in the tens-to-hundreds of microseconds, while the spdlog adapter lands in low-to-mid milliseconds for this run. -\subsection bench_harness Bench harness notes (LatencyRecorder & user_data) +\subsection bench_harness Benchmark context (LatencyRecorder) - `bench/LatencyRecorder.hpp` preallocates slots and tracks `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` with per-slot deduplication (duplicate `complete()` calls are ignored). It exposes `recorded()`, `wait_for_all()`, and `finalize()` for end-to-end timing across producers/consumers. -- `logit::LogRecord` includes an optional `user_data` field for opaque payloads (e.g., handing a benchmark token pointer to a sink instead of populating `args_array`). Leave it `0` for normal logging. The pointed storage must outlive the record until the sink consumes it. -- Example usage to pass a preallocated payload into the sink (storage lives for the entire run): - \code{.cpp} - struct BenchPayload { logit_bench::LatencyRecorder::Token token; }; - std::vector payloads(total_messages); - - // Producer - auto token = recorder.begin(true); - payloads[token.slot].token = token; - logit::LogRecord rec(level, LOGIT_CURRENT_TIMESTAMP_MS(), file, line, func, - preformatted_text, "", -1, false, false, - reinterpret_cast(&payloads[token.slot])); - Logger::get_instance().log(rec, preformatted_text); - - // Sink side - if (record.user_data) { - auto* p = reinterpret_cast(record.user_data); - recorder.complete(p->token); - } - \endcode +- The LogIt adapter stores the benchmark slot in `LogRecord::line` (see `bench/adapters/LogItAdapter.cpp`). Sinks call `LatencyRecorder::complete_slot()` when they observe a non-negative line number, so no extra payload is needed inside the log record. \subsection step5 Step 5: Build and Run Your Project diff --git a/include/logit_cpp/logit/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index 549e07d..573cf0f 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -158,35 +158,40 @@ namespace logit { /// \param record Log record to be logged. void log(const LogRecord& record) { if (m_shutdown) return; + const bool targeted = record.logger_index >= 0; + std::vector> snapshot; - { - 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; - } + snapshot.reserve(targeted ? 1 : 0); + + LoggerReadLock lock(m_loggers_mx); + if (targeted) { + if (record.logger_index < (int)m_loggers.size()) + snapshot.push_back(m_loggers[record.logger_index]); + } else { + snapshot = m_loggers; // copy shared_ptrs } + lock.unlock(); if (targeted) { if (snapshot.empty() || !snapshot[0]) return; auto& strategy = snapshot[0]; - if (!strategy->enabled) return; - if (static_cast(record.log_level) < static_cast(strategy->logger->get_log_level())) return; + std::lock_guard exec_lock(strategy->exec_mx); + if (!strategy->enabled) return; + if ((int)record.log_level < (int)strategy->logger->get_log_level()) return; dispatch_to_strategy(*strategy, record); return; } for (const auto& strategy : snapshot) { if (!strategy) continue; + + std::lock_guard exec_lock(strategy->exec_mx); if (strategy->single_mode) continue; if (!strategy->enabled) continue; - if (static_cast(record.log_level) < static_cast(strategy->logger->get_log_level())) continue; - std::lock_guard exec_lock(strategy->exec_mx); + if ((int)record.log_level < (int)strategy->logger->get_log_level()) continue; + dispatch_to_strategy(*strategy, record); } }