feat: Allow logging path to be warmed

bench/Log.bm.cpp

@@ -43,9 +43,11 @@ class FileLogger final : public Logger {
 
   private:
     void do_write_log(WallTime /*ts*/, LogLevel /*level*/, int /*tid*/, LogMsgPtr&& msg,
-                      size_t size) noexcept override
+                      size_t size, bool warming_fake) noexcept override
     {
-        os::write(*fh_, msg.get(), size);
+        if (!warming_fake) {
+            os::write(*fh_, msg.get(), size);
+        }
     }
     io::FileHandle fh_;
 };

toolbox/sys/Log.ut.cpp

@@ -42,13 +42,15 @@ StreamT& operator<<(StreamT& os, const Foo<int, int>& val)
 
 struct TestLogger final : Logger {
     void do_write_log(WallTime /*ts*/, LogLevel level, int /*tid*/, LogMsgPtr&& msg,
-                      size_t size) noexcept override
+                      size_t size, bool warming_fake) noexcept override
     {
         const auto finally = make_finally([&]() noexcept {
             log_buf_pool().bounded_push(std::move(msg));
         });
-        last_level = level;
-        last_msg.assign(static_cast<const char*>(msg.get()), size);
+        if (!warming_fake) {
+            last_level = level;
+            last_msg.assign(static_cast<const char*>(msg.get()), size);
+        }
     }
     LogLevel last_level{};
     string last_msg{};

toolbox/sys/Logger.cpp

