From 2491b28fcd2e8be4ae7f975f5d9bdd2474c8eb5d Mon Sep 17 00:00:00 2001 From: JCW Date: Thu, 4 Sep 2025 16:31:39 +0100 Subject: [PATCH] Optimise Signed-off-by: JCW --- include/xrpl/basics/Log.h | 15 ++-- include/xrpl/beast/utility/Journal.h | 28 ++++--- src/libxrpl/basics/Log.cpp | 38 +++++---- src/libxrpl/beast/utility/beast_Journal.cpp | 86 ++++++++++----------- src/tests/libxrpl/basics/log.cpp | 54 ++++++------- src/xrpld/app/main/Application.cpp | 4 - src/xrpld/app/main/Main.cpp | 4 - src/xrpld/overlay/detail/PeerImp.cpp | 3 +- 8 files changed, 109 insertions(+), 123 deletions(-) diff --git a/include/xrpl/basics/Log.h b/include/xrpl/basics/Log.h index 617c2ebbed..2bf6e6a76d 100644 --- a/include/xrpl/basics/Log.h +++ b/include/xrpl/basics/Log.h @@ -26,14 +26,14 @@ #include #include +#include +#include #include #include #include #include -#include -#include -#include #include +#include namespace ripple { @@ -150,14 +150,15 @@ private: beast::severities::Severity thresh_; File file_; bool silent_ = false; - + // Batching members mutable std::mutex batchMutex_; static constexpr size_t BATCH_BUFFER_SIZE = 64 * 1024; // 64KB buffer std::array batchBuffer_; std::span writeBuffer_; // Points to available write space std::span readBuffer_; // Points to data ready to flush - std::chrono::steady_clock::time_point lastFlush_ = std::chrono::steady_clock::now(); + std::chrono::steady_clock::time_point lastFlush_ = + std::chrono::steady_clock::now(); public: Logs(beast::severities::Severity level); @@ -209,7 +210,7 @@ public: std::string rotate(); - + void flushBatch(); @@ -255,7 +256,7 @@ private: // If the message exceeds this length it will be truncated with elipses. maximumMessageCharacters = 12 * 1024 }; - + void flushBatchUnsafe(); }; diff --git a/include/xrpl/beast/utility/Journal.h b/include/xrpl/beast/utility/Journal.h index 41bf428130..0e02336033 100644 --- a/include/xrpl/beast/utility/Journal.h +++ b/include/xrpl/beast/utility/Journal.h @@ -27,6 +27,7 @@ #include #include #include +#include #include #include #include @@ -101,7 +102,8 @@ public: endObject() const { using namespace std::string_view_literals; - buffer_.pop_back(); + if (buffer_.back() == ',') + buffer_.pop_back(); buffer_.append("},"sv); } void @@ -119,7 +121,8 @@ public: endArray() const { using namespace std::string_view_literals; - buffer_.pop_back(); + if (buffer_.back() == ',') + buffer_.pop_back(); buffer_.append("],"sv); } void @@ -348,8 +351,8 @@ private: std::string m_name; std::string m_attributesJson; - static std::atomic> globalLogAttributesJson_; - static std::size_t m_filePathOffset_; + static std::string globalLogAttributesJson_; + static std::shared_mutex globalLogAttributesMutex_; static bool m_jsonLogsEnabled; static thread_local JsonLogContext currentJsonLogContext_; @@ -368,9 +371,6 @@ private: public: //-------------------------------------------------------------------------- - static void - setRootPath(std::string_view fullPath, std::string_view relativePath); - static void enableStructuredJournal(); @@ -742,25 +742,23 @@ public: static void resetGlobalAttributes() { - globalLogAttributesJson_.store(std::make_shared()); + std::unique_lock lock(globalLogAttributesMutex_); + globalLogAttributesJson_.clear(); } template static void addGlobalAttributes(TAttributesFactory&& factory) { - auto current = globalLogAttributesJson_.load(); - std::string buffer = current ? *current : std::string{}; - buffer.reserve(128); - auto isEmpty = buffer.empty(); - detail::SimpleJsonWriter writer{buffer}; + std::unique_lock lock(globalLogAttributesMutex_); + globalLogAttributesJson_.reserve(128); + auto isEmpty = globalLogAttributesJson_.empty(); + detail::SimpleJsonWriter writer{globalLogAttributesJson_}; if (isEmpty) { writer.startObject(); } factory(writer); - - globalLogAttributesJson_.store(std::make_shared(std::move(buffer))); } }; diff --git a/src/libxrpl/basics/Log.cpp b/src/libxrpl/basics/Log.cpp index 0e0e2fb687..996c8bf3f1 100644 --- a/src/libxrpl/basics/Log.cpp +++ b/src/libxrpl/basics/Log.cpp @@ -39,7 +39,8 @@ namespace ripple { namespace { - constexpr auto FLUSH_INTERVAL = std::chrono::milliseconds(10); // Max delay before flush +constexpr auto FLUSH_INTERVAL = + std::chrono::milliseconds(10); // Max delay before flush } Logs::Sink::Sink( @@ -128,7 +129,8 @@ Logs::File::write(std::string_view text) Logs::Logs(beast::severities::Severity thresh) : thresh_(thresh) // default severity - , writeBuffer_(batchBuffer_) // Initially, entire buffer is available for writing + , writeBuffer_( + batchBuffer_) // Initially, entire buffer is available for writing , readBuffer_(batchBuffer_.data(), 0) // No data ready to flush initially { } @@ -193,41 +195,43 @@ Logs::write( { std::string s; format(s, text, level, partition); - + // Console output still immediate for responsiveness if (!silent_) std::cerr << s << '\n'; - + // Add to batch buffer for file output { std::lock_guard lock(batchMutex_); - + size_t logSize = s.size() + 1; // +1 for newline - + // If log won't fit in current write buffer, flush first - if (logSize > writeBuffer_.size()) { + if (logSize > writeBuffer_.size()) + { flushBatchUnsafe(); } - + // Copy log into write buffer std::copy(s.begin(), s.end(), writeBuffer_.begin()); writeBuffer_[s.size()] = '\n'; - + // Update spans: expand read buffer, shrink write buffer size_t totalUsed = readBuffer_.size() + logSize; readBuffer_ = std::span(batchBuffer_.data(), totalUsed); - writeBuffer_ = std::span(batchBuffer_.data() + totalUsed, - batchBuffer_.size() - totalUsed); - + writeBuffer_ = std::span( + batchBuffer_.data() + totalUsed, batchBuffer_.size() - totalUsed); + auto now = std::chrono::steady_clock::now(); bool shouldFlush = (now - lastFlush_) >= FLUSH_INTERVAL; - - if (shouldFlush) { + + if (shouldFlush) + { flushBatchUnsafe(); lastFlush_ = now; } } - + // VFALCO TODO Fix console output // if (console) // out_.write_console(s); @@ -245,10 +249,10 @@ Logs::flushBatchUnsafe() { if (readBuffer_.empty()) return; - + // Write the read buffer contents to file in one system call file_.write(std::string_view{readBuffer_.data(), readBuffer_.size()}); - + // Reset spans: entire buffer available for writing, nothing to read writeBuffer_ = std::span(batchBuffer_); readBuffer_ = std::span(batchBuffer_.data(), 0); diff --git a/src/libxrpl/beast/utility/beast_Journal.cpp b/src/libxrpl/beast/utility/beast_Journal.cpp index b318e2e00c..88ada9664b 100644 --- a/src/libxrpl/beast/utility/beast_Journal.cpp +++ b/src/libxrpl/beast/utility/beast_Journal.cpp @@ -19,12 +19,12 @@ #include +#include #include #include #include #include #include -#include namespace beast { @@ -35,45 +35,50 @@ namespace { std::string_view fastTimestampToString(std::int64_t milliseconds_since_epoch) { - thread_local char buffer[64]; // "2024-01-15T10:30:45.123Z" - + thread_local char buffer[64]; // "2024-01-15T10:30:45.123Z" + // Precomputed lookup table for 2-digit numbers 00-99 static constexpr char digits[200] = { - '0','0','0','1','0','2','0','3','0','4','0','5','0','6','0','7','0','8','0','9', - '1','0','1','1','1','2','1','3','1','4','1','5','1','6','1','7','1','8','1','9', - '2','0','2','1','2','2','2','3','2','4','2','5','2','6','2','7','2','8','2','9', - '3','0','3','1','3','2','3','3','3','4','3','5','3','6','3','7','3','8','3','9', - '4','0','4','1','4','2','4','3','4','4','4','5','4','6','4','7','4','8','4','9', - '5','0','5','1','5','2','5','3','5','4','5','5','5','6','5','7','5','8','5','9', - '6','0','6','1','6','2','6','3','6','4','6','5','6','6','6','7','6','8','6','9', - '7','0','7','1','7','2','7','3','7','4','7','5','7','6','7','7','7','8','7','9', - '8','0','8','1','8','2','8','3','8','4','8','5','8','6','8','7','8','8','8','9', - '9','0','9','1','9','2','9','3','9','4','9','5','9','6','9','7','9','8','9','9' - }; - - constexpr std::int64_t UNIX_EPOCH_DAYS = 719468; // Days from year 0 to 1970-01-01 - + '0', '0', '0', '1', '0', '2', '0', '3', '0', '4', '0', '5', '0', '6', + '0', '7', '0', '8', '0', '9', '1', '0', '1', '1', '1', '2', '1', '3', + '1', '4', '1', '5', '1', '6', '1', '7', '1', '8', '1', '9', '2', '0', + '2', '1', '2', '2', '2', '3', '2', '4', '2', '5', '2', '6', '2', '7', + '2', '8', '2', '9', '3', '0', '3', '1', '3', '2', '3', '3', '3', '4', + '3', '5', '3', '6', '3', '7', '3', '8', '3', '9', '4', '0', '4', '1', + '4', '2', '4', '3', '4', '4', '4', '5', '4', '6', '4', '7', '4', '8', + '4', '9', '5', '0', '5', '1', '5', '2', '5', '3', '5', '4', '5', '5', + '5', '6', '5', '7', '5', '8', '5', '9', '6', '0', '6', '1', '6', '2', + '6', '3', '6', '4', '6', '5', '6', '6', '6', '7', '6', '8', '6', '9', + '7', '0', '7', '1', '7', '2', '7', '3', '7', '4', '7', '5', '7', '6', + '7', '7', '7', '8', '7', '9', '8', '0', '8', '1', '8', '2', '8', '3', + '8', '4', '8', '5', '8', '6', '8', '7', '8', '8', '8', '9', '9', '0', + '9', '1', '9', '2', '9', '3', '9', '4', '9', '5', '9', '6', '9', '7', + '9', '8', '9', '9'}; + + constexpr std::int64_t UNIX_EPOCH_DAYS = + 719468; // Days from year 0 to 1970-01-01 + std::int64_t seconds = milliseconds_since_epoch / 1000; int ms = milliseconds_since_epoch % 1000; std::int64_t days = seconds / 86400 + UNIX_EPOCH_DAYS; int sec_of_day = seconds % 86400; - + // Calculate year, month, day from days using Gregorian calendar algorithm int era = (days >= 0 ? days : days - 146096) / 146097; int doe = days - era * 146097; - int yoe = (doe - doe/1460 + doe/36524 - doe/146096) / 365; + int yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; int year = yoe + era * 400; - int doy = doe - (365*yoe + yoe/4 - yoe/100); - int mp = (5*doy + 2)/153; - int day = doy - (153*mp+2)/5 + 1; + int doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + int mp = (5 * doy + 2) / 153; + int day = doy - (153 * mp + 2) / 5 + 1; int month = mp + (mp < 10 ? 3 : -9); year += (month <= 2); - + // Calculate hour, minute, second int hour = sec_of_day / 3600; int min = (sec_of_day % 3600) / 60; int sec = sec_of_day % 60; - + // Format: "2024-01-15T10:30:45.123Z" buffer[0] = '0' + year / 1000; buffer[1] = '0' + (year / 100) % 10; @@ -99,14 +104,14 @@ fastTimestampToString(std::int64_t milliseconds_since_epoch) buffer[21] = '0' + (ms / 10) % 10; buffer[22] = '0' + ms % 10; buffer[23] = 'Z'; - + return {buffer, 24}; } } // anonymous namespace -std::atomic> Journal::globalLogAttributesJson_; -std::size_t Journal::m_filePathOffset_ = 0; +std::string Journal::globalLogAttributesJson_; +std::shared_mutex Journal::globalLogAttributesMutex_; bool Journal::m_jsonLogsEnabled = false; thread_local Journal::JsonLogContext Journal::currentJsonLogContext_{}; @@ -230,11 +235,11 @@ Journal::JsonLogContext::reset( } { - auto globalAttrs = globalLogAttributesJson_.load(); - if (globalAttrs && !globalAttrs->empty()) + std::shared_lock lock(globalLogAttributesMutex_); + if (!globalLogAttributesJson_.empty()) { writer().writeKey("GlobalParams"); - writer().writeRaw(*globalAttrs); + writer().writeRaw(globalLogAttributesJson_); writer().endObject(); } } @@ -249,8 +254,9 @@ Journal::JsonLogContext::reset( writer().writeKey("File"); std::string_view fileName = location.file_name(); - std::string_view trimmedFileName = (m_filePathOffset_ < fileName.size()) - ? fileName.substr(m_filePathOffset_) + constexpr size_t KEEP_CHARS = 10; + std::string_view trimmedFileName = (fileName.size() > KEEP_CHARS) + ? fileName.substr(fileName.size() - KEEP_CHARS) : fileName; writer().writeString(trimmedFileName); @@ -265,7 +271,8 @@ Journal::JsonLogContext::reset( writer().writeString(severityStr); auto nowMs = std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()).count(); + std::chrono::system_clock::now().time_since_epoch()) + .count(); writer().writeKey("Timestamp"); writer().writeInt(nowMs); writer().writeKey("Time"); @@ -304,19 +311,6 @@ Journal::formatLog(std::string&& message) return writer.finish(); } -void -Journal::setRootPath(std::string_view fullPath, std::string_view relativePath) -{ - if (relativePath.size() <= fullPath.size() && - fullPath.ends_with(relativePath)) - { - m_filePathOffset_ = fullPath.size() - relativePath.size(); - } - else - { - m_filePathOffset_ = 0; - } -} void Journal::enableStructuredJournal() diff --git a/src/tests/libxrpl/basics/log.cpp b/src/tests/libxrpl/basics/log.cpp index fb2dcda5fd..fe631b4100 100644 --- a/src/tests/libxrpl/basics/log.cpp +++ b/src/tests/libxrpl/basics/log.cpp @@ -308,10 +308,12 @@ TEST_CASE("Test setJsonValue") writer.startObject(); log::detail::setJsonValue(writer, "testBool", true, &stringBuf); - log::detail::setJsonValue(writer, "testInt32", -1, &stringBuf); + log::detail::setJsonValue( + writer, "testInt32", -1, &stringBuf); log::detail::setJsonValue( writer, "testUInt32", 1, &stringBuf); - log::detail::setJsonValue(writer, "testInt64", -1, &stringBuf); + log::detail::setJsonValue( + writer, "testInt64", -1, &stringBuf); log::detail::setJsonValue( writer, "testUInt64", 1, &stringBuf); log::detail::setJsonValue(writer, "testDouble", 1.1, &stringBuf); @@ -327,7 +329,9 @@ TEST_CASE("Test setJsonValue") writer, "testStream", {}, &stringBuf); writer.endObject(); - CHECK(writer.finish() == R"AAA({"testBool":true,"testInt32":-1,"testUInt32":1,"testInt64":-1,"testUInt64":1,"testDouble":1.1,"testCharStar":"Char*","testStdString":"StdString","testStdStringView":"StdStringView","testToChars":"0","testStream":"0"})AAA"); + CHECK( + writer.finish() == + R"AAA({"testBool":true,"testInt32":-1,"testUInt32":1,"testInt64":-1,"testUInt64":1,"testDouble":1.1,"testCharStar":"Char*","testStdString":"StdString","testStdStringView":"StdStringView","testToChars":"0","testStream":"0"})AAA"); } TEST_CASE("Test json logging not enabled") @@ -421,30 +425,24 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log fields") CHECK(logValue.is_object()); CHECK(logValue.as_object().contains("GlobalParams")); CHECK(logValue.as_object().contains("JournalParams")); - CHECK(logValue.as_object().contains("MessageParams")); + CHECK(logValue.as_object().contains("Metadata")); CHECK(logValue.as_object().contains("Message")); CHECK(logValue.as_object()["GlobalParams"].is_object()); CHECK(logValue.as_object()["JournalParams"].is_object()); - CHECK(logValue.as_object()["MessageParams"].is_object()); + CHECK(logValue.as_object()["Metadata"].is_object()); CHECK(logValue.as_object()["Message"].is_string()); - CHECK( - logValue.as_object()["MessageParams"].as_object().contains("Function")); - CHECK(logValue.as_object()["MessageParams"].as_object().contains("File")); - CHECK(logValue.as_object()["MessageParams"].as_object().contains("Line")); - CHECK( - logValue.as_object()["MessageParams"].as_object().contains("ThreadId")); - CHECK(logValue.as_object()["MessageParams"].as_object().contains("Level")); - CHECK(logValue.as_object()["MessageParams"].as_object().contains("Time")); + CHECK(logValue.as_object()["Metadata"].as_object().contains("Function")); + CHECK(logValue.as_object()["Metadata"].as_object().contains("File")); + CHECK(logValue.as_object()["Metadata"].as_object().contains("Line")); + CHECK(logValue.as_object()["Metadata"].as_object().contains("ThreadId")); + CHECK(logValue.as_object()["Metadata"].as_object().contains("Level")); + CHECK(logValue.as_object()["Metadata"].as_object().contains("Time")); - CHECK(logValue.as_object()["MessageParams"] - .as_object()["Function"] - .is_string()); - CHECK( - logValue.as_object()["MessageParams"].as_object()["File"].is_string()); - CHECK( - logValue.as_object()["MessageParams"].as_object()["Line"].is_number()); + CHECK(logValue.as_object()["Metadata"].as_object()["Function"].is_string()); + CHECK(logValue.as_object()["Metadata"].as_object()["File"].is_string()); + CHECK(logValue.as_object()["Metadata"].as_object()["Line"].is_number()); CHECK( logValue.as_object()["Message"].get_string() == @@ -462,7 +460,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels") CHECK(ec == boost::system::errc::success); CHECK( - logValue.as_object()["MessageParams"] + logValue.as_object()["Metadata"] .as_object()["Level"] .get_string() == beast::severities::to_string(beast::severities::kTrace)); @@ -477,7 +475,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels") CHECK(ec == boost::system::errc::success); CHECK( - logValue.as_object()["MessageParams"] + logValue.as_object()["Metadata"] .as_object()["Level"] .get_string() == beast::severities::to_string(beast::severities::kDebug)); @@ -492,7 +490,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels") CHECK(ec == boost::system::errc::success); CHECK( - logValue.as_object()["MessageParams"] + logValue.as_object()["Metadata"] .as_object()["Level"] .get_string() == beast::severities::to_string(beast::severities::kInfo)); @@ -507,7 +505,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels") CHECK(ec == boost::system::errc::success); CHECK( - logValue.as_object()["MessageParams"] + logValue.as_object()["Metadata"] .as_object()["Level"] .get_string() == beast::severities::to_string(beast::severities::kWarning)); @@ -522,7 +520,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels") CHECK(ec == boost::system::errc::success); CHECK( - logValue.as_object()["MessageParams"] + logValue.as_object()["Metadata"] .as_object()["Level"] .get_string() == beast::severities::to_string(beast::severities::kError)); @@ -537,7 +535,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log levels") CHECK(ec == boost::system::errc::success); CHECK( - logValue.as_object()["MessageParams"] + logValue.as_object()["Metadata"] .as_object()["Level"] .get_string() == beast::severities::to_string(beast::severities::kFatal)); @@ -553,9 +551,7 @@ TEST_CASE_FIXTURE(JsonLogStreamFixture, "Test json log stream") CHECK(ec == boost::system::errc::success); CHECK( - logValue.as_object()["MessageParams"] - .as_object()["Level"] - .get_string() == + logValue.as_object()["Metadata"].as_object()["Level"].get_string() == beast::severities::to_string(beast::severities::kError)); } diff --git a/src/xrpld/app/main/Application.cpp b/src/xrpld/app/main/Application.cpp index 0ae7e4dce7..a4e0620d57 100644 --- a/src/xrpld/app/main/Application.cpp +++ b/src/xrpld/app/main/Application.cpp @@ -1215,10 +1215,6 @@ ApplicationImp::setup(boost::program_options::variables_map const& cmdline) << ", Instance Cookie: " << log::param("InstanceCookie", instanceCookie_); - beast::Journal::addGlobalAttributes(log::attributes( - log::attr("RippledVersion", BuildInfo::getFullVersionString()), - log::attr("InstanceCookie", to_string(instanceCookie_)))); - if (numberOfThreads(*config_) < 2) { JLOG(m_journal.warn()) << "Limited to a single I/O service thread by " diff --git a/src/xrpld/app/main/Main.cpp b/src/xrpld/app/main/Main.cpp index 304ab30874..f62b641dd2 100644 --- a/src/xrpld/app/main/Main.cpp +++ b/src/xrpld/app/main/Main.cpp @@ -790,11 +790,7 @@ run(int argc, char** argv) if (config->LOG_STYLE == LogStyle::Json) { - beast::Journal::setRootPath(std::source_location::current().file_name(), "src/xrpld/app/main/Main.cpp"); beast::Journal::enableStructuredJournal(); - beast::Journal::addGlobalAttributes(log::attributes( - log::attr("Application", "rippled"), - log::attr("NetworkID", config->NETWORK_ID))); } auto logs = std::make_unique(thresh); diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index 0180e94fa0..26784db736 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -680,7 +680,8 @@ PeerImp::setTimer() if (ec) { - JLOG(journal_.error()) << "setTimer: " << log::param("ErrorCode", ec.message()); + JLOG(journal_.error()) + << "setTimer: " << log::param("ErrorCode", ec.message()); return; } timer_.async_wait(bind_executor(