performance optimisation

Signed-off-by: JCW <a1q123456@users.noreply.github.com>

include/xrpl/basics/Log.h

@@ -156,9 +156,10 @@ private:
     private:
         std::unique_ptr<std::ofstream> m_stream;
         boost::filesystem::path m_path;
+        std::mutex mutable fileMutex_;
     };
 
-    std::mutex mutable mutex_;
+    std::mutex mutable sinkSetMutex_;
     std::map<
         std::string,
         std::unique_ptr<beast::Journal::Sink>,
@@ -205,7 +206,7 @@ public:
     write(
         beast::severities::Severity level,
         std::string const& partition,
-        std::string const& text,
+        std::string text,
         bool console);
 
     std::string
@@ -243,7 +244,7 @@ public:
     static void
     format(
         std::string& output,
-        std::string const& message,
+        std::string message,
         beast::severities::Severity severity,
         std::string const& partition);
 

include/xrpl/beast/utility/Journal.h

@@ -144,8 +144,8 @@ public:
         void
         setModuleName(std::string const& name);
 
-        [[nodiscard]] static JsonLogAttributes
+        void
-        combine(AttributeFields const& a, AttributeFields const& b);
+        combine(AttributeFields const& from);
 
         AttributeFields&
         contextValues()
@@ -172,22 +172,37 @@ public:
         friend class Journal;
     };
 
-    struct JsonLogContext
+    class JsonLogContext
     {
-        std::source_location location = {};
+        rapidjson::Value attributes_;
-        rapidjson::Value messageParams;
+        rapidjson::MemoryPoolAllocator<> allocator_;
-        rapidjson::MemoryPoolAllocator<> allocator;
 
+    public:
         JsonLogContext() = default;
 
-        void
+        rapidjson::MemoryPoolAllocator<>&
-        reset(std::source_location location_) noexcept
+        allocator()
         {
-            location = location_;
+            return allocator_;
-            messageParams = rapidjson::Value{};
-            messageParams.SetObject();
-            allocator.Clear();
         }
+
+        rapidjson::Value&
+        messageParams()
+        {
+            return attributes_["Params"];
+        }
+
+        rapidjson::Value&
+        attributes()
+        {
+            return attributes_;
+        }
+
+        void
+        reset(
+            std::source_location location,
+            severities::Severity severity,
+            std::optional<JsonLogAttributes> const& attributes) noexcept;
     };
 
 private:
@@ -204,14 +219,13 @@ private:
     // Invariant: m_sink always points to a valid Sink
     Sink* m_sink = nullptr;
 
-    static void
+    void
-    initMessageContext(std::source_location location);
+    initMessageContext(
+        std::source_location location,
+        severities::Severity severity) const;
 
     static std::string
-    formatLog(
+    formatLog(std::string const& message);
-        std::string const& message,
-        severities::Severity severity,
-        std::optional<JsonLogAttributes> const& attributes = std::nullopt);
 
 public:
     //--------------------------------------------------------------------------
