test(bench): profile LogIt producer path

.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

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})

bench/producer_profile.cpp

@@ -0,0 +1,266 @@
+#include <algorithm>
+#include <atomic>
+#include <chrono>
+#include <cstddef>
+#include <cstdint>
+#include <cstdlib>
+#include <functional>
+#include <iostream>
+#include <memory>
+#include <string>
+#include <thread>
+#include <vector>
+
+#include <logit.hpp>
+
+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');
+
+#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) {
+    if (const char* value = std::getenv(name)) {
+        try {
+            return static_cast<std::size_t>(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<int>(level), std::memory_order_relaxed);
+    }
+    logit::LogLevel get_log_level() const override {
+        return static_cast<logit::LogLevel>(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<std::size_t> m_count{0};
+    std::atomic<int> m_level{static_cast<int>(logit::LogLevel::LOG_LVL_TRACE)};
+};
+
+using Loop = std::function<void(std::size_t)>;
+using Cleanup = std::function<void(std::size_t)>;
+
+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<std::uint64_t> 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::nanoseconds>(
+            std::chrono::steady_clock::now() - start).count();
+        cleanup(total);
+        samples.push_back(static_cast<std::uint64_t>(elapsed));
+    }
+
+    std::sort(samples.begin(), samples.end());
+    return static_cast<double>(samples[samples.size() / 2]) /
+           static_cast<double>(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<ProfilingSink>();
+    auto* sink_ptr = sink.get();
+    auto& logger = logit::Logger::get_instance();
+    logger.add_logger(std::move(sink), std::make_unique<PassthroughFormatter>());
+
+    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
+              << " queue_backend=" << kQueueBackend << '\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<std::atomic<std::size_t>>(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;
+}

docs/benchmarks.md

@@ -247,6 +247,46 @@ 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 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
+  used by `LogItAdapter`;
+- `logger_log_sync_null` measures dispatch of a prepared record to a synchronous
+  counting sink;
+- `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;
+- `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, 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`.
+
+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