Make log level checks lock-free via permanent loggers. (#5349)

# Description

Make log level checks lock-free via permanent loggers.

Every CLOG_* invocation fetches its respective logger instance in order
to check if we should log this line, and the getter used to be guarded
by a recursive mutex lock. So we kept serializing every disabled log
statement, which hindered parallelization for the code paths with
frequent trace/debug logs.

Now each partition has a single permanent logger, created on first use
and never destroyed or replaced (logging rotations/reconfigurations now
are done at the sink level, instead of the logger level). Additionally,
we avoid a shared ptr copy on every logger access, as we now we can just
safely return a non-owning pointer to it.

The logging level checks per logger still have to be thread-safe, as the
level may be changed in the middle of the app lifetime. We remove
SPDLOG_NO_ATOMIC_LEVELS to achieve that, which simply uses very fast
relaxed atomic checks.

This doesn't have too large impact right now (~-3ms on the local
benchmarks), but it will become more meaningful as we land more apply
path parallelization.

# Checklist
- [ ] Reviewed the
[contributing](https://github.com/stellar/stellar-core/blob/master/CONTRIBUTING.md#submitting-changes)
document
- [ ] Rebased on top of master (no merge commits)
- [ ] Ran `clang-format` v8.0.0 (via `make format` or the Visual Studio
extension)
- [ ] Compiles
- [ ] Ran all tests
- [ ] If change impacts performance, include supporting evidence per the
[performance
document](https://github.com/stellar/stellar-core/blob/master/performance-eval/performance-eval.md)

Author: dmkozh

src/util/Logging.cpp

@@ -11,6 +11,7 @@
 #include <fmt/chrono.h>
 #include <fstream>
 #include <spdlog/sinks/basic_file_sink.h>
+#include <spdlog/sinks/dist_sink.h>
 #include <spdlog/sinks/stdout_color_sinks.h>
 #include <spdlog/sinks/stdout_sinks.h>
 #include <spdlog/spdlog.h>
@@ -36,7 +37,7 @@ bool Logging::mColor = false;
 std::string Logging::mLastPattern;
 std::string Logging::mLastFilenamePattern;
 bool Logging::mLogToConsole = true;
-#endif
+#endif // USE_SPDLOG
 
 // Right now this is hard-coded to log messages at least as important as INFO
 CoutLogger::CoutLogger(LogLevel l) : mShouldLog(l <= Logging::getLogLevel(""))
@@ -81,7 +82,68 @@ convert_loglevel(LogLevel level)
     }
     return slev;
 }
-#endif
+
+namespace
+{
+// Permanent logger to use per each logging partition.
+// This is intended to be created on the first use and never destroyed.
+struct PermanentLogger
+{
+    std::shared_ptr<spdlog::sinks::dist_sink_mt> mSink;
+    LogPtr mLogger;
+};
+
+PermanentLogger
+makePermanentLogger(std::string const& name, bool isDefault)
+{
+    auto sink = std::make_shared<spdlog::sinks::dist_sink_mt>();
+    auto logger = std::make_shared<spdlog::logger>(name, sink);
+    if (isDefault)
+    {
+        // Logging through DEFAULT_LOG before Logging::init() goes to the
+        // console, matching spdlog's own auto-created default logger.
+        sink->add_sink(std::make_shared<spdlog::sinks::stdout_color_sink_mt>());
+        // This also registers the logger in the spdlog registry.
+        spdlog::set_default_logger(logger);
+    }
+    else
+    {
+        spdlog::register_logger(logger);
+    }
+    return PermanentLogger{std::move(sink), std::move(logger)};
+}
+
+PermanentLogger&
+defaultPermanentLogger()
+{
+    static PermanentLogger pl = makePermanentLogger("default", true);
+    return pl;
+}
+
+#define LOG_PARTITION(name) \
+    PermanentLogger& name##PermanentLogger() \
+    { \
+        static PermanentLogger pl = makePermanentLogger(#name, false); \
+        return pl; \
+    }
+#include "util/LogPartitions.def"
+#undef LOG_PARTITION
+
+// NB: forces creation (and spdlog-registry registration) of every permanent
+// logger, so registry-wide operations like spdlog::set_pattern and
+// spdlog::set_level cover all of them deterministically.
+std::vector<PermanentLogger*>
+allPermanentLoggers()
+{
+    std::vector<PermanentLogger*> loggers;
+    loggers.push_back(&defaultPermanentLogger());
+#define LOG_PARTITION(name) loggers.push_back(&name##PermanentLogger());
+#include "util/LogPartitions.def"
+#undef LOG_PARTITION
+    return loggers;
+}
+} // namespace
+#endif // USE_SPDLOG
 
 void
 Logging::init(bool truncate)
@@ -166,25 +228,24 @@ Logging::init(bool truncate)
                 make_shared<basic_file_sink_mt>(filename, /*truncate=*/false));
         }
 
