From 4aa2ca94de26bfd9cbf3147b06b602a13e353e19 Mon Sep 17 00:00:00 2001 From: Ayaz Salikhov Date: Thu, 7 Aug 2025 19:46:12 +0100 Subject: [PATCH] perf: Add benchmark for Logger (#2407) --- .codecov.yml | 1 + .github/actions/code_coverage/action.yml | 1 + benchmarks/CMakeLists.txt | 4 +- benchmarks/util/log/LoggerBenchmark.cpp | 127 +++++++++++++++++++++++ src/util/log/Logger.cpp | 28 ++--- src/util/log/Logger.hpp | 16 +++ 6 files changed, 164 insertions(+), 13 deletions(-) create mode 100644 benchmarks/util/log/LoggerBenchmark.cpp diff --git a/.codecov.yml b/.codecov.yml index 5fffb1c2..5d56c0b3 100644 --- a/.codecov.yml +++ b/.codecov.yml @@ -16,6 +16,7 @@ coverage: # # More info: https://github.com/XRPLF/clio/pull/2066 ignore: + - "benchmarks" - "tests" - "src/data/cassandra/" - "src/data/CassandraBackend.hpp" diff --git a/.github/actions/code_coverage/action.yml b/.github/actions/code_coverage/action.yml index 79037207..9c91d2e0 100644 --- a/.github/actions/code_coverage/action.yml +++ b/.github/actions/code_coverage/action.yml @@ -15,6 +15,7 @@ runs: shell: bash run: | gcovr \ + -e benchmarks \ -e tests \ -e src/data/cassandra \ -e src/data/CassandraBackend.hpp \ diff --git a/benchmarks/CMakeLists.txt b/benchmarks/CMakeLists.txt index ec9a45e2..a2fc070b 100644 --- a/benchmarks/CMakeLists.txt +++ b/benchmarks/CMakeLists.txt @@ -7,10 +7,12 @@ target_sources( Playground.cpp # ExecutionContext util/async/ExecutionContextBenchmarks.cpp + # Logger + util/log/LoggerBenchmark.cpp ) include(deps/gbench) target_include_directories(clio_benchmark PRIVATE .) -target_link_libraries(clio_benchmark PUBLIC clio_etl benchmark::benchmark_main) +target_link_libraries(clio_benchmark PUBLIC clio_util benchmark::benchmark_main) set_target_properties(clio_benchmark PROPERTIES RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}) diff --git a/benchmarks/util/log/LoggerBenchmark.cpp b/benchmarks/util/log/LoggerBenchmark.cpp new file mode 100644 index 00000000..8d932044 --- /dev/null +++ b/benchmarks/util/log/LoggerBenchmark.cpp @@ -0,0 +1,127 @@ +//------------------------------------------------------------------------------ +/* + This file is part of clio: https://github.com/XRPLF/clio + Copyright (c) 2025, the clio developers. + + Permission to use, copy, modify, and distribute this software for any + purpose with or without fee is hereby granted, provided that the above + copyright notice and this permission notice appear in all copies. + + THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. +*/ +//============================================================================== + +#include "util/config/ConfigDefinition.hpp" +#include "util/log/Logger.hpp" +#include "util/prometheus/Prometheus.hpp" + +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include + +using namespace util; + +struct BenchmarkLoggingInitializer { + static constexpr auto kLOG_FORMAT = "%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%"; + + static void + initFileLogging(LogService::FileLoggingParams const& params) + { + boost::log::add_common_attributes(); + std::filesystem::create_directories(params.logDir); + LogService::initFileLogging(params, kLOG_FORMAT); + } +}; + +namespace { + +std::string +uniqueLogDir() +{ + auto const epochTime = std::chrono::high_resolution_clock::now().time_since_epoch(); + auto const tmpDir = std::filesystem::temp_directory_path(); + std::string const dirName = + "logs_" + std::to_string(std::chrono::duration_cast(epochTime).count()); + return tmpDir / "clio_benchmark" / dirName; +} + +} // anonymous namespace + +static void +benchmarkConcurrentFileLogging(benchmark::State& state) +{ + auto const numThreads = static_cast(state.range(0)); + auto const messagesPerThread = static_cast(state.range(1)); + + PrometheusService::init(config::getClioConfig()); + + auto const logDir = uniqueLogDir(); + for (auto _ : state) { + state.PauseTiming(); + std::filesystem::remove_all(logDir); + + BenchmarkLoggingInitializer::initFileLogging({ + .logDir = logDir, + .rotationSizeMB = 1, + .dirMaxSizeMB = 10, + .rotationHours = 24, + }); + state.ResumeTiming(); + + std::vector threads; + threads.reserve(numThreads); + + std::chrono::high_resolution_clock::time_point start; + std::barrier barrier(numThreads, [&start]() { start = std::chrono::high_resolution_clock::now(); }); + + for (size_t threadNum = 0; threadNum < numThreads; ++threadNum) { + threads.emplace_back([threadNum, messagesPerThread, &barrier]() { + barrier.arrive_and_wait(); + + Logger threadLogger("Thread_" + std::to_string(threadNum)); + + for (size_t messageNum = 0; messageNum < messagesPerThread; ++messageNum) { + LOG(threadLogger.info()) << "Test log message #" << messageNum; + } + }); + } + + for (auto& thread : threads) { + thread.join(); + } + boost::log::core::get()->flush(); + + auto const end = std::chrono::high_resolution_clock::now(); + + state.SetIterationTime(std::chrono::duration_cast>(end - start).count()); + } + + std::filesystem::remove_all(logDir); + + auto const totalMessages = numThreads * messagesPerThread; + state.counters["TotalMessagesRate"] = benchmark::Counter(totalMessages, benchmark::Counter::kIsRate); + state.counters["Threads"] = numThreads; + state.counters["MessagesPerThread"] = messagesPerThread; +} + +BENCHMARK(benchmarkConcurrentFileLogging) + ->ArgsProduct({ + {1, 2, 4, 8}, // Number of threads + {500, 1000, 2000, 100000}, // Messages per thread + }) + ->UseManualTime() + ->Unit(benchmark::kMillisecond); diff --git a/src/util/log/Logger.cpp b/src/util/log/Logger.cpp index 92d6cdb8..03b2e765 100644 --- a/src/util/log/Logger.cpp +++ b/src/util/log/Logger.cpp @@ -168,21 +168,18 @@ initConsoleLogging(bool logToConsole, std::string const& format) * @param format The log format string. * @param dirPath The directory path where log files will be stored. */ -static void -initFileLogging( - config::ClioConfigDefinition const& config, - std::string const& format, - std::filesystem::path const& dirPath -) +void +LogService::initFileLogging(FileLoggingParams const& params, std::string const& format) { namespace keywords = boost::log::keywords; namespace sinks = boost::log::sinks; - auto const rotationPeriod = config.get("log_rotation_hour_interval"); - // the below are taken from user in MB, but boost::log::add_file_log needs it to be in bytes - auto const rotationSize = mbToBytes(config.get("log_rotation_size")); - auto const dirSize = mbToBytes(config.get("log_directory_max_size")); + auto const rotationSize = mbToBytes(params.rotationSizeMB); + auto const dirSize = mbToBytes(params.dirMaxSizeMB); + + auto const dirPath = std::filesystem::path{params.logDir}; + auto fileSink = boost::log::add_file_log( keywords::file_name = dirPath / "clio.log", keywords::target_file_name = dirPath / "clio_%Y-%m-%d_%H-%M-%S.log", @@ -190,7 +187,8 @@ initFileLogging( keywords::format = format, keywords::open_mode = std::ios_base::app, keywords::rotation_size = rotationSize, - keywords::time_based_rotation = sinks::file::rotation_at_time_interval(boost::posix_time::hours(rotationPeriod)) + keywords::time_based_rotation = + sinks::file::rotation_at_time_interval(boost::posix_time::hours(params.rotationHours)) ); fileSink->locked_backend()->set_file_collector( sinks::file::make_collector(keywords::target = dirPath, keywords::max_size = dirSize) @@ -274,7 +272,13 @@ LogService::init(config::ClioConfigDefinition const& config) }; } } - initFileLogging(config, format, dirPath); + FileLoggingParams params{ + .logDir = logDir.value(), + .rotationSizeMB = config.get("log_rotation_size"), + .dirMaxSizeMB = config.get("log_directory_max_size"), + .rotationHours = config.get("log_rotation_hour_interval") + }; + initFileLogging(params, format); } // get default severity, can be overridden per channel using the `log_channels` array diff --git a/src/util/log/Logger.hpp b/src/util/log/Logger.hpp index ba1d8c60..ce10cf3d 100644 --- a/src/util/log/Logger.hpp +++ b/src/util/log/Logger.hpp @@ -51,6 +51,8 @@ #include #include +struct BenchmarkLoggingInitializer; + namespace util { namespace config { @@ -362,6 +364,20 @@ public: */ [[nodiscard]] static bool enabled(); + +private: + struct FileLoggingParams { + std::string logDir; + + uint32_t rotationSizeMB; + uint32_t dirMaxSizeMB; + uint32_t rotationHours; + }; + + friend struct ::BenchmarkLoggingInitializer; + + static void + initFileLogging(FileLoggingParams const& params, std::string const& format); }; }; // namespace util