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/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..ee0abe3 --- /dev/null +++ b/bench/producer_profile.cpp @@ -0,0 +1,266 @@ +#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'); + +#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::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 + << " 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>(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..811980f 100644 --- a/docs/benchmarks.md +++ b/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