@@ -304,25 +318,16 @@ public:
     {
     public:
         ScopedStream(ScopedStream const& other)
-            : ScopedStream(other.m_attributes, other.m_sink, other.m_level)
+            : ScopedStream(other.m_sink, other.m_level)
         {
         }
 
-        ScopedStream(
+        ScopedStream(Sink& sink, Severity level);
-            std::optional<JsonLogAttributes> attributes,
-            Sink& sink,
-            Severity level);
 
         template <typename T>
-        ScopedStream(
+        ScopedStream(Stream const& stream, T const& t);
-            std::optional<JsonLogAttributes> attributes,
-            Stream const& stream,
-            T const& t);
 
-        ScopedStream(
+        ScopedStream(Stream const& stream, std::ostream& manip(std::ostream&));
-            std::optional<JsonLogAttributes> attributes,
-            Stream const& stream,
-            std::ostream& manip(std::ostream&));
 
         ScopedStream&
         operator=(ScopedStream const&) = delete;
@@ -343,7 +348,6 @@ public:
         operator<<(T const& t) const;
 
     private:
-        std::optional<JsonLogAttributes> m_attributes;
         Sink& m_sink;
         Severity const m_level;
         std::ostringstream mutable m_ostream;
@@ -378,11 +382,7 @@ public:
 
             Constructor is inlined so checking active() very inexpensive.
         */
-        Stream(
+        Stream(Sink& sink, Severity level) : m_sink(sink), m_level(level)
-            std::optional<JsonLogAttributes> attributes,
-            Sink& sink,
-            Severity level)
-            : m_attributes(std::move(attributes)), m_sink(sink), m_level(level)
         {
             XRPL_ASSERT(
                 m_level < severities::kDisabled,
@@ -390,8 +390,7 @@ public:
         }
 
         /** Construct or copy another Stream. */
-        Stream(Stream const& other)
+        Stream(Stream const& other) : Stream(other.m_sink, other.m_level)
-            : Stream(other.m_attributes, other.m_sink, other.m_level)
         {
         }
 
@@ -438,7 +437,6 @@ public:
         /** @} */
 
     private:
-        std::optional<JsonLogAttributes> m_attributes;
         Sink& m_sink;
         Severity m_level;
     };
@@ -467,9 +465,8 @@ public:
         if (other.m_attributes.has_value())
         {
             if (m_attributes.has_value())
-                m_attributes = JsonLogAttributes::combine(
+                m_attributes->combine(
-                    other.m_attributes->contextValues_,
+                    other.m_attributes->contextValues_);
-                    m_attributes->contextValues_);
             else
                 m_attributes = other.m_attributes;
         }
@@ -516,9 +513,11 @@ public:
 
     /** Returns a stream for this sink, with the specified severity level. */
     Stream
-    stream(Severity level) const
+    stream(Severity level, std::source_location location = std::source_location::current()) const
     {
-        return Stream(m_attributes, *m_sink, level);
+        if (m_jsonLogsEnabled)
+            initMessageContext(location, level);
+        return Stream(*m_sink, level);
     }
 
     /** Returns `true` if any message would be logged at this severity level.
@@ -537,24 +536,24 @@ public:
     trace(std::source_location location = std::source_location::current()) const
     {
         if (m_jsonLogsEnabled)
-            initMessageContext(location);
+            initMessageContext(location, severities::kTrace);
-        return {m_attributes, *m_sink, severities::kTrace};
+        return {*m_sink, severities::kTrace};
     }
 
     Stream
     debug(std::source_location location = std::source_location::current()) const
     {
         if (m_jsonLogsEnabled)
-            initMessageContext(location);
+            initMessageContext(location, severities::kDebug);
-        return {m_attributes, *m_sink, severities::kDebug};
+        return {*m_sink, severities::kDebug};
     }
 
     Stream
     info(std::source_location location = std::source_location::current()) const
     {
         if (m_jsonLogsEnabled)
-            initMessageContext(location);
+            initMessageContext(location, severities::kInfo);
-        return {m_attributes, *m_sink, severities::kInfo};
+        return {*m_sink, severities::kInfo};
     }
 
     Stream
@@ -563,24 +562,24 @@ public:
         char const* a = "a";
         rapidjson::Value v{a, 1};
         if (m_jsonLogsEnabled)
-            initMessageContext(location);
+            initMessageContext(location, severities::kWarning);
-        return {m_attributes, *m_sink, severities::kWarning};
+        return {*m_sink, severities::kWarning};
     }
 
     Stream
     error(std::source_location location = std::source_location::current()) const
     {
         if (m_jsonLogsEnabled)
-            initMessageContext(location);
+            initMessageContext(location, severities::kError);
-        return {m_attributes, *m_sink, severities::kError};
+        return {*m_sink, severities::kError};
     }
 
     Stream
     fatal(std::source_location location = std::source_location::current()) const
     {
         if (m_jsonLogsEnabled)
-            initMessageContext(location);
+            initMessageContext(location, severities::kFatal);
-        return {m_attributes, *m_sink, severities::kFatal};
+        return {*m_sink, severities::kFatal};
     }
     /** @} */
 
@@ -599,8 +598,7 @@ public:
         {
             globalLogAttributes_ = JsonLogAttributes{};
         }
-        globalLogAttributes_ = JsonLogAttributes::combine(
+        globalLogAttributes_->combine(
-            globalLogAttributes_->contextValues(),
             globalLogAttributes.contextValues());
     }
 };
@@ -617,11 +615,8 @@ static_assert(std::is_nothrow_destructible<Journal>::value == true, "");
 //------------------------------------------------------------------------------
 
 template <typename T>
-Journal::ScopedStream::ScopedStream(
+Journal::ScopedStream::ScopedStream(Stream const& stream, T const& t)
-    std::optional<JsonLogAttributes> attributes,
+    : ScopedStream(stream.sink(), stream.level())
-    Stream const& stream,
-    T const& t)
-    : ScopedStream(std::move(attributes), stream.sink(), stream.level())
 {
     m_ostream << t;
 }
@@ -640,7 +635,7 @@ template <typename T>
 Journal::ScopedStream
 Journal::Stream::operator<<(T const& t) const
 {
-    return {m_attributes, *this, t};
+    return {*this, t};
 }
 
 namespace detail {
@@ -766,6 +761,7 @@ setJsonValue(
         }
     }
 
+    object.RemoveMember(name);
     object.AddMember(
         rapidjson::StringRef(name), std::move(jsonValue), allocator);
 }
@@ -778,8 +774,8 @@ operator<<(std::ostream& os, LogParameter<T> const& param)
     if (!beast::Journal::m_jsonLogsEnabled)
         return os;
     detail::setJsonValue(
-        beast::Journal::currentJsonLogContext_.messageParams,
+        beast::Journal::currentJsonLogContext_.messageParams(),
-        beast::Journal::currentJsonLogContext_.allocator,
+        beast::Journal::currentJsonLogContext_.allocator(),
         param.name_,
         param.value_,
         &os);
@@ -793,8 +789,8 @@ operator<<(std::ostream& os, LogField<T> const& param)
     if (!beast::Journal::m_jsonLogsEnabled)
         return os;
     detail::setJsonValue(
-        beast::Journal::currentJsonLogContext_.messageParams,
+        beast::Journal::currentJsonLogContext_.messageParams(),
-        beast::Journal::currentJsonLogContext_.allocator,
+        beast::Journal::currentJsonLogContext_.allocator(),
         param.name_,
         param.value_,
         nullptr);

src/libxrpl/basics/Log.cpp

@@ -88,9 +88,13 @@ Logs::File::open(boost::filesystem::path const& path)
 
     if (stream->good())
     {
+        std::lock_guard lock(fileMutex_);
         m_path = path;
 
         m_stream = std::move(stream);
+        size_t const bufsize = 256 * 1024;
+        static char buf[bufsize];
+        m_stream->rdbuf()->pubsetbuf(buf, bufsize);
 
         wasOpened = true;
     }
@@ -109,12 +113,14 @@ Logs::File::closeAndReopen()
 void
 Logs::File::close()
 {
+    std::lock_guard lock(fileMutex_);
     m_stream = nullptr;
 }
 
 void
 Logs::File::write(char const* text)
 {
+    std::lock_guard lock(fileMutex_);
     if (m_stream != nullptr)
         (*m_stream) << text;
 }
@@ -122,10 +128,10 @@ Logs::File::write(char const* text)
 void
 Logs::File::writeln(char const* text)
 {
+    std::lock_guard lock(fileMutex_);
     if (m_stream != nullptr)
     {
-        (*m_stream) << text;
+        (*m_stream) << text << '\n';
-        (*m_stream) << std::endl;
     }
 }
 
@@ -145,7 +151,7 @@ Logs::open(boost::filesystem::path const& pathToLogFile)
 beast::Journal::Sink&
 Logs::get(std::string const& name)
 {
-    std::lock_guard lock(mutex_);
+    std::lock_guard lock(sinkSetMutex_);
     auto const result = sinks_.emplace(name, makeSink(name, thresh_));
     return *result.first->second;
 }
@@ -173,7 +179,7 @@ Logs::threshold() const
 void
 Logs::threshold(beast::severities::Severity thresh)
 {
-    std::lock_guard lock(mutex_);
+    std::lock_guard lock(sinkSetMutex_);
     thresh_ = thresh;
     for (auto& sink : sinks_)
         sink.second->threshold(thresh);
@@ -183,7 +189,7 @@ std::vector<std::pair<std::string, std::string>>
 Logs::partition_severities() const
 {
     std::vector<std::pair<std::string, std::string>> list;
-    std::lock_guard lock(mutex_);
+    std::lock_guard lock(sinkSetMutex_);
     list.reserve(sinks_.size());
     for (auto const& [name, sink] : sinks_)
         list.emplace_back(name, toString(fromSeverity(sink->threshold())));
@@ -194,12 +200,11 @@ void
 Logs::write(
     beast::severities::Severity level,
     std::string const& partition,
-    std::string const& text,
+    std::string text,
     bool console)
 {
     std::string s;
-    format(s, text, level, partition);
+    format(s, std::move(text), level, partition);
-    std::lock_guard lock(mutex_);
     file_.writeln(s);
     if (!silent_)
         std::cerr << s << '\n';
@@ -211,7 +216,6 @@ Logs::write(
 std::string
 Logs::rotate()
 {
-    std::lock_guard lock(mutex_);
     bool const wasOpened = file_.closeAndReopen();
     if (wasOpened)
         return "The log file was closed and reopened.";
@@ -328,15 +332,15 @@ Logs::fromString(std::string const& s)
 void
 Logs::format(
     std::string& output,
-    std::string const& message,
+    std::string message,
     beast::severities::Severity severity,
     std::string const& partition)
 {
-    output.reserve(message.size() + partition.size() + 100);
+    output = std::move(message);
-
     if (!beast::Journal::isStructuredJournalEnabled())
     {
-        output = to_string(std::chrono::system_clock::now());
+        output.reserve(message.size() + partition.size() + 100);
+        output += to_string(std::chrono::system_clock::now());
 
         output += " ";
         if (!partition.empty())
@@ -369,8 +373,6 @@ Logs::format(
         }
     }
 
-    output += message;
-
     // Limit the maximum length of the output
     if (output.size() > maximumMessageCharacters)
     {

src/libxrpl/beast/utility/beast_Journal.cpp

@@ -154,135 +154,136 @@ Journal::JsonLogAttributes::setModuleName(std::string const& name)
         allocator_);
 }
 
-Journal::JsonLogAttributes
+void
 Journal::JsonLogAttributes::combine(
-    AttributeFields const& a,
+    AttributeFields const& from)
-    AttributeFields const& b)
 {
-    JsonLogAttributes result;
+    for (auto& member : from.GetObject())
+    {
+        contextValues_.RemoveMember(member.name);
 
-    result.contextValues_.CopyFrom(a, result.allocator_);
+        contextValues_.AddMember(
-
+            rapidjson::Value{member.name, allocator_},
-    for (auto& member : b.GetObject())
+            rapidjson::Value{member.value, allocator_},
-    {
+            allocator_);
-        auto val = rapidjson::Value{member.value, result.allocator_};
-        if (result.contextValues_.HasMember(member.name))
-        {
-            result.contextValues_[member.name] = std::move(val);
     }
-        else
-        {
-            result.contextValues_.AddMember(
-                rapidjson::Value{member.name, result.allocator_},
-                std::move(val),
-                result.allocator_);
-        }
-    }
-
-    return result;
 }
 
 void
-Journal::initMessageContext(std::source_location location)
+Journal::JsonLogContext::reset(
+    std::source_location location,
+    severities::Severity severity,
+    std::optional<JsonLogAttributes> const& attributes) noexcept
 {
-    currentJsonLogContext_.reset(location);
+    struct ThreadIdStringInitializer
+    {
+        std::string value;
+        ThreadIdStringInitializer()
+        {
+            std::stringstream threadIdStream;
+            threadIdStream << std::this_thread::get_id();
+            value = threadIdStream.str();
+        }
+    };
+    thread_local ThreadIdStringInitializer threadId;
+
+    attributes_.SetObject();
+    if (globalLogAttributes_.has_value())
+    {
+        attributes_.CopyFrom(globalLogAttributes_->contextValues(), allocator_);
+        if (attributes.has_value())
+        {
+            for (auto const& [key, value] :
+             attributes->contextValues().GetObject())
+            {
+                attributes_.RemoveMember(key);
+
+                rapidjson::Value jsonValue;
+                jsonValue.CopyFrom(value, allocator_);
+
+                attributes_.AddMember(
+                    rapidjson::Value{key, allocator_},
+                    rapidjson::Value{value, allocator_},
+                    allocator_);
+            }
+        }
+    }
+    else if (attributes.has_value())
+    {
+        attributes_.CopyFrom(attributes->contextValues(), allocator_);
+    }
+
+    attributes_.RemoveMember("Function");
+    attributes_.AddMember(
+        rapidjson::StringRef("Function"),
+        rapidjson::Value{location.function_name(), allocator_},
+        allocator_);
+
+    attributes_.RemoveMember("File");
+    attributes_.AddMember(
+        rapidjson::StringRef("File"),
+        rapidjson::Value{location.file_name(), allocator_},
+        allocator_);
+
+    attributes_.RemoveMember("Line");
+    attributes_.AddMember(
+        rapidjson::StringRef("Line"),
+        location.line(),
+        allocator_);
+    attributes_.RemoveMember("ThreadId");
+    attributes_.AddMember(
+        rapidjson::StringRef("ThreadId"),
+        rapidjson::Value{threadId.value.c_str(), allocator_},
+        allocator_);
+    attributes_.RemoveMember("Params");
+    attributes_.AddMember(
+        rapidjson::StringRef("Params"),
+        rapidjson::Value{rapidjson::kObjectType},
+        allocator_);
+    auto severityStr = to_string(severity);
+    attributes_.RemoveMember("Level");
+    attributes_.AddMember(
+        rapidjson::StringRef("Level"),
+        rapidjson::Value{severityStr.c_str(), allocator_},
+        allocator_);
+    attributes_.RemoveMember("Time");
+    attributes_.AddMember(
+        rapidjson::StringRef("Time"),
+        std::chrono::duration_cast<std::chrono::milliseconds>(
+            std::chrono::system_clock::now().time_since_epoch())
+            .count(),
+        allocator_);
+}
+
+void
+Journal::initMessageContext(
+    std::source_location location,
+    severities::Severity severity) const
+{
+    currentJsonLogContext_.reset(location, severity, m_attributes);
 }
 
 std::string
-Journal::formatLog(
+Journal::formatLog(std::string const& message)
-    std::string const& message,
-    severities::Severity severity,
-    std::optional<JsonLogAttributes> const& attributes)
 {
     if (!m_jsonLogsEnabled)
     {
         return message;
     }
 
-    rapidjson::Document doc{&currentJsonLogContext_.allocator};
+    auto& attributes = currentJsonLogContext_.attributes();
-    rapidjson::Value logContext;
-    logContext.SetObject();
 
-    logContext.AddMember(
+    attributes.RemoveMember("Message");
-        rapidjson::StringRef("Function"),
+    attributes.AddMember(
-        rapidjson::StringRef(currentJsonLogContext_.location.function_name()),
-        currentJsonLogContext_.allocator);
-
-    logContext.AddMember(
-        rapidjson::StringRef("File"),
-        rapidjson::StringRef(currentJsonLogContext_.location.file_name()),
-        currentJsonLogContext_.allocator);
-
-    logContext.AddMember(
-        rapidjson::StringRef("Line"),
-        currentJsonLogContext_.location.line(),
-        currentJsonLogContext_.allocator);
-    std::stringstream threadIdStream;
-    threadIdStream << std::this_thread::get_id();
-    auto threadIdStr = threadIdStream.str();
-    logContext.AddMember(
-        rapidjson::StringRef("ThreadId"),
-        rapidjson::StringRef(threadIdStr.c_str()),
-        currentJsonLogContext_.allocator);
-    logContext.AddMember(
-        rapidjson::StringRef("Params"),
-        std::move(currentJsonLogContext_.messageParams),
-        currentJsonLogContext_.allocator);
-    currentJsonLogContext_.messageParams = rapidjson::Value{};
-    currentJsonLogContext_.messageParams.SetObject();
-    auto severityStr = to_string(severity);
-    logContext.AddMember(
-        rapidjson::StringRef("Level"),
-        rapidjson::StringRef(severityStr.c_str()),
-        currentJsonLogContext_.allocator);
-    logContext.AddMember(
         rapidjson::StringRef("Message"),
-        rapidjson::StringRef(message.c_str()),
+        rapidjson::Value{rapidjson::StringRef(message.c_str()), currentJsonLogContext_.allocator()},
-        currentJsonLogContext_.allocator);
+        currentJsonLogContext_.allocator()
-    logContext.AddMember(
+    );
-        rapidjson::StringRef("Time"),
-        std::chrono::duration_cast<std::chrono::milliseconds>(
-            std::chrono::system_clock::now().time_since_epoch())
-            .count(),
-        currentJsonLogContext_.allocator);
-
-    if (attributes.has_value())
-    {
-        for (auto const& [key, value] : attributes->contextValues().GetObject())
-        {
-            if (logContext.HasMember(key))
-                continue;
-            rapidjson::Value jsonValue;
-            jsonValue.CopyFrom(value, currentJsonLogContext_.allocator);
-
-            logContext.AddMember(
-                rapidjson::Value{key, currentJsonLogContext_.allocator},
-                std::move(jsonValue),
-                currentJsonLogContext_.allocator);
-        }
-    }
-
-    if (globalLogAttributes_)
-    {
-        for (auto const& [key, value] :
-             globalLogAttributes_->contextValues().GetObject())
-        {
-            if (logContext.HasMember(key))
-                continue;
-            rapidjson::Value jsonValue;
-            jsonValue.CopyFrom(value, currentJsonLogContext_.allocator);
-
-            logContext.AddMember(
-                rapidjson::Value{key, currentJsonLogContext_.allocator},
-                std::move(jsonValue),
-                currentJsonLogContext_.allocator);
-        }
-    }
 
     rapidjson::StringBuffer buffer;
     rapidjson::Writer writer(buffer);
 
-    logContext.Accept(writer);
+    attributes.Accept(writer);
 
     return {buffer.GetString()};
 }
@@ -345,21 +346,17 @@ Journal::Sink::threshold(Severity thresh)
 
 //------------------------------------------------------------------------------
 
-Journal::ScopedStream::ScopedStream(
+Journal::ScopedStream::ScopedStream(Sink& sink, Severity level)
-    std::optional<JsonLogAttributes> attributes,
+    : m_sink(sink), m_level(level)
-    Sink& sink,
-    Severity level)
-    : m_attributes(std::move(attributes)), m_sink(sink), m_level(level)
 {
     // Modifiers applied from all ctors
     m_ostream << std::boolalpha << std::showbase;
 }
 
 Journal::ScopedStream::ScopedStream(
-    std::optional<JsonLogAttributes> attributes,
     Stream const& stream,
     std::ostream& manip(std::ostream&))
-    : ScopedStream(std::move(attributes), stream.sink(), stream.level())
+    : ScopedStream(stream.sink(), stream.level())
 {
     m_ostream << manip;
 }
@@ -370,9 +367,9 @@ Journal::ScopedStream::~ScopedStream()
     if (!s.empty())
     {
         if (s == "\n")
-            m_sink.write(m_level, formatLog("", m_level, m_attributes));
+            m_sink.write(m_level, formatLog(""));
         else
-            m_sink.write(m_level, formatLog(s, m_level, m_attributes));
+            m_sink.write(m_level, formatLog(s));
     }
 }
 
@@ -387,7 +384,7 @@ Journal::ScopedStream::operator<<(std::ostream& manip(std::ostream&)) const
 Journal::ScopedStream
 Journal::Stream::operator<<(std::ostream& manip(std::ostream&)) const
 {
-    return {m_attributes, *this, manip};
+    return {*this, manip};
 }
 
 }  // namespace beast