@@ -77,20 +77,24 @@ static LogBufPoolWrapper log_buf_pool_{};
 
 class NullLogger final : public Logger {
     void do_write_log(WallTime /*ts*/, LogLevel /*level*/, int /*tid*/, LogMsgPtr&& msg,
-                      size_t /*size*/) noexcept override
+                      size_t /*size*/, bool /*warming_fake*/) noexcept override
     {
         log_buf_pool().bounded_push(std::move(msg));
     }
 } null_logger_;
 
 class StdLogger final : public Logger {
     void do_write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg,
-                      size_t size) noexcept override
+                      size_t size, bool warming_fake) noexcept override
     {
         const auto finally = make_finally([&]() noexcept {
             log_buf_pool().bounded_push(std::move(msg));
         });
 
+        if (warming_fake) [[unlikely]] {
+            return;
+        }
+
         const auto t{WallClock::to_time_t(ts)};
         tm tm;
         localtime_r(&t, &tm);
@@ -124,12 +128,16 @@ class StdLogger final : public Logger {
 
 class SysLogger final : public Logger {
     void do_write_log(WallTime /*ts*/, LogLevel level, int /*tid*/, LogMsgPtr&& msg,
-                      size_t size) noexcept override
+                      size_t size, bool warming_fake) noexcept override
     {
         const auto finally = make_finally([&]() noexcept {
             log_buf_pool().bounded_push(std::move(msg));
         });
 
+        if (warming_fake) [[unlikely]] {
+            return;
+        }
+
         int prio;
         switch (level) {
         case LogLevel::None:
@@ -162,6 +170,7 @@ class SysLogger final : public Logger {
 // Global log level and logger function.
 atomic<LogLevel> level_{LogLevel::Info};
 atomic<Logger*> logger_{&std_logger_};
+thread_local bool warming_mode_{false};
 
 inline LogLevel acquire_level() noexcept
 {
@@ -180,6 +189,16 @@ LogBufPool& log_buf_pool() noexcept
     return log_buf_pool_.pool;
 }
 
+void set_log_warming_mode(bool enabled) noexcept
+{
+    warming_mode_ = enabled;
+}
+
+bool log_warming_mode_enabled() noexcept
+{
+    return warming_mode_;
+}
+
 Logger& null_logger() noexcept
 {
     return null_logger_;
@@ -222,7 +241,8 @@ Logger& set_logger(Logger& logger) noexcept
 
 void write_log(WallTime ts, LogLevel level, LogMsgPtr&& msg, std::size_t size) noexcept
 {
-    acquire_logger().write_log(ts, level, static_cast<int>(gettid()), std::move(msg), size);
+    acquire_logger().write_log(ts, level, static_cast<int>(gettid()), std::move(msg), size,
+                               warming_mode_);
 }
 
 Logger::~Logger() = default;
@@ -240,9 +260,16 @@ AsyncLogger::~AsyncLogger()
 void AsyncLogger::write_all_messages()
 {
     Task t;
+    int fake_count = 0;
+
     while (tq_.pop(t)) {
-        logger_.write_log(t.ts, t.level, t.tid, LogMsgPtr{t.msg}, t.size);
+        if (t.msg != nullptr) {
+            logger_.write_log(t.ts, t.level, t.tid, LogMsgPtr{t.msg}, t.size, false);
+        } else {
+            fake_count++;
+        }
     }
+    fake_pushed_count_.fetch_sub(fake_count, std::memory_order_relaxed);
 }
 
 bool AsyncLogger::run()
@@ -259,19 +286,41 @@ void AsyncLogger::stop()
 }
 
 void AsyncLogger::do_write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg,
-                               size_t size) noexcept
+                               size_t size, bool warming_fake) noexcept
 {
     char* const msg_ptr = msg.release();
+    auto push_to_queue = [&](char* ptr) -> bool {
+        return tq_.push(Task{.ts = ts, .level = level, .tid = tid, .msg = ptr, .size = size});
+    };
     try {
-        if (tq_.push(Task{.ts = ts, .level = level, .tid = tid, .msg = msg_ptr, .size = size})) {
+        if (warming_fake) [[unlikely]] {
+            const auto cnt = fake_pushed_count_.load(std::memory_order_relaxed);
+            const auto d = ts - last_time_fake_pushed_.load(std::memory_order_relaxed);
+
+            constexpr Millis FakePushInterval = 10ms;
+            constexpr int MaxPushedFakeCount = 25;
+
+            // It's possible that `last_time_fake_pushed_` OR `fake_pushed_count_` have since
+            // been modified by another thread (since the load). In this extremely rare case, a back
+            // to back push to the queue will occur. But that's fine -- not a big deal, these limits
+            // are not supposed to absolute hard limits, they are just to ensure that the queue is
+            // not flooded with "fake" entries. This compromise allows keeping the implementation
+            // simple, otherwise more complicated code is required to deal with this case.
+            if (duration_cast<Millis>(d) >= FakePushInterval && cnt < MaxPushedFakeCount) {
+                if (push_to_queue(nullptr)) {
+                    last_time_fake_pushed_.store(ts, std::memory_order_relaxed);
+                    fake_pushed_count_.fetch_add(1, std::memory_order_relaxed);
+                }
+            }
+        } else if (push_to_queue(msg_ptr)) [[likely]] {
             // Successfully pushed the task to the queue, release ownership of msg_ptr.
             return;
         }
     } catch (const std::bad_alloc&) {
         // Catching `std::bad_alloc` here is *defensive plumbing* that keeps the logger non-throwing
         // and prevents crashes caused by an out-of-memory situation during rare log-burst spikes.
     }
-    // Failed to push the task, restore ownership of msg_ptr.
+    // Failed to push the task OR warming fake, restore ownership of msg_ptr.
     log_buf_pool().bounded_push(LogMsgPtr{msg_ptr});
 }
 

toolbox/sys/Logger.hpp

@@ -58,6 +58,13 @@ using LogBufPool = boost::lockfree::stack<LogMsgPtr, boost::lockfree::capacity<L
 /// A pool of log buffers, eliminating the need for dynamic memory allocations when logging
 TOOLBOX_API LogBufPool& log_buf_pool() noexcept;
 
+/// Enables log warming mode. In this mode, the logging path is exercised without producing actual
+/// log output. This is a per-thread setting, so other threads will be able to log as normal.
+TOOLBOX_API void set_log_warming_mode(bool enabled) noexcept;
+
+/// Returns true if log warming mode is enabled.
+TOOLBOX_API bool log_warming_mode_enabled() noexcept;
+
 /// Null logger. This logger does nothing and is effectively /dev/null.
 TOOLBOX_API Logger& null_logger() noexcept;
 
@@ -114,14 +121,15 @@ class TOOLBOX_API Logger {
     Logger(Logger&&) noexcept = default;
     Logger& operator=(Logger&&) noexcept = default;
 
-    void write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg, std::size_t size) noexcept
+    void write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg, std::size_t size,
+                   bool warming_fake) noexcept
     {
-        do_write_log(ts, level, tid, std::move(msg), size);
+        do_write_log(ts, level, tid, std::move(msg), size, warming_fake);
     }
 
   protected:
     virtual void do_write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg,
-                              std::size_t size) noexcept
+                              std::size_t size, bool warming_fake) noexcept
         = 0;
 };
 
@@ -156,11 +164,16 @@ class TOOLBOX_API AsyncLogger : public Logger {
   private:
     void write_all_messages();
     void do_write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg,
-                      std::size_t size) noexcept override;
+                      std::size_t size, bool warming_fake) noexcept override;
 
     Logger& logger_;
     boost::lockfree::queue<Task, boost::lockfree::fixed_sized<false>> tq_{512};
     std::atomic<bool> stop_{false};
+
+    // warming mode variables
+    std::atomic<int> fake_pushed_count_{0};
+    std::atomic<WallTime> last_time_fake_pushed_{};
+    static_assert(std::atomic<WallTime>::is_always_lock_free, "atomic not lock free");
 };
 
 /// ScopedLogLevel provides a convenient RAII-style utility for setting the log-level for the