From a1346ddd6b0674f081fe59d95f85fbc89ed9eb01 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 3 Oct 2026 23:09:52 +0300 Subject: [PATCH 1/3] test(bench): profile LogIt producer path Add an isolated benchmark target that decomposes payload copying, LogRecord construction, logger dispatch, task admission, and the prepared asynchronous producer path. Document the workload contracts and keep production implementation unchanged. --- bench/CMakeLists.txt | 5 + bench/producer_profile.cpp | 259 +++++++++++++++++++++++++++++++++++++ docs/benchmarks.md | 35 +++++ 3 files changed, 299 insertions(+) create mode 100644 bench/producer_profile.cpp diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index e0a5cf7..de6221a 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -84,6 +84,11 @@ target_compile_definitions(logit_exec_mx_bench_concurrent PRIVATE LOGIT_BENCH_CO target_link_libraries(logit_exec_mx_bench_concurrent PRIVATE log-it-cpp::log-it-cpp) set_target_properties(logit_exec_mx_bench_concurrent PROPERTIES RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}) +add_executable(logit_producer_profile producer_profile.cpp) +target_compile_features(logit_producer_profile PRIVATE cxx_std_17) +target_link_libraries(logit_producer_profile PRIVATE log-it-cpp::log-it-cpp) +set_target_properties(logit_producer_profile PROPERTIES RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}) + add_executable(benchmark_validation_test benchmark_validation_test.cpp) target_compile_features(benchmark_validation_test PRIVATE cxx_std_17) set_target_properties(benchmark_validation_test PROPERTIES RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}) diff --git a/bench/producer_profile.cpp b/bench/producer_profile.cpp new file mode 100644 index 0000000..a914704 --- /dev/null +++ b/bench/producer_profile.cpp @@ -0,0 +1,259 @@ +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +namespace { + +constexpr std::size_t kDefaultTotal = 100000; +constexpr std::size_t kDefaultWarmup = 10000; +constexpr std::size_t kDefaultRepeats = 5; +constexpr std::size_t kQueueCapacity = 262144; +const std::string kMessage(200, 'x'); + +std::uint64_t g_observer = 0; + +std::size_t env_size(const char* name, std::size_t fallback) { + if (const char* value = std::getenv(name)) { + try { + return static_cast(std::stoull(value)); + } catch (...) { + } + } + return fallback; +} + +class PassthroughFormatter final : public logit::ILogFormatter { +public: + void set_timestamp_offset(std::int64_t) override {} + std::string format(const logit::LogRecord& record) const override { + return record.format; + } + bool is_passthrough() const noexcept override { return true; } +}; + +class ProfilingSink final : public logit::ILogger { +public: + enum class Mode { + Synchronous, + AsyncFullMessage, + }; + + void set_mode(Mode mode) { + wait(); + m_mode = mode; + reset_count(); + } + + void log(const logit::LogRecord&, const std::string& message) override { + if (m_mode == Mode::Synchronous) { + m_count.fetch_add(1, std::memory_order_relaxed); + return; + } + + std::string payload = message; + logit::detail::TaskExecutor::get_instance().add_task( + [this, payload = std::move(payload)]() mutable { + g_observer += payload.size(); + m_count.fetch_add(1, std::memory_order_relaxed); + }); + } + + std::string get_string_param(const logit::LoggerParam&) const override { return {}; } + std::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_mode == Mode::AsyncFullMessage) { + logit::detail::TaskExecutor::get_instance().wait(); + } + } + std::size_t count() const { return m_count.load(std::memory_order_acquire); } + void reset_count() { m_count.store(0, std::memory_order_relaxed); } + +private: + Mode m_mode = Mode::Synchronous; + std::atomic m_count{0}; + std::atomic m_level{static_cast(logit::LogLevel::LOG_LVL_TRACE)}; +}; + +using Loop = std::function; +using Cleanup = std::function; + +double median_ns_per_call(const Loop& loop, const Cleanup& cleanup, + std::size_t warmup, std::size_t total, + std::size_t repeats) { + loop(warmup); + cleanup(warmup); + + std::vector samples; + samples.reserve(repeats); + for (std::size_t repeat = 0; repeat < repeats; ++repeat) { + const auto start = std::chrono::steady_clock::now(); + loop(total); + const auto elapsed = std::chrono::duration_cast( + std::chrono::steady_clock::now() - start).count(); + cleanup(total); + samples.push_back(static_cast(elapsed)); + } + + std::sort(samples.begin(), samples.end()); + return static_cast(samples[samples.size() / 2]) / + static_cast(total); +} + +logit::LogRecord make_record() { + return logit::LogRecord( + logit::LogLevel::LOG_LVL_INFO, + 0, + std::string(), + -1, + std::string(), + kMessage, + std::string(), + -1, + false, + false); +} + +} // namespace + +int main() { + const std::size_t total = env_size("LOGIT_PRODUCER_PROFILE_TOTAL", kDefaultTotal); + const std::size_t warmup = env_size("LOGIT_PRODUCER_PROFILE_WARMUP", kDefaultWarmup); + const std::size_t repeats = env_size("LOGIT_PRODUCER_PROFILE_REPEATS", kDefaultRepeats); + if (total == 0 || repeats == 0) { + std::cerr << "total and repeats must be positive\n"; + return 2; + } + + auto& executor = logit::detail::TaskExecutor::get_instance(); + executor.set_queue_policy(logit::QueuePolicy::Block); + executor.set_max_queue_size(kQueueCapacity); + + auto sink = std::make_unique(); + auto* sink_ptr = sink.get(); + auto& logger = logit::Logger::get_instance(); + logger.add_logger(std::move(sink), std::make_unique()); + + const logit::LogRecord prepared = make_record(); + const auto log_prepared = [&logger, &prepared](std::size_t count) { + for (std::size_t i = 0; i < count; ++i) { + logger.log(prepared); + } + }; + + std::cout << "producer-profile total=" << total + << " warmup=" << warmup + << " repeats=" << repeats + << " message_bytes=" << kMessage.size() + << " queue_capacity=" << kQueueCapacity << '\n'; + + const double copy_ns = median_ns_per_call( + [](std::size_t count) { + for (std::size_t i = 0; i < count; ++i) { + std::string copy = kMessage; + g_observer += copy.size(); + } + }, + [](std::size_t) {}, warmup, total, repeats); + std::cout << "case=string_copy_only ns_per_call=" << copy_ns << '\n'; + + const double record_ns = median_ns_per_call( + [](std::size_t count) { + for (std::size_t i = 0; i < count; ++i) { + const auto record = make_record(); + g_observer += record.format.size(); + } + }, + [](std::size_t) {}, warmup, total, repeats); + std::cout << "case=logrecord_construct ns_per_call=" << record_ns << '\n'; + + sink_ptr->set_mode(ProfilingSink::Mode::Synchronous); + const double sync_ns = median_ns_per_call( + log_prepared, + [&logger, sink_ptr](std::size_t expected) { + logger.wait(); + if (sink_ptr->count() != expected) { + std::cerr << "sync sink count mismatch\n"; + std::exit(3); + } + sink_ptr->reset_count(); + }, + warmup, total, repeats); + std::cout << "case=logger_log_sync_null ns_per_call=" << sync_ns << '\n'; + + sink_ptr->set_mode(ProfilingSink::Mode::AsyncFullMessage); + auto task_completed = std::make_shared>(0); + const double enqueue_ns = median_ns_per_call( + [task_completed](std::size_t count) { + auto& task_executor = logit::detail::TaskExecutor::get_instance(); + for (std::size_t i = 0; i < count; ++i) { + task_executor.add_task([task_completed]() { + task_completed->fetch_add(1, std::memory_order_relaxed); + }); + } + }, + [task_completed](std::size_t expected) { + logit::detail::TaskExecutor::get_instance().wait(); + const auto completed = task_completed->load(std::memory_order_relaxed); + if (completed != expected) { + std::cerr << "TaskExecutor completion mismatch\n"; + std::exit(6); + } + g_observer += completed; + task_completed->store(0, std::memory_order_relaxed); + }, warmup, total, repeats); + std::cout << "case=taskexecutor_enqueue_noop ns_per_call=" << enqueue_ns << '\n'; + + const double async_prepared_ns = median_ns_per_call( + log_prepared, + [&logger, sink_ptr](std::size_t expected) { + logger.wait(); + if (sink_ptr->count() != expected) { + std::cerr << "async sink count mismatch\n"; + std::exit(4); + } + sink_ptr->reset_count(); + }, + warmup, total, repeats); + std::cout << "case=logger_log_async_full_prepared ns_per_call=" + << async_prepared_ns << '\n'; + + const double full_path_ns = median_ns_per_call( + [&logger](std::size_t count) { + for (std::size_t i = 0; i < count; ++i) { + auto record = make_record(); + logger.log(record); + } + }, + [&logger, sink_ptr](std::size_t expected) { + logger.wait(); + if (sink_ptr->count() != expected) { + std::cerr << "full producer path count mismatch\n"; + std::exit(5); + } + sink_ptr->reset_count(); + }, + warmup, total, repeats); + std::cout << "case=prepared_record_plus_logger_async_full ns_per_call=" + << full_path_ns << '\n'; + + std::cout << "observer=" << g_observer << '\n'; + return 0; +} diff --git a/docs/benchmarks.md b/docs/benchmarks.md index 5696d86..6aa58a7 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -247,6 +247,41 @@ custom formatters and backends are not assumed to be safe for concurrent invocation. Any future lock-elision experiment must advertise and test an explicit concurrency contract rather than infer one from a benchmark sink. +## Producer path profiling + +`logit_producer_profile` is a benchmark-only decomposition of the prepared +LogIt++ producer path. It does not change library code and does not compare +against another logging library. The cases are intentionally cumulative: + +- `string_copy_only` measures copying the prepared 200-byte payload; +- `logrecord_construct` measures construction of the same `LogRecord` shape + used by `LogItAdapter`; +- `logger_log_sync_null` measures dispatch of a prepared record to a synchronous + counting sink; +- `taskexecutor_enqueue_noop` measures direct MPSC task admission with a no-op + completion task; +- `logger_log_async_full_prepared` measures prepared-record dispatch plus full + message task admission; +- `prepared_record_plus_logger_async_full` adds per-call `LogRecord` + construction to the previous asynchronous path. + +The reported `ns_per_call` values are medians over independent repeats. Async +cases time only the producer loop; their drain barrier runs after the timed +region and verifies that every task was consumed. These are attribution probes, +not intrinsic latency claims: cases differ in allocation and ownership work, +and the direct queue case is not a public API contract. Configure the run with +`LOGIT_PRODUCER_PROFILE_TOTAL`, `LOGIT_PRODUCER_PROFILE_WARMUP`, and +`LOGIT_PRODUCER_PROFILE_REPEATS`. + +For example: + +```powershell +$env:LOGIT_PRODUCER_PROFILE_TOTAL = "200000" +$env:LOGIT_PRODUCER_PROFILE_WARMUP = "10000" +$env:LOGIT_PRODUCER_PROFILE_REPEATS = "5" +./build/logit_producer_profile +``` + The flush regression target uses an intentionally delayed asynchronous sink and asserts that `flush()` does not return before every queued message has reached that sink. The fixture records latency completion and the flush barrier as From 5f361f74c47125ec07edc24a618caecc9f6fdc2e Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 3 Oct 2026 23:47:25 +0300 Subject: [PATCH 2/3] test(bench): cover producer profile smoke Build and run the producer profiling target in the Linux C++17 benchmark job, report the selected TaskExecutor backend, and document that the measurements are overlapping attribution probes rather than additive component costs. --- .github/workflows/ci.yml | 9 ++++++++- bench/producer_profile.cpp | 9 ++++++++- docs/benchmarks.md | 15 ++++++++++----- 3 files changed, 26 insertions(+), 7 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b682160..d2d5f69 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -30,7 +30,7 @@ jobs: run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -DCMAKE_BUILD_TYPE=Release -DCMAKE_CXX_STANDARD=${{ matrix.std }} -DLOGIT_WITH_SYSLOG=ON -DLOGIT_WITH_WIN_EVENT_LOG=OFF - name: Build benchmarks # if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} - run: cmake --build build-bench --target logit_bench logit_bench_async_contract logit_bench_async_payload_contract_test logit_bench_flush_test logit_bench_pipeline_research logit_public_macro_bench logit_public_macro_formatted_bench logit_hotpath_bench logit_hotpath_bench_legacy logit_exec_mx_bench logit_exec_mx_bench_concurrent benchmark_validation_test + run: cmake --build build-bench --target logit_bench logit_bench_async_contract logit_bench_async_payload_contract_test logit_bench_flush_test logit_bench_pipeline_research logit_public_macro_bench logit_public_macro_formatted_bench logit_hotpath_bench logit_hotpath_bench_legacy logit_exec_mx_bench logit_exec_mx_bench_concurrent logit_producer_profile benchmark_validation_test - name: Run spdlog async flush regression run: ./build-bench/logit_bench_flush_test - name: Run public macro benchmark smoke @@ -47,6 +47,13 @@ jobs: run: ./build-bench/logit_public_macro_formatted_bench - name: Run benchmark validation tests run: ./build-bench/benchmark_validation_test + - name: Run producer profiling smoke + if: matrix.std == 17 + env: + LOGIT_PRODUCER_PROFILE_TOTAL: 2000 + LOGIT_PRODUCER_PROFILE_WARMUP: 200 + LOGIT_PRODUCER_PROFILE_REPEATS: 1 + run: ./build-bench/logit_producer_profile - name: Run async payload contract regression run: ./build-bench/logit_bench_async_payload_contract_test - name: Run logger hot-path A/B smoke diff --git a/bench/producer_profile.cpp b/bench/producer_profile.cpp index a914704..ee0abe3 100644 --- a/bench/producer_profile.cpp +++ b/bench/producer_profile.cpp @@ -21,6 +21,12 @@ constexpr std::size_t kDefaultRepeats = 5; constexpr std::size_t kQueueCapacity = 262144; const std::string kMessage(200, 'x'); +#if defined(LOGIT_USE_MPSC_RING) +constexpr const char* kQueueBackend = "mpsc_ring"; +#else +constexpr const char* kQueueBackend = "mutex_deque"; +#endif + std::uint64_t g_observer = 0; std::size_t env_size(const char* name, std::size_t fallback) { @@ -162,7 +168,8 @@ int main() { << " warmup=" << warmup << " repeats=" << repeats << " message_bytes=" << kMessage.size() - << " queue_capacity=" << kQueueCapacity << '\n'; + << " queue_capacity=" << kQueueCapacity + << " queue_backend=" << kQueueBackend << '\n'; const double copy_ns = median_ns_per_call( [](std::size_t count) { diff --git a/docs/benchmarks.md b/docs/benchmarks.md index 6aa58a7..5bfae0e 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -249,9 +249,10 @@ explicit concurrency contract rather than infer one from a benchmark sink. ## Producer path profiling -`logit_producer_profile` is a benchmark-only decomposition of the prepared -LogIt++ producer path. It does not change library code and does not compare -against another logging library. The cases are intentionally cumulative: +`logit_producer_profile` is a benchmark-only set of overlapping attribution +probes for the prepared LogIt++ producer path. It does not change library code +and does not compare against another logging library. The cases intentionally +overlap rather than form an additive decomposition: - `string_copy_only` measures copying the prepared 200-byte payload; - `logrecord_construct` measures construction of the same `LogRecord` shape @@ -268,8 +269,12 @@ against another logging library. The cases are intentionally cumulative: The reported `ns_per_call` values are medians over independent repeats. Async cases time only the producer loop; their drain barrier runs after the timed region and verifies that every task was consumed. These are attribution probes, -not intrinsic latency claims: cases differ in allocation and ownership work, -and the direct queue case is not a public API contract. Configure the run with +not intrinsic latency claims: cases differ in allocation, ownership, allocator, +worker, and queue state. Do not sum the rows or treat subtraction between rows +as an exact component cost; differences are exploratory signals only. The +direct queue case is not a public API contract. The header reports +`queue_backend=mpsc_ring` or `queue_backend=mutex_deque`, depending on the +compile-time executor configuration. Configure the run with `LOGIT_PRODUCER_PROFILE_TOTAL`, `LOGIT_PRODUCER_PROFILE_WARMUP`, and `LOGIT_PRODUCER_PROFILE_REPEATS`. From 70ff915ba1013f8a01cb320a29479051dd201e81 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sun, 4 Oct 2026 00:21:23 +0300 Subject: [PATCH 3/3] docs(bench): generalize executor admission wording Describe the producer profiling queue probe independently of the selected TaskExecutor backend so mutex-deque builds remain accurately documented. --- docs/benchmarks.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/benchmarks.md b/docs/benchmarks.md index 5bfae0e..811980f 100644 --- a/docs/benchmarks.md +++ b/docs/benchmarks.md @@ -259,7 +259,7 @@ overlap rather than form an additive decomposition: used by `LogItAdapter`; - `logger_log_sync_null` measures dispatch of a prepared record to a synchronous counting sink; -- `taskexecutor_enqueue_noop` measures direct MPSC task admission with a no-op +- `taskexecutor_enqueue_noop` measures direct `TaskExecutor` task admission with a no-op completion task; - `logger_log_async_full_prepared` measures prepared-record dispatch plus full message task admission;