diff --git a/README-RU.md b/README-RU.md index 12073c5..34c33ad 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,58 @@ 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`. + +### Что на самом деле измеряет бенчмарк + +Харнесс меряет 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-05-10k.csv`). +- Метрики: медианная задержка (`p50`) в наносекундах и достигнутая пропускная способность (сообщений/с). +- Железо: 3 vCPU (Intel Xeon E5-2673 v4 @ 2.30GHz) в виртуальной машине, одна NUMA-нода. +- Данные: обновлено по `bench/results/latency-2025-12-05-10k.csv` (05.12.2025, 03:18 UTC). + +| Режим | Приёмник | LogIt++ p50 | Пропускная (LogIt++) | spdlog p50 | Пропускная (spdlog) | +|-------|----------|-------------|----------------------|------------|---------------------| +| 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++ держит sub-µs p50 в синхронных режимах, даже с путём метаданных в стиле IceCream; spdlog выигрывает по скорости на null/file за счёт более лёгкого форматирования. В async обе стороны включают enqueue + пробуждения + sink: LogIt++ остаётся в десятках–сотнях микросекунд, тогда как адаптер spdlog в этой конфигурации уходит в миллисекунды. + +### Как устроен бенч-харнесс (LatencyRecorder) + +- `bench/LatencyRecorder.hpp` заранее резервирует слоты и ведёт `Token {slot, t0_ns, active}` → `Summary {p50, p99, p999}` с защитой от повторных `complete()` на один слот. Доступны методы `recorded()`, `wait_for_all()` и `finalize()` для end-to-end измерений между продюсерами и консюмером. +- Адаптер LogIt кладёт номер слота в `LogRecord::line` (см. `bench/adapters/LogItAdapter.cpp`). Приёмник вызывает `LatencyRecorder::complete_slot()`, когда видит неотрицательный номер строки; никаких дополнительных полей в записи не требуется. + + ## Системные бэкенды LogIt++ может отправлять сообщения в системные журналы. diff --git a/README.md b/README.md index 6c48578..ad2e872 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,50 @@ 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. +### 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-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-05-10k.csv` (Dec 05, 2025 @ 03:18 UTC). + +| Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | +|------|------|-------------|--------------------|------------|-------------------| +| 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. + + --- ## Documentation diff --git a/bench/LatencyRecorder.hpp b/bench/LatencyRecorder.hpp index a9b65b5..de990d4 100644 --- a/bench/LatencyRecorder.hpp +++ b/bench/LatencyRecorder.hpp @@ -13,111 +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) {} - /** - * 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; - 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(); + + /// 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::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"); + + /** + * 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); } - 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; - mutable std::condition_variable m_wait_cv; - mutable std::mutex m_wait_mx; -}; + + std::size_t recorded() const { + return m_next_slot.load(std::memory_order_relaxed); + } + + std::size_t completed() const { + return m_completed.load(std::memory_order_acquire); + } + + 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 diff --git a/bench/adapters/LogItAdapter.cpp b/bench/adapters/LogItAdapter.cpp index 7ddd835..d9dd191 100644 --- a/bench/adapters/LogItAdapter.cpp +++ b/bench/adapters/LogItAdapter.cpp @@ -3,6 +3,7 @@ #include #include #include +#include #include #include #include @@ -10,201 +11,199 @@ #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; - } -}; - -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(); + } } - 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(); + + 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); + }); } - std::lock_guard lock(m_file_mutex); - if (m_file.is_open()) { - m_file.flush(); + + 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); } - } - -private: - struct AsyncPayload { - LatencyRecorder::Token token; - std::string text; + + 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::lock_guard lock(m_file_mutex); + if (m_file.is_open()) { + m_file.flush(); + } + } + + 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'; + } + } + } + + 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)}; }; - - static LatencyRecorder::Token extract(const logit::LogRecord& record) { - LatencyRecorder::Token token; - if (record.args_array.size() <= kActiveIndex) { - return token; + + 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)); } - 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; + + void prepare(const Scenario& scenario, LatencyRecorder& recorder) { + if (sink) { + sink->configure(scenario, recorder); + } } - return 0; - } - - void consume(const LatencyRecorder::Token& token, std::string_view text) { - if (token.active && m_recorder) { - m_recorder->complete(token); + + 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); } - if (m_sink == SinkKind::File) { - std::lock_guard lock(m_file_mutex); - if (m_file.is_open()) { - m_file << text << '\n'; + + void flush() { + if (sink) { + sink->wait(); } } - } - - 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); + + 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); } } - - 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(), - -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)); - 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; -}; - -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 diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp index e1ab0f3..d0bd26a 100644 --- a/bench/adapters/SpdlogAdapter.cpp +++ b/bench/adapters/SpdlogAdapter.cpp @@ -3,15 +3,14 @@ #ifdef LOGIT_BENCH_HAVE_SPDLOG #include -#include -#include +#include #include #include +#include #include #include #include #include -#include #include #include @@ -19,204 +18,140 @@ #include 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; -}; -} // namespace - -class SpdlogAdapter::MeasuringSink : public spdlog::sinks::sink { -public: - MeasuringSink() = default; - - void configure(const Scenario& scenario, LatencyRecorder& 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; - } - 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 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. - } - - 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(); - } - } - - 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; - } - - 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)); + 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(); } } - m_retired.insert(m_retired.end(), - std::make_move_iterator(retired.begin()), - std::make_move_iterator(retired.end())); - } - -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 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'; + } } } - - const MessagePayload& msg = owned ? *owned : payload; - - 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) { + + 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 << msg.text << '\n'; + m_file.flush(); } } - } - - SinkKind m_sink = SinkKind::Null; - LatencyRecorder* m_recorder = nullptr; - std::ofstream m_file; - std::mutex m_mutex; - struct Pending { - std::unique_ptr payload; - LatencyRecorder::Token token; + + private: + SinkKind m_sink = SinkKind::Null; + std::shared_ptr m_recorder; + + std::ofstream m_file; + std::mutex m_mutex; }; - 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; - -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(); - m_sink->configure(scenario, recorder); - 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); + + SpdlogAdapter::SpdlogAdapter() = default; + + SpdlogAdapter::~SpdlogAdapter() { + flush(); + spdlog::shutdown(); } -} - -void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { - if (!m_logger) { - return; + + void SpdlogAdapter::set_recorder_handle(std::shared_ptr recorder) { + m_recorder_handle = std::move(recorder); } - auto payload = std::make_unique(); - 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)); + + 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); + } } - spdlog::source_loc loc{nullptr, 0, reinterpret_cast(payload_ptr)}; - m_logger->log(loc, spdlog::level::info, spdlog::string_view_t(payload_ptr->text)); -} - -void SpdlogAdapter::flush() { - if (m_logger) { - m_logger->flush(); + + void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { + if (!m_logger) return; + + 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"}; + + m_logger->log( + loc, + spdlog::level::info, + spdlog::string_view_t(message.data(), message.size())); } - if (m_sink) { - m_sink->complete_pending(); - m_sink->flush(); + + void SpdlogAdapter::flush() { + if (m_logger) { + m_logger->flush(); + } + if (m_sink) { + m_sink->flush(); + } } -} } // namespace logit_bench 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 c8b565e..66a62e0 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,55 @@ 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. + +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-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-05-10k.csv` (Dec 05, 2025 @ 03:18 UTC). + +| Mode | Sink | LogIt++ p50 | LogIt++ throughput | spdlog p50 | spdlog throughput | +|------|------|-------------|--------------------|------------|-------------------| +| 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. + +\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. +- 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 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/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index 0120b14..573cf0f 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -14,8 +14,25 @@ #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. /// @@ -43,13 +60,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; + + LoggerWriteLock lock(m_loggers_mx); + m_loggers.push_back(std::move(strategy)); } /// \brief Enables or disables a logger by index. @@ -57,9 +75,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; + 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; } } @@ -67,9 +85,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; + LoggerReadLock lock(m_loggers_mx); + if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { + return m_loggers[logger_index]->enabled; } return false; } @@ -79,9 +97,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; + 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; } } @@ -90,9 +108,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); + 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); } } @@ -100,9 +119,11 @@ namespace logit { /// \param level Minimum log level. void set_log_level(LogLevel level) { if (m_shutdown) return; - std::lock_guard lock(m_mutex); + LoggerReadLock 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 +132,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); + 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); } } @@ -122,9 +144,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; + LoggerReadLock lock(m_loggers_mx); + if (logger_index >= 0 && logger_index < static_cast(m_loggers.size()) && m_loggers[logger_index]) { + return m_loggers[logger_index]->single_mode; } return false; } @@ -136,20 +158,41 @@ 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; - strategy.logger->log(record, strategy.formatter->format(record)); + + const bool targeted = record.logger_index >= 0; + + std::vector> snapshot; + snapshot.reserve(targeted ? 1 : 0); + + LoggerReadLock lock(m_loggers_mx); + if (targeted) { + if (record.logger_index < (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]; + + 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 : 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)); + + 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 ((int)record.log_level < (int)strategy->logger->get_log_level()) continue; + + dispatch_to_strategy(*strategy, record); } } @@ -159,9 +202,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())) { + 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); + return strategy->logger->get_string_param(param); } return std::string(); } @@ -172,9 +216,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())) { + 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); + return strategy->logger->get_int_param(param); } return 0; } @@ -185,9 +230,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())) { + 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); + return strategy->logger->get_float_param(param); } return 0.0; } @@ -228,8 +274,10 @@ namespace logit { /// /// Ensures that all log messages are fully processed before continuing. void wait() { + LoggerReadLock lock(m_loggers_mx); for (const auto& strategy : m_loggers) { - strategy.logger->wait(); + if (!strategy) continue; + strategy->logger->wait(); } } @@ -251,12 +299,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 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) { @@ -278,10 +336,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 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 diff --git a/include/logit_cpp/logit/utils/LogRecord.hpp b/include/logit_cpp/logit/utils/LogRecord.hpp index be65e1a..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.