-        auto makeLogger =
-            [&](std::string const& name) -> shared_ptr<spdlog::logger> {
-            auto logger =
-                make_shared<spdlog::logger>(name, sinks.begin(), sinks.end());
-            spdlog::register_logger(logger);
-            return logger;
-        };
-
-        spdlog::set_default_logger(makeLogger("default"));
-        for (auto const& partition : stellar::Logging::kPartitionNames)
+        // Attach the configured sinks to all the permanent loggers.
+        for (auto* permanentLogger : allPermanentLoggers())
         {
-            makeLogger(partition);
+            permanentLogger->mSink->set_sinks(sinks);
         }
         if (mLastPattern.empty())
         {
             mLastPattern = "%Y-%m-%dT%H:%M:%S.%e [%^%n %l%$] %v";
         }
         auto maxLevel = mGlobalLogLevel;
         spdlog::set_pattern(mLastPattern);
+        // NB: these level writes are read lock-free by isLogLevelAtLeast() on
+        // other threads. set_level() first resets every logger to the global
+        // level, then the loop applies per-partition overrides, so a thread
+        // logging concurrently with (re)configuration can momentarily observe a
+        // partition at the global level (or an override that is about to be
+        // re-applied). This is benign: reconfiguration is rare, and the worst
+        // case is a single log line emitted or suppressed at the prior level.
         spdlog::set_level(convert_loglevel(mGlobalLogLevel));
         for (auto const& pair : mPartitionLogLevels)
         {
@@ -206,10 +267,15 @@ Logging::deinit()
     std::lock_guard<std::recursive_mutex> guard(mLogMutex);
     if (mInitialized)
     {
-#define LOG_PARTITION(name) Logging::name##LogPtr = nullptr;
-#include "util/LogPartitions.def"
-#undef LOG_PARTITION
-        spdlog::drop_all();
+        // Detach all the sinks from the permanent loggers (which
+        // closes the log file once the last reference drops).
+        // The loggers themselves are never destroyed and just stop writing
+        // anywhere until the next init().
+        for (auto* permanentLogger : allPermanentLoggers())
+        {
+            permanentLogger->mSink->flush();
+            permanentLogger->mSink->set_sinks({});
+        }
         mInitialized = false;
     }
 #endif
@@ -291,17 +357,9 @@ Logging::setLogLevel(LogLevel level, char const* partition)
         mPartitionLogLevels.clear();
     }
 #if defined(USE_SPDLOG)
+    // Re-initialize the loggers, which also picks up the new levels.
     deinit();
     init();
-    auto slev = convert_loglevel(level);
-    if (partition)
-    {
-        spdlog::get(partition)->set_level(slev);
-    }
-    else
-    {
-        spdlog::set_level(slev);
-    }
 #endif
 }
 
