feat: Use spdlog logger

Author: mathbunnyru

.github/workflows/nightly.yml

@@ -64,7 +64,7 @@ jobs:
       disable_cache: true
 
   analyze_build_time:
-    name: Analyze Build Time
+    name: Analyze Build Time using Clang Build Analyzer
 
     strategy:
       fail-fast: false

CMakeLists.txt

@@ -58,6 +58,7 @@ include(deps/Threads)
 include(deps/libfmt)
 include(deps/cassandra)
 include(deps/libbacktrace)
+include(deps/spdlog)
 
 add_subdirectory(src)
 add_subdirectory(tests)

benchmarks/CMakeLists.txt

@@ -14,5 +14,5 @@ target_sources(
 include(deps/gbench)
 
 target_include_directories(clio_benchmark PRIVATE .)
-target_link_libraries(clio_benchmark PUBLIC clio_util benchmark::benchmark_main)
+target_link_libraries(clio_benchmark PUBLIC clio_util benchmark::benchmark_main spdlog::spdlog)
 set_target_properties(clio_benchmark PROPERTIES RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR})

benchmarks/util/log/LoggerBenchmark.cpp

@@ -22,28 +22,36 @@
 #include "util/prometheus/Prometheus.hpp"
 
 #include <benchmark/benchmark.h>
-#include <boost/log/core/core.hpp>
-#include <boost/log/utility/setup/common_attributes.hpp>
+#include <spdlog/async.h>
+#include <spdlog/async_logger.h>
+#include <spdlog/spdlog.h>
 
 #include <barrier>
 #include <chrono>
 #include <cstddef>
 #include <filesystem>
+#include <memory>
 #include <string>
 #include <thread>
+#include <utility>
 #include <vector>
 
 using namespace util;
 
