From 1aeeb10277d3825fc2980fb0d728b9266385a197 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 18 Sep 2025 06:36:45 +0300 Subject: [PATCH 01/17] feat(bench): add latency benchmarks Add benchmark harness with adapters for log-it-cpp and spdlog, integrate build options, and document usage. --- CMakeLists.txt | 6 + README.md | 13 ++ bench/CMakeLists.txt | 29 ++++ bench/LatencyRecorder.hpp | 102 ++++++++++++++ bench/Scenario.hpp | 31 +++++ bench/adapters/ILoggerAdapter.hpp | 23 +++ bench/adapters/LogItAdapter.cpp | 210 ++++++++++++++++++++++++++++ bench/adapters/LogItAdapter.hpp | 28 ++++ bench/adapters/SpdlogAdapter.cpp | 144 +++++++++++++++++++ bench/adapters/SpdlogAdapter.hpp | 37 +++++ bench/main.cpp | 224 ++++++++++++++++++++++++++++++ bench/results/.gitignore | 1 + 12 files changed, 848 insertions(+) create mode 100644 bench/CMakeLists.txt create mode 100644 bench/LatencyRecorder.hpp create mode 100644 bench/Scenario.hpp create mode 100644 bench/adapters/ILoggerAdapter.hpp create mode 100644 bench/adapters/LogItAdapter.cpp create mode 100644 bench/adapters/LogItAdapter.hpp create mode 100644 bench/adapters/SpdlogAdapter.cpp create mode 100644 bench/adapters/SpdlogAdapter.hpp create mode 100644 bench/main.cpp create mode 100644 bench/results/.gitignore diff --git a/CMakeLists.txt b/CMakeLists.txt index 8ba99e4..6975864 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -3,6 +3,8 @@ project(log-it-cpp VERSION 1.0.0 LANGUAGES CXX) option(LOGIT_CPP_BUILD_TESTS "Build log-it-cpp tests" ${PROJECT_IS_TOP_LEVEL}) option(LOGIT_CPP_BUILD_EXAMPLES "Build log-it-cpp examples" OFF) +option(LOGIT_BENCH_ENABLE "Build log-it-cpp benchmarks" OFF) +option(LOGIT_BENCH_WITH_SPDLOG "Enable spdlog comparison benchmarks" OFF) option(LOGIT_WITH_GZIP "Enable gzip via zlib" OFF) option(LOGIT_WITH_ZSTD "Enable zstd" OFF) option(LOGIT_WITH_FMT "Enable fmt support" OFF) @@ -140,6 +142,10 @@ if(LOGIT_CPP_BUILD_EXAMPLES) add_subdirectory(examples) endif() +if(LOGIT_BENCH_ENABLE) + add_subdirectory(bench) +endif() + include(CMakePackageConfigHelpers) install(DIRECTORY include/ DESTINATION include) diff --git a/README.md b/README.md index d6b054b..e6d4f5a 100644 --- a/README.md +++ b/README.md @@ -736,6 +736,19 @@ When building with Emscripten the library runs without threads. Console logging works as usual while file-based loggers are replaced by stubs that warn when used. +## Benchmarks + +Latency and throughput benchmarks live under `bench/`. Enable them during configuration and optionally pull in the spdlog +adapters: + +```bash +cmake -S . -B build -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON +cmake --build build --target logit_bench +``` + +Run the executable to record 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. + --- ## Documentation diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt new file mode 100644 index 0000000..91348a2 --- /dev/null +++ b/bench/CMakeLists.txt @@ -0,0 +1,29 @@ +set(LOGIT_BENCH_SOURCES + main.cpp + adapters/LogItAdapter.cpp +) + +if(LOGIT_BENCH_WITH_SPDLOG) + list(APPEND LOGIT_BENCH_SOURCES adapters/SpdlogAdapter.cpp) +endif() + +add_executable(logit_bench ${LOGIT_BENCH_SOURCES}) + +target_include_directories(logit_bench PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}) + +target_compile_features(logit_bench PRIVATE cxx_std_17) + +target_link_libraries(logit_bench PRIVATE log-it-cpp::log-it-cpp) + +if(LOGIT_BENCH_WITH_SPDLOG) + target_compile_definitions(logit_bench PRIVATE LOGIT_BENCH_HAVE_SPDLOG=1) + if(NOT TARGET spdlog::spdlog) + include(FetchContent) + FetchContent_Declare(spdlog + GIT_REPOSITORY https://github.com/gabime/spdlog.git + GIT_TAG v1.12.0 + ) + FetchContent_MakeAvailable(spdlog) + endif() + target_link_libraries(logit_bench PRIVATE spdlog::spdlog) +endif() diff --git a/bench/LatencyRecorder.hpp b/bench/LatencyRecorder.hpp new file mode 100644 index 0000000..c735d7d --- /dev/null +++ b/bench/LatencyRecorder.hpp @@ -0,0 +1,102 @@ +#pragma once + +#include +#include +#include +#include +#include +#include +#include + +namespace logit_bench { + +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) {} + + Token begin(bool record) { + Token token; + token.active = record; + token.t0_ns = now(); + if (record) { + 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); + } + return token; + } + + void complete(const Token& token) { + if (!token.active) { + return; + } + const auto t1_ns = now(); + m_values[token.slot] = t1_ns - token.t0_ns; + } + + std::size_t recorded() const { + return m_next_slot.load(std::memory_order_relaxed); + } + + Summary finalize() const { + if (recorded() != 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 now_tp = std::chrono::steady_clock::now().time_since_epoch(); + return std::chrono::duration_cast(now_tp).count(); + } + +private: + static std::uint64_t pick(const std::vector& data, double percentile) { + if (data.empty()) { + return 0; + } + const double rank = percentile * static_cast(data.size()); + std::size_t index = static_cast(rank); + if (static_cast(index) < rank) { + index += 1; + } + if (index == 0) { + index = 1; + } + const std::size_t pos = std::min(index - 1, data.size() - 1); + return data[pos]; + } + + std::vector m_values; + const std::size_t m_expected; + std::atomic m_next_slot; +}; + +} // namespace logit_bench diff --git a/bench/Scenario.hpp b/bench/Scenario.hpp new file mode 100644 index 0000000..7bc0d37 --- /dev/null +++ b/bench/Scenario.hpp @@ -0,0 +1,31 @@ +#pragma once + +#include +#include + +namespace logit_bench { + +enum class SinkKind { + Null, + File, +}; + +inline std::string sink_name(SinkKind sink) { + switch (sink) { + case SinkKind::Null: + return "null"; + case SinkKind::File: + return "file"; + } + return "unknown"; +} + +struct Scenario { + bool async = false; + SinkKind sink = SinkKind::Null; + std::size_t producers = 1; + std::size_t message_bytes = 0; + std::size_t total_messages = 0; +}; + +} // namespace logit_bench diff --git a/bench/adapters/ILoggerAdapter.hpp b/bench/adapters/ILoggerAdapter.hpp new file mode 100644 index 0000000..508a4ad --- /dev/null +++ b/bench/adapters/ILoggerAdapter.hpp @@ -0,0 +1,23 @@ +#pragma once + +#include + +#include "../LatencyRecorder.hpp" +#include "../Scenario.hpp" + +namespace logit_bench { + +class ILoggerAdapter { +public: + virtual ~ILoggerAdapter() = default; + + virtual const char* library_name() const = 0; + + virtual void prepare(const Scenario& scenario, LatencyRecorder& recorder) = 0; + + virtual void log(const LatencyRecorder::Token& token, std::string_view message) = 0; + + virtual void flush() = 0; +}; + +} // namespace logit_bench diff --git a/bench/adapters/LogItAdapter.cpp b/bench/adapters/LogItAdapter.cpp new file mode 100644 index 0000000..7ddd835 --- /dev/null +++ b/bench/adapters/LogItAdapter.cpp @@ -0,0 +1,210 @@ +#include "LogItAdapter.hpp" + +#include +#include +#include +#include +#include +#include + +#include + +namespace logit_bench { +namespace { +constexpr const char* kFilePath = "bench/results/logit_sink.log"; +constexpr std::size_t kSlotIndex = 0; +constexpr std::size_t kT0Index = 1; +constexpr std::size_t kActiveIndex = 2; +} // namespace + +class PassthroughFormatter : public logit::ILogFormatter { +public: + void set_timestamp_offset(int64_t) override {} + + std::string format(const logit::LogRecord& record) const override { + return record.format; + } +}; + +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(); + } + } + + void log(const logit::LogRecord& record, const std::string& message) override { + LatencyRecorder::Token token = extract(record); + if (!m_async) { + consume(token, message); + return; + } + AsyncPayload payload; + payload.token = token; + payload.text = message; + logit::detail::TaskExecutor::get_instance().add_task([this, payload = std::move(payload)]() mutable { + consume(payload.token, payload.text); + }); + } + + std::string get_string_param(const logit::LoggerParam&) const override { return std::string(); } + int64_t get_int_param(const logit::LoggerParam&) const override { return 0; } + double get_float_param(const logit::LoggerParam&) const override { return 0.0; } + + void set_log_level(logit::LogLevel level) override { + m_level.store(static_cast(level), std::memory_order_relaxed); + } + + logit::LogLevel get_log_level() const override { + return static_cast(m_level.load(std::memory_order_relaxed)); + } + + void wait() override { + if (m_async) { + logit::detail::TaskExecutor::get_instance().wait(); + } + std::lock_guard lock(m_file_mutex); + if (m_file.is_open()) { + m_file.flush(); + } + } + +private: + struct AsyncPayload { + LatencyRecorder::Token token; + std::string text; + }; + + static LatencyRecorder::Token extract(const logit::LogRecord& record) { + LatencyRecorder::Token token; + if (record.args_array.size() <= kActiveIndex) { + return token; + } + 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; + } + return 0; + } + + void consume(const LatencyRecorder::Token& token, std::string_view text) { + if (token.active && m_recorder) { + m_recorder->complete(token); + } + 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)}; +}; + +class LogItAdapter::Impl { +public: + Impl() + : logger(logit::Logger::get_instance()) { + auto sink_ptr = std::make_unique(); + sink = sink_ptr.get(); + auto formatter = std::unique_ptr(new PassthroughFormatter()); + logger.add_logger(std::move(sink_ptr), std::move(formatter)); + } + + void prepare(const Scenario& scenario, LatencyRecorder& recorder) { + if (sink) { + sink->configure(scenario, recorder); + } + } + + void 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(); + } + } + + 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(); + } +} + +} // namespace logit_bench diff --git a/bench/adapters/LogItAdapter.hpp b/bench/adapters/LogItAdapter.hpp new file mode 100644 index 0000000..f949081 --- /dev/null +++ b/bench/adapters/LogItAdapter.hpp @@ -0,0 +1,28 @@ +#pragma once + +#include +#include + +#include "ILoggerAdapter.hpp" + +namespace logit_bench { + +class LogItAdapter : public ILoggerAdapter { +public: + LogItAdapter(); + ~LogItAdapter() override; + + const char* library_name() const override { return "log-it-cpp"; } + + void prepare(const Scenario& scenario, LatencyRecorder& recorder) override; + + void log(const LatencyRecorder::Token& token, std::string_view message) override; + + void flush() override; + +private: + class Impl; + std::unique_ptr m_impl; +}; + +} // namespace logit_bench diff --git a/bench/adapters/SpdlogAdapter.cpp b/bench/adapters/SpdlogAdapter.cpp new file mode 100644 index 0000000..5cb22c1 --- /dev/null +++ b/bench/adapters/SpdlogAdapter.cpp @@ -0,0 +1,144 @@ +#include "SpdlogAdapter.hpp" + +#ifdef LOGIT_BENCH_HAVE_SPDLOG + +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#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; + if (m_sink == SinkKind::File) { + std::filesystem::create_directories("bench/results"); + std::lock_guard lock(m_mutex); + m_file.close(); + m_file.open(kFilePath, std::ios::out | std::ios::trunc); + } else { + std::lock_guard lock(m_mutex); + m_file.close(); + } + } + + void log(const spdlog::details::log_msg& msg) override { + const auto* payload_ptr = reinterpret_cast(msg.source.funcname); + if (!payload_ptr) { + return; + } + auto* payload = const_cast(payload_ptr); + consume(*payload); + delete 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(); + } + } + +private: + void consume(const MessagePayload& payload) { + if (payload.token.active && m_recorder) { + m_recorder->complete(payload.token); + } + if (m_sink == SinkKind::File) { + std::lock_guard lock(m_mutex); + if (m_file.is_open()) { + m_file << payload.text << '\n'; + } + } + } + + SinkKind m_sink = SinkKind::Null; + LatencyRecorder* m_recorder = nullptr; + std::ofstream m_file; + std::mutex m_mutex; +}; + +SpdlogAdapter::SpdlogAdapter() = default; + +SpdlogAdapter::~SpdlogAdapter() { + flush(); + spdlog::shutdown(); +} + +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); + } +} + +void SpdlogAdapter::log(const LatencyRecorder::Token& token, std::string_view message) { + if (!m_logger) { + return; + } + auto* payload = new MessagePayload(); + payload->token = token; + payload->text.assign(message.data(), message.size()); + spdlog::source_loc loc{nullptr, 0, reinterpret_cast(payload)}; + m_logger->log(loc, spdlog::level::info, spdlog::string_view_t(payload->text)); +} + +void SpdlogAdapter::flush() { + if (m_logger) { + m_logger->flush(); + } + if (m_sink) { + m_sink->flush(); + } +} + +} // namespace logit_bench + +#endif // LOGIT_BENCH_HAVE_SPDLOG diff --git a/bench/adapters/SpdlogAdapter.hpp b/bench/adapters/SpdlogAdapter.hpp new file mode 100644 index 0000000..b34bf68 --- /dev/null +++ b/bench/adapters/SpdlogAdapter.hpp @@ -0,0 +1,37 @@ +#pragma once + +#ifdef LOGIT_BENCH_HAVE_SPDLOG + +#include +#include + +#include + +#include "ILoggerAdapter.hpp" + +namespace logit_bench { + +class SpdlogAdapter : public ILoggerAdapter { +public: + SpdlogAdapter(); + ~SpdlogAdapter() override; + + const char* library_name() const override { return "spdlog"; } + + void prepare(const Scenario& scenario, LatencyRecorder& recorder) override; + + void log(const LatencyRecorder::Token& token, std::string_view message) override; + + void flush() override; + +private: + class MeasuringSink; + + std::shared_ptr m_logger; + std::shared_ptr m_sink; + bool m_async = false; +}; + +} // namespace logit_bench + +#endif // LOGIT_BENCH_HAVE_SPDLOG diff --git a/bench/main.cpp b/bench/main.cpp new file mode 100644 index 0000000..d3ee64e --- /dev/null +++ b/bench/main.cpp @@ -0,0 +1,224 @@ +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "LatencyRecorder.hpp" +#include "Scenario.hpp" +#include "adapters/LogItAdapter.hpp" + +#ifdef LOGIT_BENCH_HAVE_SPDLOG +#include "adapters/SpdlogAdapter.hpp" +#endif + +namespace logit_bench { +namespace { +std::string make_message(std::size_t bytes, std::size_t index) { + if (bytes == 0) { + return std::string(); + } + char fill = static_cast('A' + static_cast(index % 26)); + return std::string(bytes, fill); +} + +std::chrono::nanoseconds run_workload( + ILoggerAdapter& adapter, + LatencyRecorder& recorder, + const Scenario& scenario, + std::size_t total_messages, + bool record_latency, + bool measure_duration) { + std::vector per_thread(scenario.producers, 0); + if (scenario.producers == 0) { + adapter.flush(); + return std::chrono::nanoseconds(0); + } + const std::size_t base = total_messages / scenario.producers; + std::size_t remaining = total_messages % scenario.producers; + for (std::size_t i = 0; i < scenario.producers; ++i) { + per_thread[i] = base + (remaining > 0 ? 1 : 0); + if (remaining > 0) { + --remaining; + } + } + + std::mutex start_mutex; + std::condition_variable start_cv; + bool start_flag = false; + std::size_t ready = 0; + + std::vector threads; + threads.reserve(scenario.producers); + + for (std::size_t i = 0; i < scenario.producers; ++i) { + threads.emplace_back([&, i]() { + std::string message = make_message(scenario.message_bytes, i); + { + std::unique_lock lock(start_mutex); + ++ready; + if (ready == scenario.producers) { + start_cv.notify_one(); + } + start_cv.wait(lock, [&]() { return start_flag; }); + } + for (std::size_t n = 0; n < per_thread[i]; ++n) { + auto token = recorder.begin(record_latency); + adapter.log(token, message); + } + }); + } + + std::chrono::steady_clock::time_point start_tp; + if (scenario.producers > 0) { + std::unique_lock lock(start_mutex); + start_cv.wait(lock, [&]() { return ready == scenario.producers; }); + if (measure_duration) { + start_tp = std::chrono::steady_clock::now(); + } + start_flag = true; + start_cv.notify_all(); + } + + for (auto& thread : threads) { + thread.join(); + } + + adapter.flush(); + + if (!measure_duration) { + return std::chrono::nanoseconds(0); + } + auto end_tp = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(end_tp - start_tp); +} + +struct ScenarioResult { + LatencyRecorder::Summary summary; + double throughput = 0.0; + std::chrono::nanoseconds duration{0}; +}; + +ScenarioResult execute_scenario( + ILoggerAdapter& adapter, + const Scenario& scenario, + std::size_t warmup_messages) { + LatencyRecorder recorder(scenario.total_messages); + adapter.prepare(scenario, recorder); + run_workload(adapter, recorder, scenario, warmup_messages, false, false); + const auto duration = run_workload(adapter, recorder, scenario, scenario.total_messages, true, true); + const auto summary = recorder.finalize(); + double throughput = 0.0; + if (duration.count() > 0) { + const double seconds = static_cast(duration.count()) / 1'000'000'000.0; + throughput = static_cast(scenario.total_messages) / seconds; + } + return ScenarioResult{summary, throughput, duration}; +} + +void append_csv( + const std::string& library, + const Scenario& scenario, + const LatencyRecorder::Summary& summary, + double throughput) { + namespace fs = std::filesystem; + const fs::path csv_path{"bench/results/latency.csv"}; + fs::create_directories(csv_path.parent_path()); + bool write_header = false; + if (!fs::exists(csv_path)) { + write_header = true; + } else if (fs::file_size(csv_path) == 0) { + write_header = true; + } + + std::ofstream out(csv_path, std::ios::app); + if (!out) { + throw std::runtime_error("Failed to open latency.csv for writing"); + } + if (write_header) { + out << "lib,async,sink,producers,msg_bytes,total,p50_ns,p99_ns,p999_ns,throughput\n"; + } + std::ostringstream throughput_stream; + throughput_stream << std::fixed << std::setprecision(2) << throughput; + out << library << ',' + << (scenario.async ? 1 : 0) << ',' + << sink_name(scenario.sink) << ',' + << scenario.producers << ',' + << scenario.message_bytes << ',' + << scenario.total_messages << ',' + << summary.p50_ns << ',' + << summary.p99_ns << ',' + << summary.p999_ns << ',' + << throughput_stream.str() << '\n'; +} + +void print_summary( + const std::string& library, + const Scenario& scenario, + const ScenarioResult& result) { + std::cout << library + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << scenario.total_messages + << " p50=" << result.summary.p50_ns + << "ns p99=" << result.summary.p99_ns + << "ns p999=" << result.summary.p999_ns + << "ns throughput=" << std::fixed << std::setprecision(2) + << result.throughput << " msg/s" << std::endl; +} + +} // namespace +} // namespace logit_bench + +int main() { + using namespace logit_bench; + try { + std::vector> adapters; + adapters.emplace_back(std::make_unique()); +#ifdef LOGIT_BENCH_HAVE_SPDLOG + adapters.emplace_back(std::make_unique()); +#endif + + const std::array async_modes{false, true}; + const std::array sinks{SinkKind::Null, SinkKind::File}; + const std::array producer_counts{1, 4, 16}; + const std::array message_sizes{40, 200, 1024}; + constexpr std::size_t total_messages = 6000; + constexpr std::size_t warmup_messages = 512; + + for (auto& adapter : adapters) { + for (bool async_mode : async_modes) { + for (auto sink : sinks) { + for (std::size_t producers : producer_counts) { + for (std::size_t msg_bytes : message_sizes) { + Scenario scenario; + scenario.async = async_mode; + scenario.sink = sink; + scenario.producers = producers; + scenario.message_bytes = msg_bytes; + scenario.total_messages = total_messages; + + auto result = execute_scenario(*adapter, scenario, warmup_messages); + append_csv(adapter->library_name(), scenario, result.summary, result.throughput); + print_summary(adapter->library_name(), scenario, result); + } + } + } + } + } + } catch (const std::exception& ex) { + std::cerr << "Benchmark failed: " << ex.what() << std::endl; + return 1; + } + return 0; +} diff --git a/bench/results/.gitignore b/bench/results/.gitignore new file mode 100644 index 0000000..9bae93b --- /dev/null +++ b/bench/results/.gitignore @@ -0,0 +1 @@ +latency.csv From 3deaf98e2b388a8c6260314cc50875fd0a164157 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 18 Sep 2025 07:07:24 +0300 Subject: [PATCH 02/17] ci: add gated bench job Run the benchmark configure/build/run steps only when relevant events trigger. --- .github/workflows/ci.yml | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b009f52..fd1daf4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -2,7 +2,7 @@ name: CI on: push: - branches: [ main ] + branches: [ main, stable ] pull_request: branches: [ main ] @@ -25,6 +25,15 @@ jobs: run: cmake --install build --prefix install - name: Test run: ctest --test-dir build --output-on-failure + - name: Configure benchmarks + if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -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 + - name: Run latency benchmarks + if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + run: ./build-bench/logit_bench - name: Configure consumer project run: cmake -S tests/install_consumer -B build-consumer -DCMAKE_PREFIX_PATH=${{ github.workspace }}/install -DCMAKE_CXX_STANDARD=${{ matrix.std }} - name: Build consumer project From d402daaa38c0abe34848cd1bb60040fe5861992b Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 18 Sep 2025 07:16:19 +0300 Subject: [PATCH 03/17] ci: fix benchmark run path --- .github/workflows/ci.yml | 2 +- README.md | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index fd1daf4..ce840bb 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -33,7 +33,7 @@ jobs: run: cmake --build build-bench --target logit_bench - name: Run latency benchmarks if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} - run: ./build-bench/logit_bench + run: ./build-bench/bench/logit_bench - name: Configure consumer project run: cmake -S tests/install_consumer -B build-consumer -DCMAKE_PREFIX_PATH=${{ github.workspace }}/install -DCMAKE_CXX_STANDARD=${{ matrix.std }} - name: Build consumer project diff --git a/README.md b/README.md index e6d4f5a..2220958 100644 --- a/README.md +++ b/README.md @@ -746,8 +746,8 @@ cmake -S . -B build -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON cmake --build build --target logit_bench ``` -Run the executable to record 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. +Run `./build/bench/logit_bench` to record 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. --- From d22d79191899e8d2571219713cabc4ee04cab149 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 18 Sep 2025 16:46:35 +0300 Subject: [PATCH 04/17] refactor(bench): refine latency measurements Adopt the revised latency recorder, scenario runner, and README guidance so the benchmark captures timestamps after slot reservation, calculates percentiles via nearest rank, and allows workload overrides via environment variables. --- README.md | 3 +- bench/CMakeLists.txt | 2 +- bench/LatencyRecorder.hpp | 57 ++++++----- bench/Scenario.hpp | 14 ++- bench/{main.cpp => logit_bench.cpp} | 144 ++++++++++++++++------------ 5 files changed, 121 insertions(+), 99 deletions(-) rename bench/{main.cpp => logit_bench.cpp} (63%) diff --git a/README.md b/README.md index 2220958..6c48578 100644 --- a/README.md +++ b/README.md @@ -747,7 +747,8 @@ cmake --build build --target logit_bench ``` Run `./build/bench/logit_bench` to record 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. +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. --- diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index 91348a2..60f4d17 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -1,5 +1,5 @@ set(LOGIT_BENCH_SOURCES - main.cpp + logit_bench.cpp adapters/LogItAdapter.cpp ) diff --git a/bench/LatencyRecorder.hpp b/bench/LatencyRecorder.hpp index c735d7d..f25a84e 100644 --- a/bench/LatencyRecorder.hpp +++ b/bench/LatencyRecorder.hpp @@ -7,9 +7,18 @@ #include #include #include +#include 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 { @@ -19,8 +28,8 @@ class LatencyRecorder { }; struct Summary { - std::uint64_t p50_ns = 0; - std::uint64_t p99_ns = 0; + std::uint64_t p50_ns = 0; + std::uint64_t p99_ns = 0; std::uint64_t p999_ns = 0; }; @@ -29,26 +38,29 @@ class LatencyRecorder { m_expected(total), m_next_slot(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(). + */ Token begin(bool record) { Token token; token.active = record; - token.t0_ns = now(); if (record) { 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(); } return token; } + /// Capture t1 and store (t1 - t0) into the reserved slot. void complete(const Token& token) { - if (!token.active) { - return; - } + if (!token.active) return; const auto t1_ns = now(); - m_values[token.slot] = t1_ns - token.t0_ns; + m_values[token.slot] = t1_ns - token.t0_ns; // distinct slots -> no data race } std::size_t recorded() const { @@ -62,8 +74,8 @@ class LatencyRecorder { 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.p50_ns = pick(sorted, 0.50); + summary.p99_ns = pick(sorted, 0.99); summary.p999_ns = pick(sorted, 0.999); return summary; } @@ -78,25 +90,18 @@ class LatencyRecorder { } private: - static std::uint64_t pick(const std::vector& data, double percentile) { - if (data.empty()) { - return 0; - } - const double rank = percentile * static_cast(data.size()); - std::size_t index = static_cast(rank); - if (static_cast(index) < rank) { - index += 1; - } - if (index == 0) { - index = 1; - } - const std::size_t pos = std::min(index - 1, data.size() - 1); - return data[pos]; + // 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; - const std::size_t m_expected; - std::atomic m_next_slot; + std::vector m_values; // preallocated; no reallocation + const std::size_t m_expected; // total messages to record + std::atomic m_next_slot; }; } // namespace logit_bench diff --git a/bench/Scenario.hpp b/bench/Scenario.hpp index 7bc0d37..3fe052a 100644 --- a/bench/Scenario.hpp +++ b/bench/Scenario.hpp @@ -12,19 +12,17 @@ enum class SinkKind { inline std::string sink_name(SinkKind sink) { switch (sink) { - case SinkKind::Null: - return "null"; - case SinkKind::File: - return "file"; + case SinkKind::Null: return "null"; + case SinkKind::File: return "file"; } return "unknown"; } struct Scenario { - bool async = false; - SinkKind sink = SinkKind::Null; - std::size_t producers = 1; - std::size_t message_bytes = 0; + bool async = false; + SinkKind sink = SinkKind::Null; + std::size_t producers = 1; + std::size_t message_bytes = 0; std::size_t total_messages = 0; }; diff --git a/bench/main.cpp b/bench/logit_bench.cpp similarity index 63% rename from bench/main.cpp rename to bench/logit_bench.cpp index d3ee64e..4fd8236 100644 --- a/bench/main.cpp +++ b/bench/logit_bench.cpp @@ -1,12 +1,13 @@ #include #include #include +#include #include #include #include #include +#include #include -#include #include #include #include @@ -22,36 +23,56 @@ namespace logit_bench { namespace { + std::string make_message(std::size_t bytes, std::size_t index) { - if (bytes == 0) { - return std::string(); - } - char fill = static_cast('A' + static_cast(index % 26)); + if (bytes == 0) return {}; + const char fill = static_cast('A' + static_cast(index % 26)); return std::string(bytes, fill); } +std::size_t get_env_size_t(const char* name, std::size_t def) { + if (const char* v = std::getenv(name)) { + try { + return static_cast(std::stoull(v)); + } catch (...) { + // fallthrough + } + } + return def; +} + +/** + * Run a workload: + * - producers start together (barrier), + * - each producer logs its portion of total_messages, + * - LatencyRecorder::begin(record) captures t0 and slot, + * - adapter.log(token, message) must eventually call recorder.complete(token) from sink/consumer, + * - returns total wall duration (for throughput). + */ std::chrono::nanoseconds run_workload( ILoggerAdapter& adapter, LatencyRecorder& recorder, const Scenario& scenario, std::size_t total_messages, bool record_latency, - bool measure_duration) { - std::vector per_thread(scenario.producers, 0); + bool measure_duration) +{ if (scenario.producers == 0) { adapter.flush(); return std::chrono::nanoseconds(0); } + + // Distribute messages across producers. + std::vector per_thread(scenario.producers, 0); const std::size_t base = total_messages / scenario.producers; - std::size_t remaining = total_messages % scenario.producers; + std::size_t rem = total_messages % scenario.producers; for (std::size_t i = 0; i < scenario.producers; ++i) { - per_thread[i] = base + (remaining > 0 ? 1 : 0); - if (remaining > 0) { - --remaining; - } + per_thread[i] = base + (rem ? 1 : 0); + if (rem) --rem; } - std::mutex start_mutex; + // Barrier to start together. + std::mutex start_mx; std::condition_variable start_cv; bool start_flag = false; std::size_t ready = 0; @@ -63,12 +84,10 @@ std::chrono::nanoseconds run_workload( threads.emplace_back([&, i]() { std::string message = make_message(scenario.message_bytes, i); { - std::unique_lock lock(start_mutex); + std::unique_lock lk(start_mx); ++ready; - if (ready == scenario.producers) { - start_cv.notify_one(); - } - start_cv.wait(lock, [&]() { return start_flag; }); + if (ready == scenario.producers) start_cv.notify_one(); + start_cv.wait(lk, [&]{ return start_flag; }); } for (std::size_t n = 0; n < per_thread[i]; ++n) { auto token = recorder.begin(record_latency); @@ -77,28 +96,21 @@ std::chrono::nanoseconds run_workload( }); } - std::chrono::steady_clock::time_point start_tp; - if (scenario.producers > 0) { - std::unique_lock lock(start_mutex); - start_cv.wait(lock, [&]() { return ready == scenario.producers; }); - if (measure_duration) { - start_tp = std::chrono::steady_clock::now(); - } + std::chrono::steady_clock::time_point t0; + { + std::unique_lock lk(start_mx); + start_cv.wait(lk, [&]{ return ready == scenario.producers; }); + if (measure_duration) t0 = std::chrono::steady_clock::now(); start_flag = true; start_cv.notify_all(); } - for (auto& thread : threads) { - thread.join(); - } - + for (auto& th : threads) th.join(); adapter.flush(); - if (!measure_duration) { - return std::chrono::nanoseconds(0); - } - auto end_tp = std::chrono::steady_clock::now(); - return std::chrono::duration_cast(end_tp - start_tp); + if (!measure_duration) return std::chrono::nanoseconds(0); + auto t1 = std::chrono::steady_clock::now(); + return std::chrono::duration_cast(t1 - t0); } struct ScenarioResult { @@ -110,44 +122,46 @@ struct ScenarioResult { ScenarioResult execute_scenario( ILoggerAdapter& adapter, const Scenario& scenario, - std::size_t warmup_messages) { + std::size_t warmup_messages) +{ LatencyRecorder recorder(scenario.total_messages); + + // Adapter should keep a pointer/ref to recorder and call complete(token) from its sink. adapter.prepare(scenario, recorder); + + // Warm-up (no recording, no duration). run_workload(adapter, recorder, scenario, warmup_messages, false, false); - const auto duration = run_workload(adapter, recorder, scenario, scenario.total_messages, true, true); - const auto summary = recorder.finalize(); - double throughput = 0.0; - if (duration.count() > 0) { - const double seconds = static_cast(duration.count()) / 1'000'000'000.0; - throughput = static_cast(scenario.total_messages) / seconds; + + // Measured run. + const auto dur = run_workload(adapter, recorder, scenario, scenario.total_messages, true, true); + const auto sum = recorder.finalize(); + + double thr = 0.0; + if (dur.count() > 0) { + const double sec = static_cast(dur.count()) / 1'000'000'000.0; + thr = static_cast(scenario.total_messages) / sec; } - return ScenarioResult{summary, throughput, duration}; + return ScenarioResult{sum, thr, dur}; } void append_csv( const std::string& library, const Scenario& scenario, const LatencyRecorder::Summary& summary, - double throughput) { + double throughput) +{ namespace fs = std::filesystem; const fs::path csv_path{"bench/results/latency.csv"}; fs::create_directories(csv_path.parent_path()); - bool write_header = false; - if (!fs::exists(csv_path)) { - write_header = true; - } else if (fs::file_size(csv_path) == 0) { - write_header = true; - } + + const bool write_header = !fs::exists(csv_path) || fs::file_size(csv_path) == 0; std::ofstream out(csv_path, std::ios::app); - if (!out) { - throw std::runtime_error("Failed to open latency.csv for writing"); - } + if (!out) throw std::runtime_error("Failed to open latency.csv for writing"); + if (write_header) { out << "lib,async,sink,producers,msg_bytes,total,p50_ns,p99_ns,p999_ns,throughput\n"; } - std::ostringstream throughput_stream; - throughput_stream << std::fixed << std::setprecision(2) << throughput; out << library << ',' << (scenario.async ? 1 : 0) << ',' << sink_name(scenario.sink) << ',' @@ -157,13 +171,14 @@ void append_csv( << summary.p50_ns << ',' << summary.p99_ns << ',' << summary.p999_ns << ',' - << throughput_stream.str() << '\n'; + << std::fixed << std::setprecision(2) << throughput << '\n'; } void print_summary( const std::string& library, const Scenario& scenario, - const ScenarioResult& result) { + const ScenarioResult& result) +{ std::cout << library << " async=" << (scenario.async ? '1' : '0') << " sink=" << sink_name(scenario.sink) @@ -174,7 +189,7 @@ void print_summary( << "ns p99=" << result.summary.p99_ns << "ns p999=" << result.summary.p999_ns << "ns throughput=" << std::fixed << std::setprecision(2) - << result.throughput << " msg/s" << std::endl; + << result.throughput << " msg/s\n"; } } // namespace @@ -189,12 +204,15 @@ int main() { adapters.emplace_back(std::make_unique()); #endif + // Matrix const std::array async_modes{false, true}; const std::array sinks{SinkKind::Null, SinkKind::File}; const std::array producer_counts{1, 4, 16}; const std::array message_sizes{40, 200, 1024}; - constexpr std::size_t total_messages = 6000; - constexpr std::size_t warmup_messages = 512; + + // Totals (can be overridden by env): + const std::size_t total_messages = get_env_size_t("LOGIT_BENCH_TOTAL", 200000); + const std::size_t warmup_messages = get_env_size_t("LOGIT_BENCH_WARMUP", 4096); for (auto& adapter : adapters) { for (bool async_mode : async_modes) { @@ -202,10 +220,10 @@ int main() { for (std::size_t producers : producer_counts) { for (std::size_t msg_bytes : message_sizes) { Scenario scenario; - scenario.async = async_mode; - scenario.sink = sink; - scenario.producers = producers; - scenario.message_bytes = msg_bytes; + scenario.async = async_mode; + scenario.sink = sink; + scenario.producers = producers; + scenario.message_bytes = msg_bytes; scenario.total_messages = total_messages; auto result = execute_scenario(*adapter, scenario, warmup_messages); From 500e8f5d302ff32cafdcc8c7444b660d13b1220f Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 18 Sep 2025 21:46:24 +0300 Subject: [PATCH 05/17] fix(ci): point benchmark step to binary Ensure the Linux workflow runs the built logit_bench executable from the build directory so the step no longer fails with a missing file. --- .github/workflows/ci.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index ce840bb..fd1daf4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -33,7 +33,7 @@ jobs: run: cmake --build build-bench --target logit_bench - name: Run latency benchmarks if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} - run: ./build-bench/bench/logit_bench + run: ./build-bench/logit_bench - name: Configure consumer project run: cmake -S tests/install_consumer -B build-consumer -DCMAKE_PREFIX_PATH=${{ github.workspace }}/install -DCMAKE_CXX_STANDARD=${{ matrix.std }} - name: Build consumer project From f00e844eb5673edf7f4708f382181b1107bb8d24 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Thu, 18 Sep 2025 21:46:29 +0300 Subject: [PATCH 06/17] fix(tests): guard tsan access in backpressure ordering --- tests/backpressure_ordering_test.cpp | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/tests/backpressure_ordering_test.cpp b/tests/backpressure_ordering_test.cpp index 824b45a..3b3a6b4 100644 --- a/tests/backpressure_ordering_test.cpp +++ b/tests/backpressure_ordering_test.cpp @@ -23,6 +23,8 @@ int main() { LOGIT_SET_MAX_QUEUE(kQueueCapacity); LOGIT_RESET_DROPPED_TASKS(); + // Векторы лежат в стеке main-потока, но их изменяют воркеры. + // Пишем/читаем их ТОЛЬКО под одним и тем же per-producer мьютексом. std::array, kProducers> sequences; for (auto &sequence : sequences) { sequence.clear(); @@ -37,6 +39,7 @@ int main() { for (std::size_t producer_id = 0; producer_id < kProducers; ++producer_id) { producers.emplace_back([producer_id, &executor, &start, &sequence_guards, &sequences]() { + // Барьер запуска while (!start.load(std::memory_order_acquire)) { std::this_thread::yield(); } @@ -56,13 +59,16 @@ int main() { producer.join(); } - executor.wait(); + executor.wait(); // гарантируем завершение всех задач if (LOGIT_GET_DROPPED_TASKS() != 0) { return 1; } + // Читаем под тем же мьютексом — это устраняет data race в TSAN for (std::size_t producer_id = 0; producer_id < kProducers; ++producer_id) { + std::lock_guard lock(sequence_guards[producer_id]); + const auto &sequence = sequences[producer_id]; if (sequence.size() != kMessagesPerProducer) { return 2; From 08ce2035673efe1b7b43600024ddb52ae1d9d449 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 02:23:25 +0300 Subject: [PATCH 07/17] fix(bench): stabilise benchmark execution Ensure the CI job finds the logit_bench binary and add timeout-based watchdog logging so hangs surface with context. --- bench/CMakeLists.txt | 10 ++++++++ bench/logit_bench.cpp | 54 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 64 insertions(+) diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index 60f4d17..ebffc7c 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -13,6 +13,16 @@ target_include_directories(logit_bench PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}) target_compile_features(logit_bench PRIVATE cxx_std_17) +set_target_properties(logit_bench PROPERTIES + RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR} +) + +foreach(config IN ITEMS DEBUG RELEASE RELWITHDEBINFO MINSIZEREL) + set_target_properties(logit_bench PROPERTIES + RUNTIME_OUTPUT_DIRECTORY_${config} ${CMAKE_BINARY_DIR} + ) +endforeach() + target_link_libraries(logit_bench PRIVATE log-it-cpp::log-it-cpp) if(LOGIT_BENCH_WITH_SPDLOG) diff --git a/bench/logit_bench.cpp b/bench/logit_bench.cpp index 4fd8236..c86652d 100644 --- a/bench/logit_bench.cpp +++ b/bench/logit_bench.cpp @@ -1,4 +1,5 @@ #include +#include #include #include #include @@ -130,10 +131,34 @@ ScenarioResult execute_scenario( adapter.prepare(scenario, recorder); // Warm-up (no recording, no duration). + std::cout << "[logit_bench] Warm-up start lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << warmup_messages << std::endl; run_workload(adapter, recorder, scenario, warmup_messages, false, false); + std::cout << "[logit_bench] Warm-up completed lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << std::endl; // Measured run. + std::cout << "[logit_bench] Measure start lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << scenario.total_messages << std::endl; const auto dur = run_workload(adapter, recorder, scenario, scenario.total_messages, true, true); + std::cout << "[logit_bench] Measure completed lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << std::endl; const auto sum = recorder.finalize(); double thr = 0.0; @@ -197,6 +222,8 @@ void print_summary( int main() { using namespace logit_bench; + std::atomic watchdog_done{false}; + std::thread watchdog; try { std::vector> adapters; adapters.emplace_back(std::make_unique()); @@ -213,6 +240,23 @@ int main() { // Totals (can be overridden by env): const std::size_t total_messages = get_env_size_t("LOGIT_BENCH_TOTAL", 200000); const std::size_t warmup_messages = get_env_size_t("LOGIT_BENCH_WARMUP", 4096); + const std::size_t timeout_seconds = get_env_size_t("LOGIT_BENCH_TIMEOUT_SEC", 600); + + if (timeout_seconds > 0) { + watchdog = std::thread([timeout_seconds, &watchdog_done]() { + const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(timeout_seconds); + while (!watchdog_done.load(std::memory_order_relaxed)) { + if (std::chrono::steady_clock::now() >= deadline) { + std::cerr << "[logit_bench] Timeout reached after " + << timeout_seconds + << " seconds. Terminating benchmark." << std::endl; + std::cerr.flush(); + std::_Exit(124); + } + std::this_thread::sleep_for(std::chrono::milliseconds(200)); + } + }); + } for (auto& adapter : adapters) { for (bool async_mode : async_modes) { @@ -226,6 +270,12 @@ int main() { scenario.message_bytes = msg_bytes; scenario.total_messages = total_messages; + std::cout << "[logit_bench] Scenario start lib=" << adapter->library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << scenario.total_messages << std::endl; auto result = execute_scenario(*adapter, scenario, warmup_messages); append_csv(adapter->library_name(), scenario, result.summary, result.throughput); print_summary(adapter->library_name(), scenario, result); @@ -234,7 +284,11 @@ int main() { } } } + watchdog_done.store(true, std::memory_order_relaxed); + if (watchdog.joinable()) watchdog.join(); } catch (const std::exception& ex) { + watchdog_done.store(true, std::memory_order_relaxed); + if (watchdog.joinable()) watchdog.join(); std::cerr << "Benchmark failed: " << ex.what() << std::endl; return 1; } From 728c7a5c742a3a81da1ecbbe0f841d6f4f88021a Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 02:50:10 +0300 Subject: [PATCH 08/17] ci: throttle logit bench runtime --- .github/workflows/ci.yml | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index fd1daf4..7592ab4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -33,6 +33,11 @@ jobs: run: cmake --build build-bench --target logit_bench - name: Run latency benchmarks if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + timeout-minutes: 20 + env: + LOGIT_BENCH_TIMEOUT_SEC: 900 + LOGIT_BENCH_TOTAL: 20000 + LOGIT_BENCH_WARMUP: 2000 run: ./build-bench/logit_bench - name: Configure consumer project run: cmake -S tests/install_consumer -B build-consumer -DCMAKE_PREFIX_PATH=${{ github.workspace }}/install -DCMAKE_CXX_STANDARD=${{ matrix.std }} From f3f0fd229c0fefe39738f5804bfee248dca9b804 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 03:20:53 +0300 Subject: [PATCH 09/17] ci(workflow): trust pull_request_target Switch the CI workflow to pull_request_target so forked pull requests run without maintainer approval. Explicitly check out the contributor repository when needed and tighten permissions while still allowing checks and artifacts. --- .github/workflows/ci.yml | 80 +++++++++++++++++++++++++++++++++++----- 1 file changed, 70 insertions(+), 10 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 7592ab4..46253b3 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -3,9 +3,15 @@ name: CI on: push: branches: [ main, stable ] - pull_request: + pull_request_target: branches: [ main ] +permissions: + actions: write + checks: write + contents: read + pull-requests: read + jobs: linux: runs-on: ubuntu-latest @@ -13,7 +19,16 @@ jobs: matrix: std: [11, 17] steps: - - uses: actions/checkout@v4 + - name: Checkout pull request head + if: github.event_name == 'pull_request_target' + uses: actions/checkout@v4 + with: + repository: ${{ github.event.pull_request.head.repo.full_name }} + ref: ${{ github.event.pull_request.head.ref }} + submodules: true + - name: Checkout repository + if: github.event_name != 'pull_request_target' + uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -26,13 +41,13 @@ jobs: - name: Test run: ctest --test-dir build --output-on-failure - name: Configure benchmarks - if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + if: ${{ github.event_name != 'push' || github.ref == 'refs/heads/stable' }} run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -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') }} + if: ${{ github.event_name != 'push' || github.ref == 'refs/heads/stable' }} run: cmake --build build-bench --target logit_bench - name: Run latency benchmarks - if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + if: ${{ github.event_name != 'push' || github.ref == 'refs/heads/stable' }} timeout-minutes: 20 env: LOGIT_BENCH_TIMEOUT_SEC: 900 @@ -59,7 +74,16 @@ jobs: matrix: std: [11, 17] steps: - - uses: actions/checkout@v4 + - name: Checkout pull request head + if: github.event_name == 'pull_request_target' + uses: actions/checkout@v4 + with: + repository: ${{ github.event.pull_request.head.repo.full_name }} + ref: ${{ github.event.pull_request.head.ref }} + submodules: true + - name: Checkout repository + if: github.event_name != 'pull_request_target' + uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -91,7 +115,16 @@ jobs: matrix: std: [11, 17] steps: - - uses: actions/checkout@v4 + - name: Checkout pull request head + if: github.event_name == 'pull_request_target' + uses: actions/checkout@v4 + with: + repository: ${{ github.event.pull_request.head.repo.full_name }} + ref: ${{ github.event.pull_request.head.ref }} + submodules: true + - name: Checkout repository + if: github.event_name != 'pull_request_target' + uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -120,7 +153,16 @@ jobs: asan-ubsan: runs-on: ubuntu-latest steps: - - uses: actions/checkout@v4 + - name: Checkout pull request head + if: github.event_name == 'pull_request_target' + uses: actions/checkout@v4 + with: + repository: ${{ github.event.pull_request.head.repo.full_name }} + ref: ${{ github.event.pull_request.head.ref }} + submodules: true + - name: Checkout repository + if: github.event_name != 'pull_request_target' + uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -136,7 +178,16 @@ jobs: env: LOGIT_PROFILE: thread steps: - - uses: actions/checkout@v4 + - name: Checkout pull request head + if: github.event_name == 'pull_request_target' + uses: actions/checkout@v4 + with: + repository: ${{ github.event.pull_request.head.repo.full_name }} + ref: ${{ github.event.pull_request.head.ref }} + submodules: true + - name: Checkout repository + if: github.event_name != 'pull_request_target' + uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -152,7 +203,16 @@ jobs: env: VCPKG_TAG: '2024.09.30' steps: - - uses: actions/checkout@v4 + - name: Checkout pull request head + if: github.event_name == 'pull_request_target' + uses: actions/checkout@v4 + with: + repository: ${{ github.event.pull_request.head.repo.full_name }} + ref: ${{ github.event.pull_request.head.ref }} + submodules: true + - name: Checkout repository + if: github.event_name != 'pull_request_target' + uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive From 2f2247e3bded1809459e8ffc95d61c318f9043bc Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 03:26:53 +0300 Subject: [PATCH 10/17] ci: handle internal pull requests Run the workflow on pull_request events for repository branches while keeping pull_request_target for forks, and ensure each job checks out the proper head and skips duplicate runs. --- .github/workflows/ci.yml | 142 +++++++++++++++++++++++++++++++++++---- 1 file changed, 129 insertions(+), 13 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 46253b3..792dbaa 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -3,6 +3,8 @@ name: CI on: push: branches: [ main, stable ] + pull_request: + branches: [ main ] pull_request_target: branches: [ main ] @@ -14,20 +16,35 @@ permissions: jobs: linux: + if: >- + github.event_name == 'push' || + ( + github.event_name != 'push' && + ( + (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || + (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) + ) + ) runs-on: ubuntu-latest strategy: matrix: std: [11, 17] steps: - - name: Checkout pull request head + - name: Checkout pull request head (fork) if: github.event_name == 'pull_request_target' uses: actions/checkout@v4 with: repository: ${{ github.event.pull_request.head.repo.full_name }} ref: ${{ github.event.pull_request.head.ref }} submodules: true + - name: Checkout pull request head (same repository) + if: github.event_name == 'pull_request' + uses: actions/checkout@v4 + with: + ref: ${{ github.event.pull_request.head.sha }} + submodules: true - name: Checkout repository - if: github.event_name != 'pull_request_target' + if: github.event_name == 'push' uses: actions/checkout@v4 with: submodules: true @@ -69,20 +86,35 @@ jobs: if-no-files-found: ignore windows: + if: >- + github.event_name == 'push' || + ( + github.event_name != 'push' && + ( + (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || + (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) + ) + ) runs-on: windows-latest strategy: matrix: std: [11, 17] steps: - - name: Checkout pull request head + - name: Checkout pull request head (fork) if: github.event_name == 'pull_request_target' uses: actions/checkout@v4 with: repository: ${{ github.event.pull_request.head.repo.full_name }} ref: ${{ github.event.pull_request.head.ref }} submodules: true + - name: Checkout pull request head (same repository) + if: github.event_name == 'pull_request' + uses: actions/checkout@v4 + with: + ref: ${{ github.event.pull_request.head.sha }} + submodules: true - name: Checkout repository - if: github.event_name != 'pull_request_target' + if: github.event_name == 'push' uses: actions/checkout@v4 with: submodules: true @@ -110,20 +142,35 @@ jobs: if-no-files-found: ignore macos: + if: >- + github.event_name == 'push' || + ( + github.event_name != 'push' && + ( + (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || + (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) + ) + ) runs-on: macos-latest strategy: matrix: std: [11, 17] steps: - - name: Checkout pull request head + - name: Checkout pull request head (fork) if: github.event_name == 'pull_request_target' uses: actions/checkout@v4 with: repository: ${{ github.event.pull_request.head.repo.full_name }} ref: ${{ github.event.pull_request.head.ref }} submodules: true + - name: Checkout pull request head (same repository) + if: github.event_name == 'pull_request' + uses: actions/checkout@v4 + with: + ref: ${{ github.event.pull_request.head.sha }} + submodules: true - name: Checkout repository - if: github.event_name != 'pull_request_target' + if: github.event_name == 'push' uses: actions/checkout@v4 with: submodules: true @@ -151,17 +198,32 @@ jobs: if-no-files-found: ignore asan-ubsan: + if: >- + github.event_name == 'push' || + ( + github.event_name != 'push' && + ( + (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || + (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) + ) + ) runs-on: ubuntu-latest steps: - - name: Checkout pull request head + - name: Checkout pull request head (fork) if: github.event_name == 'pull_request_target' uses: actions/checkout@v4 with: repository: ${{ github.event.pull_request.head.repo.full_name }} ref: ${{ github.event.pull_request.head.ref }} submodules: true + - name: Checkout pull request head (same repository) + if: github.event_name == 'pull_request' + uses: actions/checkout@v4 + with: + ref: ${{ github.event.pull_request.head.sha }} + submodules: true - name: Checkout repository - if: github.event_name != 'pull_request_target' + if: github.event_name == 'push' uses: actions/checkout@v4 with: submodules: true @@ -174,19 +236,34 @@ jobs: run: ctest --test-dir build --output-on-failure tsan: + if: >- + github.event_name == 'push' || + ( + github.event_name != 'push' && + ( + (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || + (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) + ) + ) runs-on: ubuntu-latest env: LOGIT_PROFILE: thread steps: - - name: Checkout pull request head + - name: Checkout pull request head (fork) if: github.event_name == 'pull_request_target' uses: actions/checkout@v4 with: repository: ${{ github.event.pull_request.head.repo.full_name }} ref: ${{ github.event.pull_request.head.ref }} submodules: true + - name: Checkout pull request head (same repository) + if: github.event_name == 'pull_request' + uses: actions/checkout@v4 + with: + ref: ${{ github.event.pull_request.head.sha }} + submodules: true - name: Checkout repository - if: github.event_name != 'pull_request_target' + if: github.event_name == 'push' uses: actions/checkout@v4 with: submodules: true @@ -199,19 +276,34 @@ jobs: run: ctest --test-dir build --output-on-failure vcpkg-install: + if: >- + github.event_name == 'push' || + ( + github.event_name != 'push' && + ( + (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || + (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) + ) + ) runs-on: ubuntu-latest env: VCPKG_TAG: '2024.09.30' steps: - - name: Checkout pull request head + - name: Checkout pull request head (fork) if: github.event_name == 'pull_request_target' uses: actions/checkout@v4 with: repository: ${{ github.event.pull_request.head.repo.full_name }} ref: ${{ github.event.pull_request.head.ref }} submodules: true + - name: Checkout pull request head (same repository) + if: github.event_name == 'pull_request' + uses: actions/checkout@v4 + with: + ref: ${{ github.event.pull_request.head.sha }} + submodules: true - name: Checkout repository - if: github.event_name != 'pull_request_target' + if: github.event_name == 'push' uses: actions/checkout@v4 with: submodules: true @@ -259,9 +351,33 @@ jobs: if-no-files-found: ignore emscripten: + if: >- + github.event_name == 'push' || + ( + github.event_name != 'push' && + ( + (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || + (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) + ) + ) runs-on: ubuntu-latest steps: - - uses: actions/checkout@v4 + - name: Checkout pull request head (fork) + if: github.event_name == 'pull_request_target' + uses: actions/checkout@v4 + with: + repository: ${{ github.event.pull_request.head.repo.full_name }} + ref: ${{ github.event.pull_request.head.ref }} + submodules: true + - name: Checkout pull request head (same repository) + if: github.event_name == 'pull_request' + uses: actions/checkout@v4 + with: + ref: ${{ github.event.pull_request.head.sha }} + submodules: true + - name: Checkout repository + if: github.event_name == 'push' + uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive From cad3ed1372816a3e25ec03def98772386bd5c732 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 04:04:05 +0300 Subject: [PATCH 11/17] ci(workflow): drop unused write permissions --- .github/workflows/ci.yml | 2 -- 1 file changed, 2 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 792dbaa..f34de53 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -9,8 +9,6 @@ on: branches: [ main ] permissions: - actions: write - checks: write contents: read pull-requests: read From cedd8a38af02854d49ab1cc0bb9d6f92c17a2ee8 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 04:04:09 +0300 Subject: [PATCH 12/17] revert(ci): restore original workflow Revert the conditional triggers added earlier so the CI matches the prior configuration without pull_request_target logic. --- .github/workflows/ci.yml | 204 ++------------------------------------- 1 file changed, 8 insertions(+), 196 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index f34de53..b009f52 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -2,48 +2,18 @@ name: CI on: push: - branches: [ main, stable ] - pull_request: branches: [ main ] - pull_request_target: + pull_request: branches: [ main ] -permissions: - contents: read - pull-requests: read - jobs: linux: - if: >- - github.event_name == 'push' || - ( - github.event_name != 'push' && - ( - (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || - (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) - ) - ) runs-on: ubuntu-latest strategy: matrix: std: [11, 17] steps: - - name: Checkout pull request head (fork) - if: github.event_name == 'pull_request_target' - uses: actions/checkout@v4 - with: - repository: ${{ github.event.pull_request.head.repo.full_name }} - ref: ${{ github.event.pull_request.head.ref }} - submodules: true - - name: Checkout pull request head (same repository) - if: github.event_name == 'pull_request' - uses: actions/checkout@v4 - with: - ref: ${{ github.event.pull_request.head.sha }} - submodules: true - - name: Checkout repository - if: github.event_name == 'push' - uses: actions/checkout@v4 + - uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -55,20 +25,6 @@ jobs: run: cmake --install build --prefix install - name: Test run: ctest --test-dir build --output-on-failure - - name: Configure benchmarks - if: ${{ github.event_name != 'push' || github.ref == 'refs/heads/stable' }} - run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -DCMAKE_CXX_STANDARD=${{ matrix.std }} -DLOGIT_WITH_SYSLOG=ON -DLOGIT_WITH_WIN_EVENT_LOG=OFF - - name: Build benchmarks - if: ${{ github.event_name != 'push' || github.ref == 'refs/heads/stable' }} - run: cmake --build build-bench --target logit_bench - - name: Run latency benchmarks - if: ${{ github.event_name != 'push' || github.ref == 'refs/heads/stable' }} - timeout-minutes: 20 - env: - LOGIT_BENCH_TIMEOUT_SEC: 900 - LOGIT_BENCH_TOTAL: 20000 - LOGIT_BENCH_WARMUP: 2000 - run: ./build-bench/logit_bench - name: Configure consumer project run: cmake -S tests/install_consumer -B build-consumer -DCMAKE_PREFIX_PATH=${{ github.workspace }}/install -DCMAKE_CXX_STANDARD=${{ matrix.std }} - name: Build consumer project @@ -84,36 +40,12 @@ jobs: if-no-files-found: ignore windows: - if: >- - github.event_name == 'push' || - ( - github.event_name != 'push' && - ( - (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || - (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) - ) - ) runs-on: windows-latest strategy: matrix: std: [11, 17] steps: - - name: Checkout pull request head (fork) - if: github.event_name == 'pull_request_target' - uses: actions/checkout@v4 - with: - repository: ${{ github.event.pull_request.head.repo.full_name }} - ref: ${{ github.event.pull_request.head.ref }} - submodules: true - - name: Checkout pull request head (same repository) - if: github.event_name == 'pull_request' - uses: actions/checkout@v4 - with: - ref: ${{ github.event.pull_request.head.sha }} - submodules: true - - name: Checkout repository - if: github.event_name == 'push' - uses: actions/checkout@v4 + - uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -140,36 +72,12 @@ jobs: if-no-files-found: ignore macos: - if: >- - github.event_name == 'push' || - ( - github.event_name != 'push' && - ( - (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || - (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) - ) - ) runs-on: macos-latest strategy: matrix: std: [11, 17] steps: - - name: Checkout pull request head (fork) - if: github.event_name == 'pull_request_target' - uses: actions/checkout@v4 - with: - repository: ${{ github.event.pull_request.head.repo.full_name }} - ref: ${{ github.event.pull_request.head.ref }} - submodules: true - - name: Checkout pull request head (same repository) - if: github.event_name == 'pull_request' - uses: actions/checkout@v4 - with: - ref: ${{ github.event.pull_request.head.sha }} - submodules: true - - name: Checkout repository - if: github.event_name == 'push' - uses: actions/checkout@v4 + - uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -196,33 +104,9 @@ jobs: if-no-files-found: ignore asan-ubsan: - if: >- - github.event_name == 'push' || - ( - github.event_name != 'push' && - ( - (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || - (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) - ) - ) runs-on: ubuntu-latest steps: - - name: Checkout pull request head (fork) - if: github.event_name == 'pull_request_target' - uses: actions/checkout@v4 - with: - repository: ${{ github.event.pull_request.head.repo.full_name }} - ref: ${{ github.event.pull_request.head.ref }} - submodules: true - - name: Checkout pull request head (same repository) - if: github.event_name == 'pull_request' - uses: actions/checkout@v4 - with: - ref: ${{ github.event.pull_request.head.sha }} - submodules: true - - name: Checkout repository - if: github.event_name == 'push' - uses: actions/checkout@v4 + - uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -234,35 +118,11 @@ jobs: run: ctest --test-dir build --output-on-failure tsan: - if: >- - github.event_name == 'push' || - ( - github.event_name != 'push' && - ( - (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || - (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) - ) - ) runs-on: ubuntu-latest env: LOGIT_PROFILE: thread steps: - - name: Checkout pull request head (fork) - if: github.event_name == 'pull_request_target' - uses: actions/checkout@v4 - with: - repository: ${{ github.event.pull_request.head.repo.full_name }} - ref: ${{ github.event.pull_request.head.ref }} - submodules: true - - name: Checkout pull request head (same repository) - if: github.event_name == 'pull_request' - uses: actions/checkout@v4 - with: - ref: ${{ github.event.pull_request.head.sha }} - submodules: true - - name: Checkout repository - if: github.event_name == 'push' - uses: actions/checkout@v4 + - uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -274,35 +134,11 @@ jobs: run: ctest --test-dir build --output-on-failure vcpkg-install: - if: >- - github.event_name == 'push' || - ( - github.event_name != 'push' && - ( - (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || - (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) - ) - ) runs-on: ubuntu-latest env: VCPKG_TAG: '2024.09.30' steps: - - name: Checkout pull request head (fork) - if: github.event_name == 'pull_request_target' - uses: actions/checkout@v4 - with: - repository: ${{ github.event.pull_request.head.repo.full_name }} - ref: ${{ github.event.pull_request.head.ref }} - submodules: true - - name: Checkout pull request head (same repository) - if: github.event_name == 'pull_request' - uses: actions/checkout@v4 - with: - ref: ${{ github.event.pull_request.head.sha }} - submodules: true - - name: Checkout repository - if: github.event_name == 'push' - uses: actions/checkout@v4 + - uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive @@ -349,33 +185,9 @@ jobs: if-no-files-found: ignore emscripten: - if: >- - github.event_name == 'push' || - ( - github.event_name != 'push' && - ( - (github.event_name == 'pull_request' && github.event.pull_request.head.repo.full_name == github.repository) || - (github.event_name == 'pull_request_target' && github.event.pull_request.head.repo.full_name != github.repository) - ) - ) runs-on: ubuntu-latest steps: - - name: Checkout pull request head (fork) - if: github.event_name == 'pull_request_target' - uses: actions/checkout@v4 - with: - repository: ${{ github.event.pull_request.head.repo.full_name }} - ref: ${{ github.event.pull_request.head.ref }} - submodules: true - - name: Checkout pull request head (same repository) - if: github.event_name == 'pull_request' - uses: actions/checkout@v4 - with: - ref: ${{ github.event.pull_request.head.sha }} - submodules: true - - name: Checkout repository - if: github.event_name == 'push' - uses: actions/checkout@v4 + - uses: actions/checkout@v4 with: submodules: true - run: git submodule update --init --recursive From 4c4d15c38dc8305575c5cabed3ef71d4652d9518 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 04:04:14 +0300 Subject: [PATCH 13/17] revert(ci): restore bench throttle Reset the CI workflow to commit 728c7a5c742a3a81da1ecbbe0f841d6f4f88021a so benchmark jobs, timeout, and stable branch trigger return. --- .github/workflows/ci.yml | 16 +++++++++++++++- 1 file changed, 15 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b009f52..7592ab4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -2,7 +2,7 @@ name: CI on: push: - branches: [ main ] + branches: [ main, stable ] pull_request: branches: [ main ] @@ -25,6 +25,20 @@ jobs: run: cmake --install build --prefix install - name: Test run: ctest --test-dir build --output-on-failure + - name: Configure benchmarks + if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + run: cmake -S . -B build-bench -DLOGIT_BENCH_ENABLE=ON -DLOGIT_BENCH_WITH_SPDLOG=ON -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 + - name: Run latency benchmarks + if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + timeout-minutes: 20 + env: + LOGIT_BENCH_TIMEOUT_SEC: 900 + LOGIT_BENCH_TOTAL: 20000 + LOGIT_BENCH_WARMUP: 2000 + run: ./build-bench/logit_bench - name: Configure consumer project run: cmake -S tests/install_consumer -B build-consumer -DCMAKE_PREFIX_PATH=${{ github.workspace }}/install -DCMAKE_CXX_STANDARD=${{ matrix.std }} - name: Build consumer project From 08db148fed2c55e6ba5e41bd14e3bd05937770b6 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 04:45:11 +0300 Subject: [PATCH 14/17] fix(bench): add timestamped logs and watchdog progress Print timestamps for every bench log line, refresh the watchdog when output appears, and fail only after prolonged inactivity so the run no longer times out mid-execution. --- .github/workflows/ci.yml | 5 ++ bench/CMakeLists.txt | 10 +++ bench/logit_bench.cpp | 146 +++++++++++++++++++++++++++++++++++---- 3 files changed, 149 insertions(+), 12 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index fd1daf4..7592ab4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -33,6 +33,11 @@ jobs: run: cmake --build build-bench --target logit_bench - name: Run latency benchmarks if: ${{ github.event_name == 'pull_request' || (github.event_name == 'push' && github.ref == 'refs/heads/stable') }} + timeout-minutes: 20 + env: + LOGIT_BENCH_TIMEOUT_SEC: 900 + LOGIT_BENCH_TOTAL: 20000 + LOGIT_BENCH_WARMUP: 2000 run: ./build-bench/logit_bench - name: Configure consumer project run: cmake -S tests/install_consumer -B build-consumer -DCMAKE_PREFIX_PATH=${{ github.workspace }}/install -DCMAKE_CXX_STANDARD=${{ matrix.std }} diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index 60f4d17..ebffc7c 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -13,6 +13,16 @@ target_include_directories(logit_bench PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}) target_compile_features(logit_bench PRIVATE cxx_std_17) +set_target_properties(logit_bench PROPERTIES + RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR} +) + +foreach(config IN ITEMS DEBUG RELEASE RELWITHDEBINFO MINSIZEREL) + set_target_properties(logit_bench PROPERTIES + RUNTIME_OUTPUT_DIRECTORY_${config} ${CMAKE_BINARY_DIR} + ) +endforeach() + target_link_libraries(logit_bench PRIVATE log-it-cpp::log-it-cpp) if(LOGIT_BENCH_WITH_SPDLOG) diff --git a/bench/logit_bench.cpp b/bench/logit_bench.cpp index 4fd8236..3f1c39f 100644 --- a/bench/logit_bench.cpp +++ b/bench/logit_bench.cpp @@ -1,17 +1,21 @@ #include +#include #include #include +#include #include #include #include #include #include +#include #include #include #include #include #include #include +#include #include "LatencyRecorder.hpp" #include "Scenario.hpp" @@ -24,6 +28,8 @@ namespace logit_bench { namespace { +std::atomic* g_watchdog_progress = nullptr; + std::string make_message(std::size_t bytes, std::size_t index) { if (bytes == 0) return {}; const char fill = static_cast('A' + static_cast(index % 26)); @@ -41,6 +47,44 @@ std::size_t get_env_size_t(const char* name, std::size_t def) { return def; } +std::uint64_t steady_now_ns() { + const auto now_tp = std::chrono::steady_clock::now().time_since_epoch(); + return std::chrono::duration_cast(now_tp).count(); +} + +std::string format_timestamp() { + const auto now = std::chrono::system_clock::now(); + const auto time = std::chrono::system_clock::to_time_t(now); + std::tm tm{}; +#ifdef _WIN32 + localtime_s(&tm, &time); +#else + localtime_r(&time, &tm); +#endif + const auto ms = std::chrono::duration_cast( + now.time_since_epoch()) % 1000; + std::ostringstream oss; + oss << std::put_time(&tm, "%Y-%m-%d %H:%M:%S") + << '.' << std::setw(3) << std::setfill('0') << ms.count(); + return oss.str(); +} + +void touch_watchdog() { + if (g_watchdog_progress) { + g_watchdog_progress->store(steady_now_ns(), std::memory_order_relaxed); + } +} + +void log_info(const std::string& message) { + std::cout << "[logit_bench " << format_timestamp() << "] " << message << std::endl; + touch_watchdog(); +} + +void log_error(const std::string& message) { + std::cerr << "[logit_bench " << format_timestamp() << "] " << message << std::endl; + touch_watchdog(); +} + /** * Run a workload: * - producers start together (barrier), @@ -130,10 +174,48 @@ ScenarioResult execute_scenario( adapter.prepare(scenario, recorder); // Warm-up (no recording, no duration). + { + std::ostringstream oss; + oss << "Warm-up start lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << warmup_messages; + log_info(oss.str()); + } run_workload(adapter, recorder, scenario, warmup_messages, false, false); + { + std::ostringstream oss; + oss << "Warm-up completed lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes; + log_info(oss.str()); + } // Measured run. + { + std::ostringstream oss; + oss << "Measure start lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << scenario.total_messages; + log_info(oss.str()); + } const auto dur = run_workload(adapter, recorder, scenario, scenario.total_messages, true, true); + { + std::ostringstream oss; + oss << "Measure completed lib=" << adapter.library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes; + log_info(oss.str()); + } const auto sum = recorder.finalize(); double thr = 0.0; @@ -179,17 +261,19 @@ void print_summary( const Scenario& scenario, const ScenarioResult& result) { - std::cout << library - << " async=" << (scenario.async ? '1' : '0') - << " sink=" << sink_name(scenario.sink) - << " producers=" << scenario.producers - << " bytes=" << scenario.message_bytes - << " total=" << scenario.total_messages - << " p50=" << result.summary.p50_ns - << "ns p99=" << result.summary.p99_ns - << "ns p999=" << result.summary.p999_ns - << "ns throughput=" << std::fixed << std::setprecision(2) - << result.throughput << " msg/s\n"; + std::ostringstream oss; + oss << library + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << scenario.total_messages + << " p50=" << result.summary.p50_ns + << "ns p99=" << result.summary.p99_ns + << "ns p999=" << result.summary.p999_ns + << "ns throughput=" << std::fixed << std::setprecision(2) + << result.throughput << " msg/s"; + log_info(oss.str()); } } // namespace @@ -197,6 +281,10 @@ void print_summary( int main() { using namespace logit_bench; + std::atomic watchdog_done{false}; + std::thread watchdog; + std::atomic watchdog_progress{steady_now_ns()}; + g_watchdog_progress = &watchdog_progress; try { std::vector> adapters; adapters.emplace_back(std::make_unique()); @@ -213,6 +301,24 @@ int main() { // Totals (can be overridden by env): const std::size_t total_messages = get_env_size_t("LOGIT_BENCH_TOTAL", 200000); const std::size_t warmup_messages = get_env_size_t("LOGIT_BENCH_WARMUP", 4096); + const std::size_t timeout_seconds = get_env_size_t("LOGIT_BENCH_TIMEOUT_SEC", 600); + + if (timeout_seconds > 0) { + watchdog = std::thread([timeout_seconds, &watchdog_done, &watchdog_progress]() { + const auto timeout = std::chrono::seconds(timeout_seconds); + while (!watchdog_done.load(std::memory_order_relaxed)) { + const auto last_ns = watchdog_progress.load(std::memory_order_relaxed); + const auto last_tp = std::chrono::steady_clock::time_point(std::chrono::nanoseconds(last_ns)); + if (std::chrono::steady_clock::now() - last_tp >= timeout) { + log_error(std::string("Timeout reached after ") + std::to_string(timeout_seconds) + + " seconds without progress. Terminating benchmark."); + std::cerr.flush(); + std::_Exit(124); + } + std::this_thread::sleep_for(std::chrono::milliseconds(200)); + } + }); + } for (auto& adapter : adapters) { for (bool async_mode : async_modes) { @@ -226,6 +332,16 @@ int main() { scenario.message_bytes = msg_bytes; scenario.total_messages = total_messages; + { + std::ostringstream oss; + oss << "Scenario start lib=" << adapter->library_name() + << " async=" << (scenario.async ? '1' : '0') + << " sink=" << sink_name(scenario.sink) + << " producers=" << scenario.producers + << " bytes=" << scenario.message_bytes + << " total=" << scenario.total_messages; + log_info(oss.str()); + } auto result = execute_scenario(*adapter, scenario, warmup_messages); append_csv(adapter->library_name(), scenario, result.summary, result.throughput); print_summary(adapter->library_name(), scenario, result); @@ -234,9 +350,15 @@ int main() { } } } + watchdog_done.store(true, std::memory_order_relaxed); + if (watchdog.joinable()) watchdog.join(); } catch (const std::exception& ex) { - std::cerr << "Benchmark failed: " << ex.what() << std::endl; + watchdog_done.store(true, std::memory_order_relaxed); + if (watchdog.joinable()) watchdog.join(); + log_error(std::string("Benchmark failed: ") + ex.what()); + g_watchdog_progress = nullptr; return 1; } + g_watchdog_progress = nullptr; return 0; } From 1bfd6856310621177e0e39672edffd3bffaeb701 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Fri, 19 Sep 2025 04:54:08 +0300 Subject: [PATCH 15/17] fix(bench): refresh watchdog and extend timeout Update the benchmark watchdog while producers run so slow scenarios keep reporting progress, bump the default timeout to twenty minutes, and keep the watchdog alive through adapter flushes. --- bench/logit_bench.cpp | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/bench/logit_bench.cpp b/bench/logit_bench.cpp index 3f1c39f..7cacdf1 100644 --- a/bench/logit_bench.cpp +++ b/bench/logit_bench.cpp @@ -29,6 +29,7 @@ namespace logit_bench { namespace { std::atomic* g_watchdog_progress = nullptr; +constexpr std::size_t k_watchdog_stride = 256; std::string make_message(std::size_t bytes, std::size_t index) { if (bytes == 0) return {}; @@ -127,6 +128,7 @@ std::chrono::nanoseconds run_workload( for (std::size_t i = 0; i < scenario.producers; ++i) { threads.emplace_back([&, i]() { std::string message = make_message(scenario.message_bytes, i); + std::size_t watchdog_counter = 0; { std::unique_lock lk(start_mx); ++ready; @@ -136,7 +138,12 @@ std::chrono::nanoseconds run_workload( for (std::size_t n = 0; n < per_thread[i]; ++n) { auto token = recorder.begin(record_latency); adapter.log(token, message); + ++watchdog_counter; + if ((watchdog_counter & (k_watchdog_stride - 1)) == 0) { + touch_watchdog(); + } } + touch_watchdog(); }); } @@ -151,6 +158,7 @@ std::chrono::nanoseconds run_workload( for (auto& th : threads) th.join(); adapter.flush(); + touch_watchdog(); if (!measure_duration) return std::chrono::nanoseconds(0); auto t1 = std::chrono::steady_clock::now(); @@ -301,7 +309,7 @@ int main() { // Totals (can be overridden by env): const std::size_t total_messages = get_env_size_t("LOGIT_BENCH_TOTAL", 200000); const std::size_t warmup_messages = get_env_size_t("LOGIT_BENCH_WARMUP", 4096); - const std::size_t timeout_seconds = get_env_size_t("LOGIT_BENCH_TIMEOUT_SEC", 600); + const std::size_t timeout_seconds = get_env_size_t("LOGIT_BENCH_TIMEOUT_SEC", 1200); if (timeout_seconds > 0) { watchdog = std::thread([timeout_seconds, &watchdog_done, &watchdog_progress]() { From 79dffd524fe41fc280f71229d14938b3882e2990 Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 20 Sep 2025 02:49:34 +0300 Subject: [PATCH 16/17] refactor: added LOGIT_SET_MAX_QUEUE(total_messages) --- bench/logit_bench.cpp | 2 ++ 1 file changed, 2 insertions(+) diff --git a/bench/logit_bench.cpp b/bench/logit_bench.cpp index d0e403b..98b2974 100644 --- a/bench/logit_bench.cpp +++ b/bench/logit_bench.cpp @@ -313,6 +313,8 @@ int main() { const std::size_t warmup_messages = get_env_size_t("LOGIT_BENCH_WARMUP", 4096); const std::size_t timeout_seconds = get_env_size_t("LOGIT_BENCH_TIMEOUT_SEC", 1200); + LOGIT_SET_MAX_QUEUE(total_messages); + if (timeout_seconds > 0) { watchdog = std::thread([timeout_seconds, &watchdog_done, &watchdog_progress]() { const auto timeout = std::chrono::seconds(timeout_seconds); From 67d26cf8fe1550c8f52902ff7d23bc4393c5d63e Mon Sep 17 00:00:00 2001 From: Aster Seker Date: Sat, 20 Sep 2025 03:01:13 +0300 Subject: [PATCH 17/17] refactor: added in LogItAdapter.hpp --- bench/adapters/LogItAdapter.hpp | 1 + 1 file changed, 1 insertion(+) diff --git a/bench/adapters/LogItAdapter.hpp b/bench/adapters/LogItAdapter.hpp index f949081..bc5467b 100644 --- a/bench/adapters/LogItAdapter.hpp +++ b/bench/adapters/LogItAdapter.hpp @@ -2,6 +2,7 @@ #include #include +#include #include "ILoggerAdapter.hpp"