@@ -384,13 +442,29 @@ Logging::logTrace(std::string const& partition)
 bool
 Logging::isLogLevelAtLeast(std::string const& partition, LogLevel level)
 {
+#if defined(USE_SPDLOG)
+    // Read the (atomic) level of the permanent partition logger instead of
+    // consulting the level maps under the global mutex: this function is
+    // called from hot paths on concurrently-running threads. The logger
+    // levels are kept in sync with the maps by setLogLevel()/init().
+    auto slev = convert_loglevel(level);
+#define LOG_PARTITION(name) \
+    if (partition == #name) \
+    { \
+        return name##PermanentLogger().mLogger->should_log(slev); \
+    }
+#include "util/LogPartitions.def"
+#undef LOG_PARTITION
+    return defaultPermanentLogger().mLogger->should_log(slev);
+#else
     std::lock_guard<std::recursive_mutex> guard(mLogMutex);
     auto it = mPartitionLogLevels.find(partition);
     if (it != mPartitionLogLevels.end())
     {
         return it->second >= level;
     }
     return mGlobalLogLevel >= level;
+#endif
 }
 
 void
@@ -418,27 +492,19 @@ Logging::normalizePartition(std::string const& partition)
 std::recursive_mutex Logging::mLogMutex;
 
 #if defined(USE_SPDLOG)
-LogPtr Logging::defaultLogPtr = nullptr;
-LogPtr
+// These are called by every CLOG_* macro invocation (including ones for
+// disabled levels) and must remain lock-free and write-free: they return a
+// raw pointer into a permanent logger that is guaranteed to never be destroyed,
+// and thus is safe to be stored if necessary.
+spdlog::logger*
 Logging::getDefaultLogPtr()
 {
-    std::lock_guard<std::recursive_mutex> guard(mLogMutex);
-    if (!defaultLogPtr)
-    {
-        defaultLogPtr = spdlog::default_logger();
-    }
-    return defaultLogPtr;
+    return defaultPermanentLogger().mLogger.get();
 }
 #define LOG_PARTITION(name) \
-    LogPtr Logging::name##LogPtr = nullptr; \
-    LogPtr Logging::get##name##LogPtr() \
+    spdlog::logger* Logging::get##name##LogPtr() \
     { \
-        std::lock_guard<std::recursive_mutex> guard(mLogMutex); \
-        if (!name##LogPtr) \
-        { \
-            name##LogPtr = spdlog::get(#name); \
-        } \
-        return name##LogPtr; \
+        return name##PermanentLogger().mLogger.get(); \
     }
 #include "util/LogPartitions.def"
 #undef LOG_PARTITION
@@ -458,7 +524,7 @@ Logging::logAtPartitionAndLevel(std::string const& partition, LogLevel level,
     }
 #include "util/LogPartitions.def"
 #undef LOG_PARTITION
-    LOG_CHECK(spdlog::default_logger(), lev, lg->log(lev, msg));
+    LOG_CHECK(Logging::getDefaultLogPtr(), lev, lg->log(lev, msg));
 #else
     CoutLogger logger(level) << msg;
 #endif

src/util/Logging.h

@@ -157,6 +157,19 @@ class CoutLogger
     }
 };
 
+// Logging uses one *permanent* spdlog logger per partition (plus "default"):
+// the logger objects are created on first use and are never destroyed or
+// replaced for the lifetime of the process. Each logger's single sink is a
+// thread-safe dist_sink_mt whose child sinks (console/file) are swapped in
+// place, under that sink's own mutex, whenever logging is (re)configured.
+// Log levels are atomics inside spdlog.
+//
+// This makes the per-partition getters below (and thus every CLOG_* call
+// site) lock-free and write-free: checking whether a disabled level is
+// enabled costs two loads and touches no shared mutable state, so it can be
+// done freely from concurrently-running threads. It is also safe to cache the
+// returned pointer: reconfiguration changes what the permanent loggers write
+// to, not the logger identities.
 class Logging
 {
     static LogLevel mGlobalLogLevel;
@@ -168,10 +181,6 @@ class Logging
     static std::string mLastPattern;
     static std::string mLastFilenamePattern;
     static bool mLogToConsole;
-    static LogPtr defaultLogPtr;
-#define LOG_PARTITION(name) static LogPtr name##LogPtr;
-#include "util/LogPartitions.def"
-#undef LOG_PARTITION
 #endif
 
   public:
@@ -196,8 +205,8 @@ class Logging
     static std::array<std::string const, 15> const kPartitionNames;
 
 #if defined(USE_SPDLOG)
-    static LogPtr getDefaultLogPtr();
-#define LOG_PARTITION(name) static LogPtr get##name##LogPtr();
+    static spdlog::logger* getDefaultLogPtr();
+#define LOG_PARTITION(name) static spdlog::logger* get##name##LogPtr();
 #include "util/LogPartitions.def"
 #undef LOG_PARTITION
 #endif

src/util/SpdlogTweaks.h

@@ -12,7 +12,10 @@
 #define SPDLOG_FMT_EXTERNAL
 #define SPDLOG_NO_THREAD_ID
 #define SPDLOG_NO_TLS
-#define SPDLOG_NO_ATOMIC_LEVELS
+// NB: SPDLOG_NO_ATOMIC_LEVELS must remain undefined: stellar logging keeps
+// permanent logger objects whose levels can be changed in place while other
+// threads are logging through them, so the level reads/writes must be
+// atomic. A relaxed atomic load costs the same as a plain load on x86/arm64.
 #define SPDLOG_PREVENT_CHILD_FD
 #define SPDLOG_LEVEL_NAMES \
     {"TRACE", "DEBUG", "INFO", "WARNING", "ERROR", "FATAL", "OFF"}