-struct BenchmarkLoggingInitializer {
-    static constexpr auto kLOG_FORMAT = "%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%";
+static constexpr auto kLOG_FORMAT = "%Y-%m-%d %H:%M:%S.%f %^(%@) [%t] %n:%L%$ %v";
 
-    static void
-    initFileLogging(LogService::FileLoggingParams const& params)
+struct BenchmarkLoggingInitializer {
+    static std::shared_ptr<spdlog::sinks::sink>
+    createFileSink(LogService::FileLoggingParams const& params)
     {
-        boost::log::add_common_attributes();
         std::filesystem::create_directories(params.logDir);
-        LogService::initFileLogging(params, kLOG_FORMAT);
+        return LogService::createFileSink(params);
+    }
+
+    static Logger
+    getLogger(std::shared_ptr<spdlog::logger> logger)
+    {
+        return Logger(std::move(logger));
     }
 };
 
@@ -68,31 +76,40 @@ benchmarkConcurrentFileLogging(benchmark::State& state)
     auto const messagesPerThread = static_cast<size_t>(state.range(1));
 
     PrometheusService::init(config::getClioConfig());
+    spdlog::drop_all();
 
     auto const logDir = uniqueLogDir();
     for (auto _ : state) {
         state.PauseTiming();
-        std::filesystem::remove_all(logDir);
+        spdlog::init_thread_pool(8192, 1);
 
-        BenchmarkLoggingInitializer::initFileLogging({
+        auto fileSink = BenchmarkLoggingInitializer::createFileSink({
             .logDir = logDir,
-            .rotationSizeMB = 1,
-            .dirMaxSizeMB = 10,
+            .rotationSizeMB = 128,
+            .dirMaxSizeMB = 3200,
             .rotationHours = 24,
         });
-        state.ResumeTiming();
 
         std::vector<std::thread> threads;
         threads.reserve(numThreads);
 
         std::chrono::high_resolution_clock::time_point start;
-        std::barrier barrier(numThreads, [&start]() { start = std::chrono::high_resolution_clock::now(); });
+        std::barrier barrier(numThreads, [&state, &start]() {
+            state.ResumeTiming();
+            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();
+            threads.emplace_back([threadNum, messagesPerThread, fileSink, &barrier]() {
+                std::string const channel = "Thread_" + std::to_string(threadNum);
+                auto logger = std::make_shared<spdlog::async_logger>(
+                    channel, fileSink, spdlog::thread_pool(), spdlog::async_overflow_policy::block
+                );
+                logger->set_pattern(kLOG_FORMAT);
+                spdlog::register_logger(logger);
+                Logger const threadLogger = BenchmarkLoggingInitializer::getLogger(std::move(logger));
 
-                Logger const threadLogger("Thread_" + std::to_string(threadNum));
+                barrier.arrive_and_wait();
 
                 for (size_t messageNum = 0; messageNum < messagesPerThread; ++messageNum) {
                     LOG(threadLogger.info()) << "Test log message #" << messageNum;
@@ -103,14 +120,14 @@ benchmarkConcurrentFileLogging(benchmark::State& state)
         for (auto& thread : threads) {
             thread.join();
         }
-        boost::log::core::get()->flush();
 
-        auto const end = std::chrono::high_resolution_clock::now();
+        spdlog::shutdown();
 
+        auto const end = std::chrono::high_resolution_clock::now();
         state.SetIterationTime(std::chrono::duration_cast<std::chrono::duration<double>>(end - start).count());
-    }
 
-    std::filesystem::remove_all(logDir);
+        std::filesystem::remove_all(logDir);
+    }
 
     auto const totalMessages = numThreads * messagesPerThread;
     state.counters["TotalMessagesRate"] = benchmark::Counter(totalMessages, benchmark::Counter::kIsRate);
@@ -120,8 +137,10 @@ benchmarkConcurrentFileLogging(benchmark::State& state)
 
 BENCHMARK(benchmarkConcurrentFileLogging)
     ->ArgsProduct({
-        {1, 2, 4, 8},               // Number of threads
-        {500, 1000, 2000, 100000},  // Messages per thread
+        // Number of threads
+        {1, 2, 4, 8},
+        // Messages per thread
+        {10'000, 100'000, 500'000, 1'000'000},
     })
     ->UseManualTime()
     ->Unit(benchmark::kMillisecond);

cmake/deps/spdlog.cmake

@@ -0,0 +1,5 @@
+find_package(spdlog REQUIRED)
+
+if (NOT TARGET spdlog::spdlog)
+  message(FATAL_ERROR "spdlog::spdlog target not found")
+endif ()

conan.lock

@@ -5,6 +5,7 @@
         "xxhash/0.8.2#7856c968c985b2981b707ee8f2413b2b%1754325010.01",
         "xrpl/2.5.0@clio/boost-odr#f68e48da1490c0a583052e4f068ada55%1754325014.392",
         "sqlite3/3.47.0#7a0904fd061f5f8a2366c294f9387830%1754325009.708",
+        "spdlog/1.15.3#3ca0e9e6b83af4d0151e26541d140c86%1748617970.519",
         "soci/4.0.3#a9f8d773cd33e356b5879a4b0564f287%1754412158.144",
         "re2/20230301#dfd6e2bf050eb90ddd8729cfb4c844a4%1754412148.014",
         "rapidjson/cci.20220822#1b9d8c2256876a154172dc5cfbe447c6%1754325007.656",
@@ -54,4 +55,4 @@
         ]
     },
     "config_requires": []
-}
+}

conanfile.py

@@ -33,7 +33,8 @@ class ClioConan(ConanFile):
         'openssl/1.1.1v',
         'xrpl/2.5.0@clio/boost-odr',
         'zlib/1.3.1',
-        'libbacktrace/cci.20210118'
+        'libbacktrace/cci.20210118',
+        'spdlog/1.15.3',
     ]
 
     default_options = {

docs/config-description.md

@@ -439,13 +439,21 @@ This document provides a list of all available Clio configuration properties in
 - **Constraints**: The value must be one of the following: `trace`, `debug`, `info`, `warning`, `error`, `fatal`, `count`.
 - **Description**: The general logging level of Clio. This level is applied to all log channels that do not have an explicitly defined logging level.
 
-### log_format
+### spdlog_format
 
 - **Required**: True
 - **Type**: string
-- **Default value**: `%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%`
+- **Default value**: `%Y-%m-%d %H:%M:%S.%f %^(%@) [%t] %n:%L%$ %v`
 - **Constraints**: None
-- **Description**: The format string for log messages. The format is described here: <https://www.boost.org/doc/libs/1_83_0/libs/log/doc/html/log/tutorial/formatters.html>.
+- **Description**: The format string for log messages using spdlog format patterns. Documentation can be found at: <https://github.com/gabime/spdlog/wiki/Custom-formatting>.
+
+### spdlog_async
+
+- **Required**: True
+- **Type**: boolean
+- **Default value**: `True`
+- **Constraints**: None
+- **Description**: Whether spdlog is asynchronous or not.
 
 ### log_to_console
 
@@ -479,14 +487,6 @@ This document provides a list of all available Clio configuration properties in
 - **Constraints**: The minimum value is `1`. The maximum value is `4294967295`.
 - **Description**: The maximum size of the log directory in megabytes.
 
-### log_rotation_hour_interval
-
-- **Required**: True
-- **Type**: int
-- **Default value**: `12`
-- **Constraints**: The minimum value is `1`. The maximum value is `4294967295`.
-- **Description**: Represents the interval (in hours) for log rotation. If the current log file reaches this value in logging, a new log file starts.
-
 ### log_tag_style
 
 - **Required**: True

docs/examples/config/example-config.json

@@ -122,14 +122,15 @@
     "compress_reply": true
   },
   "log_level": "info",
-  // Log format (this is the default format)
-  "log_format": "%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%",
+  // Log format using spdlog format patterns (this is the default format)
+  "spdlog_format": "%Y-%m-%d %H:%M:%S.%f %^(%@) [%t] %n:%L%$ %v",
+  // Whether spdlog is asynchronous or not.
+  "spdlog_async": true,
   "log_to_console": true,
   // Clio logs to file in the specified directory only if "log_directory" is set
   // "log_directory": "./clio_log",
   "log_rotation_size": 2048,
   "log_directory_max_size": 51200,
-  "log_rotation_hour_interval": 12,
   "log_tag_style": "uint",
   "extractor_threads": 8,
   "read_only": false,

docs/logging.md

@@ -6,18 +6,26 @@ Clio provides several logging options, which all are configurable via the config
 
 The minimum level of severity at which the log message will be outputted by default. Severity options are `trace`, `debug`, `info`, `warning`, `error`, `fatal`. Defaults to `info`.
 
-## `log_format`
+## `spdlog_format`
 
-The format of log lines produced by Clio. Defaults to `"%TimeStamp% (%SourceLocation%) [%ThreadID%] %Channel%:%Severity% %Message%"`.
+The format of log lines produced by Clio using spdlog format patterns. Defaults to `"%Y-%m-%d %H:%M:%S.%f %^(%@) [%t] %n:%L%$ %v"`.
 
 Each of the variables expands like so:
 
-- `TimeStamp`: The full date and time of the log entry
-- `SourceLocation`: A partial path to the c++ file and the line number in said file (`source/file/path:linenumber`)
-- `ThreadID`: The ID of the thread the log entry is written from
-- `Channel`: The channel that this log entry was sent to
-- `Severity`: The severity (aka log level) the entry was sent at
-- `Message`: The actual log message
+- `%^`: Start color range
+- `%Y-%m-%d %H:%M:%S.%f`: The full date and time of the log entry with microsecond precision
+- `%@`: A partial path to the c++ file and the line number in said file (`source/file/path:linenumber`)
+- `%t`: The ID of the thread the log entry is written from
+- `%n`: The logger name (channel) that this log entry was sent to
+- `%l`: The severity (aka log level) the entry was sent at
+- `%$`: End color range
+- `%v`: The actual log message
+
+For more information about spdlog format patterns, see: <https://github.com/gabime/spdlog/wiki/Custom-formatting>
+
+## `spdlog_async`
+
+Whether spdlog is asynchronous or not.
 
 ## `log_channels`
 
@@ -60,13 +68,6 @@ The max size of the log file in **megabytes** before it will rotate into a small
 
 The max size of the log directory in **megabytes** before old log files will be deleted to free up space. Defaults to 50GB.
 
-## `log_rotation_hour_interval`
-
-The time interval in **hours** after the last log rotation to automatically rotate the current log file. Defaults to 12 hours.
-
-> [!NOTE]
-> Log rotation based on time occurs in conjunction with size-based log rotation. For example, if a size-based log rotation occurs, the timer for the time-based rotation will reset.
-
 ## `log_tag_style`
 
 Tag implementation to use. Must be one of: