From ddfcf49e2b994b967e85e211afd805b7389ea04f Mon Sep 17 00:00:00 2001 From: JCW Date: Sun, 31 Aug 2025 14:28:26 +0100 Subject: [PATCH] Optimisation Signed-off-by: JCW --- include/xrpl/beast/utility/Journal.h | 47 +++---- src/libxrpl/beast/utility/beast_Journal.cpp | 145 +++++++++++++------- src/tests/libxrpl/basics/log.cpp | 140 ++++++++++--------- 3 files changed, 186 insertions(+), 146 deletions(-) diff --git a/include/xrpl/beast/utility/Journal.h b/include/xrpl/beast/utility/Journal.h index 10715ad93a..4e4bd3ae3f 100644 --- a/include/xrpl/beast/utility/Journal.h +++ b/include/xrpl/beast/utility/Journal.h @@ -174,8 +174,9 @@ public: class JsonLogContext { - rapidjson::Value attributes_; + rapidjson::Value messageParams_; rapidjson::MemoryPoolAllocator<> allocator_; + std::optional journalAttributesJson_; public: JsonLogContext() = default; @@ -189,20 +190,20 @@ public: rapidjson::Value& messageParams() { - return attributes_["Params"]; + return messageParams_; } - rapidjson::Value& - attributes() + std::optional& + journalAttributesJson() { - return attributes_; + return journalAttributesJson_; } void reset( std::source_location location, severities::Severity severity, - std::optional const& attributes) noexcept; + std::optional const& journalAttributesJson) noexcept; }; private: @@ -210,7 +211,9 @@ private: using Severity = severities::Severity; std::optional m_attributes; + std::optional m_attributesJson; static std::optional globalLogAttributes_; + static std::optional globalLogAttributesJson_; static std::mutex globalLogAttributesMutex_; static bool m_jsonLogsEnabled; @@ -227,6 +230,9 @@ private: static std::string formatLog(std::string&& message); + void + rebuildAttributeJson(); + public: //-------------------------------------------------------------------------- @@ -457,18 +463,8 @@ public: Journal( Journal const& other, - std::optional attributes = std::nullopt) - : m_attributes(other.m_attributes) - , m_sink(other.m_sink) - { - if (attributes.has_value()) - { - if (m_attributes) - m_attributes->combine(attributes->contextValues_); - else - m_attributes = std::move(attributes); - } - } + std::optional attributes = std::nullopt); + /** Create a journal that writes to the specified sink. */ explicit Journal( Sink& sink, @@ -481,6 +477,7 @@ public: m_attributes = std::move(attributes); m_attributes->setModuleName(name); } + rebuildAttributeJson(); } Journal& @@ -491,6 +488,7 @@ public: m_sink = other.m_sink; m_attributes = other.m_attributes; + rebuildAttributeJson(); return *this; } @@ -499,6 +497,7 @@ public: { m_sink = other.m_sink; m_attributes = std::move(other.m_attributes); + rebuildAttributeJson(); return *this; } @@ -586,19 +585,11 @@ public: { std::lock_guard lock(globalLogAttributesMutex_); globalLogAttributes_ = std::nullopt; + globalLogAttributesJson_ = std::nullopt; } static void - addGlobalAttributes(JsonLogAttributes globalLogAttributes) - { - std::lock_guard lock(globalLogAttributesMutex_); - if (!globalLogAttributes_) - { - globalLogAttributes_ = JsonLogAttributes{}; - } - globalLogAttributes_->combine( - globalLogAttributes.contextValues()); - } + addGlobalAttributes(JsonLogAttributes globalLogAttributes); }; #ifndef __INTELLISENSE__ diff --git a/src/libxrpl/beast/utility/beast_Journal.cpp b/src/libxrpl/beast/utility/beast_Journal.cpp index 65593db214..b523477cf7 100644 --- a/src/libxrpl/beast/utility/beast_Journal.cpp +++ b/src/libxrpl/beast/utility/beast_Journal.cpp @@ -32,6 +32,8 @@ namespace beast { std::optional Journal::globalLogAttributes_; +std::optional Journal::globalLogAttributesJson_; + std::mutex Journal::globalLogAttributesMutex_; bool Journal::m_jsonLogsEnabled = false; thread_local Journal::JsonLogContext Journal::currentJsonLogContext_{}; @@ -169,11 +171,44 @@ Journal::JsonLogAttributes::combine( } } +Journal::Journal( + Journal const& other, + std::optional attributes) + : m_attributes(other.m_attributes), m_sink(other.m_sink) +{ + if (attributes.has_value()) + { + if (m_attributes) + m_attributes->combine(attributes->contextValues_); + else + m_attributes = std::move(attributes); + } + rebuildAttributeJson(); +} + +void +Journal::addGlobalAttributes(JsonLogAttributes globalLogAttributes) +{ + std::lock_guard lock(globalLogAttributesMutex_); + if (!globalLogAttributes_) + { + globalLogAttributes_ = JsonLogAttributes{}; + } + globalLogAttributes_->combine(globalLogAttributes.contextValues()); + + rapidjson::StringBuffer buffer; + rapidjson::Writer writer{buffer}; + + globalLogAttributes_->contextValues().Accept(writer); + + globalLogAttributesJson_ = {buffer.GetString()}; +} + void Journal::JsonLogContext::reset( std::source_location location, severities::Severity severity, - std::optional const& attributes) noexcept + std::optional const& journalAttributesJson) noexcept { struct ThreadIdStringInitializer { @@ -187,67 +222,37 @@ Journal::JsonLogContext::reset( }; thread_local ThreadIdStringInitializer const 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); + journalAttributesJson_ = journalAttributesJson; - rapidjson::Value jsonValue; - jsonValue.CopyFrom(value, allocator_); + messageParams_.SetObject(); - 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( + messageParams_.AddMember( rapidjson::StringRef("Function"), rapidjson::Value{location.function_name(), allocator_}, allocator_); - attributes_.RemoveMember("File"); - attributes_.AddMember( + messageParams_.AddMember( rapidjson::StringRef("File"), rapidjson::Value{location.file_name(), allocator_}, allocator_); - attributes_.RemoveMember("Line"); - attributes_.AddMember( + messageParams_.AddMember( rapidjson::StringRef("Line"), location.line(), allocator_); - attributes_.RemoveMember("ThreadId"); - attributes_.AddMember( + + messageParams_.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( + messageParams_.AddMember( rapidjson::StringRef("Level"), rapidjson::Value{severityStr.c_str(), allocator_}, allocator_); - attributes_.RemoveMember("Time"); - attributes_.AddMember( + + messageParams_.AddMember( rapidjson::StringRef("Time"), std::chrono::duration_cast( std::chrono::system_clock::now().time_since_epoch()) @@ -260,7 +265,7 @@ Journal::initMessageContext( std::source_location location, severities::Severity severity) const { - currentJsonLogContext_.reset(location, severity, m_attributes); + currentJsonLogContext_.reset(location, severity, m_attributesJson); } std::string @@ -271,23 +276,59 @@ Journal::formatLog(std::string&& message) return message; } - auto& attributes = currentJsonLogContext_.attributes(); - - attributes.RemoveMember("Message"); - attributes.AddMember( - rapidjson::StringRef("Message"), - rapidjson::Value{rapidjson::StringRef(message.c_str()), currentJsonLogContext_.allocator()}, - currentJsonLogContext_.allocator() - ); + auto& messageParams = currentJsonLogContext_.messageParams(); rapidjson::StringBuffer buffer; rapidjson::Writer writer(buffer); - attributes.Accept(writer); + writer.StartObject(); + if (globalLogAttributesJson_.has_value()) + { + writer.Key("GlobalParams"); + writer.RawValue( + globalLogAttributesJson_->c_str(), + globalLogAttributesJson_->length(), + rapidjson::kObjectType); + } + + if (currentJsonLogContext_.journalAttributesJson().has_value()) + { + writer.Key("JournalParams"); + writer.RawValue( + currentJsonLogContext_.journalAttributesJson()->c_str(), + currentJsonLogContext_.journalAttributesJson()->length(), + rapidjson::kObjectType); + } + + writer.Key("MessageParams"); + messageParams.Accept(writer); + + writer.Key("Message"); + writer.String(message.c_str(), message.length()); + + writer.EndObject(); return {buffer.GetString()}; } +void +Journal::rebuildAttributeJson() +{ + if (m_attributes.has_value()) + { + rapidjson::StringBuffer buffer; + rapidjson::Writer writer{buffer}; + + m_attributes->contextValues().Accept(writer); + + m_attributesJson = {buffer.GetString()}; + } + else + { + m_attributesJson = {}; + } +} + void Journal::enableStructuredJournal() { diff --git a/src/tests/libxrpl/basics/log.cpp b/src/tests/libxrpl/basics/log.cpp index de5a2aa5a2..4c2b14eb98 100644 --- a/src/tests/libxrpl/basics/log.cpp +++ b/src/tests/libxrpl/basics/log.cpp @@ -164,9 +164,11 @@ TEST_CASE("Global attributes") jsonLog.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); CHECK(jsonLog.IsObject()); - CHECK(jsonLog.HasMember("Field1")); - CHECK(jsonLog["Field1"].IsString()); - CHECK(jsonLog["Field1"].GetString() == std::string{"Value1"}); + CHECK(jsonLog.HasMember("GlobalParams")); + CHECK(jsonLog["GlobalParams"].IsObject()); + CHECK(jsonLog["GlobalParams"].HasMember("Field1")); + CHECK(jsonLog["GlobalParams"]["Field1"].IsString()); + CHECK(jsonLog["GlobalParams"]["Field1"].GetString() == std::string{"Value1"}); beast::Journal::disableStructuredJournal(); } @@ -194,12 +196,11 @@ TEST_CASE("Global attributes inheritable") jsonLog.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); CHECK(jsonLog.IsObject()); - CHECK(jsonLog.HasMember("Field1")); - CHECK(jsonLog["Field1"].IsString()); - // Field1 should be overwritten to Value3 - CHECK(jsonLog["Field1"].GetString() == std::string{"Value3"}); - CHECK(jsonLog["Field2"].IsString()); - CHECK(jsonLog["Field2"].GetString() == std::string{"Value2"}); + CHECK(jsonLog["GlobalParams"].HasMember("Field1")); + CHECK(jsonLog["GlobalParams"]["Field1"].IsString()); + CHECK(jsonLog["GlobalParams"]["Field1"].GetString() == std::string{"Value1"}); + CHECK(jsonLog["JournalParams"]["Field1"].GetString() == std::string{"Value3"}); + CHECK(jsonLog["JournalParams"]["Field2"].GetString() == std::string{"Value2"}); beast::Journal::disableStructuredJournal(); } @@ -234,7 +235,9 @@ class JsonLogStreamFixture { public: JsonLogStreamFixture() - : sink_(beast::severities::kAll, logStream_), j_(sink_) + : sink_(beast::severities::kAll, logStream_), j_(sink_, "Test", log::attributes( + log::attr("Field1", "Value1") + )) { beast::Journal::enableStructuredJournal(); } @@ -264,8 +267,9 @@ private: TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogFields") { + beast::Journal::addGlobalAttributes(log::attributes(log::attr("Field2", "Value2"))); journal().debug() << std::boolalpha << true << std::noboolalpha << " Test " - << std::boolalpha << false; + << std::boolalpha << false << log::field("Field3", "Value3"); rapidjson::Document logValue; logValue.Parse(stream().str().c_str()); @@ -274,20 +278,27 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogFields") logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); CHECK(logValue.IsObject()); - CHECK(logValue.HasMember("Function")); - CHECK(logValue.HasMember("File")); - CHECK(logValue.HasMember("Line")); - CHECK(logValue.HasMember("ThreadId")); - CHECK(logValue.HasMember("Params")); - CHECK(logValue.HasMember("Level")); + CHECK(logValue.HasMember("GlobalParams")); + CHECK(logValue.HasMember("JournalParams")); + CHECK(logValue.HasMember("MessageParams")); CHECK(logValue.HasMember("Message")); - CHECK(logValue.HasMember("Time")); - CHECK(logValue["Function"].IsString()); - CHECK(logValue["File"].IsString()); - CHECK(logValue["Line"].IsNumber()); - CHECK(logValue["Params"].IsObject()); + CHECK(logValue["GlobalParams"].IsObject()); + CHECK(logValue["JournalParams"].IsObject()); + CHECK(logValue["MessageParams"].IsObject()); CHECK(logValue["Message"].IsString()); + + CHECK(logValue["MessageParams"].HasMember("Function")); + CHECK(logValue["MessageParams"].HasMember("File")); + CHECK(logValue["MessageParams"].HasMember("Line")); + CHECK(logValue["MessageParams"].HasMember("ThreadId")); + CHECK(logValue["MessageParams"].HasMember("Level")); + CHECK(logValue["MessageParams"].HasMember("Time")); + + CHECK(logValue["MessageParams"]["Function"].IsString()); + CHECK(logValue["MessageParams"]["File"].IsString()); + CHECK(logValue["MessageParams"]["Line"].IsNumber()); + CHECK(logValue["Message"].GetString() == std::string{"true Test false"}); } @@ -305,7 +316,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogLevels") rapidjson::ParseErrorCode::kParseErrorNone); CHECK( - logValue["Level"].GetString() == + logValue["MessageParams"]["Level"].GetString() == beast::severities::to_string(beast::severities::kTrace)); } @@ -321,7 +332,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogLevels") rapidjson::ParseErrorCode::kParseErrorNone); CHECK( - logValue["Level"].GetString() == + logValue["MessageParams"]["Level"].GetString() == beast::severities::to_string(beast::severities::kDebug)); } @@ -337,7 +348,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogLevels") rapidjson::ParseErrorCode::kParseErrorNone); CHECK( - logValue["Level"].GetString() == + logValue["MessageParams"]["Level"].GetString() == beast::severities::to_string(beast::severities::kInfo)); } @@ -353,7 +364,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogLevels") rapidjson::ParseErrorCode::kParseErrorNone); CHECK( - logValue["Level"].GetString() == + logValue["MessageParams"]["Level"].GetString() == beast::severities::to_string(beast::severities::kWarning)); } @@ -369,7 +380,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogLevels") rapidjson::ParseErrorCode::kParseErrorNone); CHECK( - logValue["Level"].GetString() == + logValue["MessageParams"]["Level"].GetString() == beast::severities::to_string(beast::severities::kError)); } @@ -385,7 +396,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogLevels") rapidjson::ParseErrorCode::kParseErrorNone); CHECK( - logValue["Level"].GetString() == + logValue["MessageParams"]["Level"].GetString() == beast::severities::to_string(beast::severities::kFatal)); } } @@ -401,7 +412,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogStream") logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); CHECK( - logValue["Level"].GetString() == + logValue["MessageParams"]["Level"].GetString() == beast::severities::to_string(beast::severities::kError)); } @@ -418,15 +429,12 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogParams") CHECK( logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); - CHECK(logValue["Params"].IsObject()); - CHECK(logValue["Params"]["Field1"].IsNumber()); - CHECK(logValue["Params"]["Field1"].GetInt() == 1); - // UInt64 doesn't fit in Json::Value so it should be converted to a string - // NOTE: We should expect it to be an int64 after we make the json library - // support in64 and uint64 - CHECK(logValue["Params"]["Field2"].IsNumber()); + CHECK(logValue["MessageParams"].IsObject()); + CHECK(logValue["MessageParams"]["Field1"].IsNumber()); + CHECK(logValue["MessageParams"]["Field1"].GetInt() == 1); + CHECK(logValue["MessageParams"]["Field2"].IsNumber()); CHECK( - logValue["Params"]["Field2"].GetUint64() == + logValue["MessageParams"]["Field2"].GetUint64() == std::numeric_limits::max()); CHECK(logValue["Message"].IsString()); CHECK( @@ -447,15 +455,15 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJsonLogFields") CHECK( logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); - CHECK(logValue["Params"].IsObject()); - CHECK(logValue["Params"]["Field1"].IsNumber()); - CHECK(logValue["Params"]["Field1"].GetInt() == 1); + CHECK(logValue["MessageParams"].IsObject()); + CHECK(logValue["MessageParams"]["Field1"].IsNumber()); + CHECK(logValue["MessageParams"]["Field1"].GetInt() == 1); // UInt64 doesn't fit in Json::Value so it should be converted to a string // NOTE: We should expect it to be an int64 after we make the json library // support in64 and uint64 - CHECK(logValue["Params"]["Field2"].IsNumber()); + CHECK(logValue["MessageParams"]["Field2"].IsNumber()); CHECK( - logValue["Params"]["Field2"].GetUint64() == + logValue["MessageParams"]["Field2"].GetUint64() == std::numeric_limits::max()); CHECK(logValue["Message"].IsString()); CHECK(logValue["Message"].GetString() == std::string{"Test"}); @@ -475,10 +483,10 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJournalAttributes") CHECK( logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); - CHECK(logValue["Field1"].IsString()); - CHECK(logValue["Field1"].GetString() == std::string{"Value1"}); - CHECK(logValue["Field2"].IsNumber()); - CHECK(logValue["Field2"].GetInt() == 2); + CHECK(logValue["JournalParams"]["Field1"].IsString()); + CHECK(logValue["JournalParams"]["Field1"].GetString() == std::string{"Value1"}); + CHECK(logValue["JournalParams"]["Field2"].IsNumber()); + CHECK(logValue["JournalParams"]["Field2"].GetInt() == 2); } TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJournalAttributesInheritable") @@ -498,13 +506,13 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "TestJournalAttributesInheritable") CHECK( logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); - CHECK(logValue["Field1"].IsString()); - CHECK(logValue["Field1"].GetString() == std::string{"Value1"}); - CHECK(logValue["Field3"].IsString()); - CHECK(logValue["Field3"].GetString() == std::string{"Value3"}); + CHECK(logValue["JournalParams"]["Field1"].IsString()); + CHECK(logValue["JournalParams"]["Field1"].GetString() == std::string{"Value1"}); + CHECK(logValue["JournalParams"]["Field3"].IsString()); + CHECK(logValue["JournalParams"]["Field3"].GetString() == std::string{"Value3"}); // Field2 should be overwritten to 0 - CHECK(logValue["Field2"].IsNumber()); - CHECK(logValue["Field2"].GetInt() == 0); + CHECK(logValue["JournalParams"]["Field2"].IsNumber()); + CHECK(logValue["JournalParams"]["Field2"].GetInt() == 0); } TEST_CASE_FIXTURE( @@ -526,13 +534,13 @@ TEST_CASE_FIXTURE( CHECK( logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); - CHECK(logValue["Field1"].IsString()); - CHECK(logValue["Field1"].GetString() == std::string{"Value1"}); - CHECK(logValue["Field3"].IsString()); - CHECK(logValue["Field3"].GetString() == std::string{"Value3"}); + CHECK(logValue["JournalParams"]["Field1"].IsString()); + CHECK(logValue["JournalParams"]["Field1"].GetString() == std::string{"Value1"}); + CHECK(logValue["JournalParams"]["Field3"].IsString()); + CHECK(logValue["JournalParams"]["Field3"].GetString() == std::string{"Value3"}); // Field2 should be overwritten to 0 - CHECK(logValue["Field2"].IsNumber()); - CHECK(logValue["Field2"].GetInt() == 0); + CHECK(logValue["JournalParams"]["Field2"].IsNumber()); + CHECK(logValue["JournalParams"]["Field2"].GetInt() == 0); } TEST_CASE_FIXTURE( @@ -555,10 +563,10 @@ TEST_CASE_FIXTURE( CHECK( logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); - CHECK(logValue["Field1"].IsString()); - CHECK(logValue["Field1"].GetString() == std::string{"Value1"}); - CHECK(logValue["Field2"].IsNumber()); - CHECK(logValue["Field2"].GetInt() == 2); + CHECK(logValue["JournalParams"]["Field1"].IsString()); + CHECK(logValue["JournalParams"]["Field1"].GetString() == std::string{"Value1"}); + CHECK(logValue["JournalParams"]["Field2"].IsNumber()); + CHECK(logValue["JournalParams"]["Field2"].GetInt() == 2); } TEST_CASE_FIXTURE( @@ -581,8 +589,8 @@ TEST_CASE_FIXTURE( CHECK( logValue.GetParseError() == rapidjson::ParseErrorCode::kParseErrorNone); - CHECK(logValue["Field1"].IsString()); - CHECK(logValue["Field1"].GetString() == std::string{"Value1"}); - CHECK(logValue["Field2"].IsNumber()); - CHECK(logValue["Field2"].GetInt() == 2); + CHECK(logValue["JournalParams"]["Field1"].IsString()); + CHECK(logValue["JournalParams"]["Field1"].GetString() == std::string{"Value1"}); + CHECK(logValue["JournalParams"]["Field2"].IsNumber()); + CHECK(logValue["JournalParams"]["Field2"].GetInt() == 2); } \ No newline at end of file