diff --git a/include/xrpl/basics/Log.h b/include/xrpl/basics/Log.h index 95d4150e2f..617c2ebbed 100644 --- a/include/xrpl/basics/Log.h +++ b/include/xrpl/basics/Log.h @@ -31,6 +31,9 @@ #include #include #include +#include +#include +#include namespace ripple { @@ -129,33 +132,13 @@ private: Does nothing if there is no associated system file. */ void - write(char const* text); + write(std::string_view str); - /** write to the log file and append an end of line marker. - Does nothing if there is no associated system file. - */ - void - writeln(char const* text); - - /** Write to the log file using std::string. */ - /** @{ */ - void - write(std::string const& str) - { - write(str.c_str()); - } - - void - writeln(std::string const& str) - { - writeln(str.c_str()); - } /** @} */ private: std::unique_ptr m_stream; boost::filesystem::path m_path; - std::mutex mutable fileMutex_; }; std::mutex mutable sinkSetMutex_; @@ -167,6 +150,14 @@ 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(); public: Logs(beast::severities::Severity level); @@ -175,7 +166,7 @@ public: Logs& operator=(Logs const&) = delete; - virtual ~Logs() = default; + virtual ~Logs(); // Need to flush on destruction bool open(boost::filesystem::path const& pathToLogFile); @@ -218,6 +209,9 @@ public: std::string rotate(); + + void + flushBatch(); /** * Set flag to write logs to stderr (false) or not (true). @@ -261,6 +255,9 @@ private: // If the message exceeds this length it will be truncated with elipses. maximumMessageCharacters = 12 * 1024 }; + + void + flushBatchUnsafe(); }; // Wraps a Journal::Stream to skip evaluation of diff --git a/include/xrpl/beast/utility/Journal.h b/include/xrpl/beast/utility/Journal.h index 66df05379a..41bf428130 100644 --- a/include/xrpl/beast/utility/Journal.h +++ b/include/xrpl/beast/utility/Journal.h @@ -22,10 +22,11 @@ #include +#include #include #include +#include #include -#include #include #include #include @@ -347,8 +348,8 @@ private: std::string m_name; std::string m_attributesJson; - static std::string globalLogAttributesJson_; - static std::shared_mutex globalLogAttributesMutex_; + static std::atomic> globalLogAttributesJson_; + static std::size_t m_filePathOffset_; static bool m_jsonLogsEnabled; static thread_local JsonLogContext currentJsonLogContext_; @@ -367,6 +368,9 @@ private: public: //-------------------------------------------------------------------------- + static void + setRootPath(std::string_view fullPath, std::string_view relativePath); + static void enableStructuredJournal(); @@ -628,6 +632,7 @@ public: : m_name(name), m_sink(&sink) { std::string buffer; + buffer.reserve(128); detail::SimpleJsonWriter writer{buffer}; writer.startObject(); attributesFactory(writer); @@ -737,25 +742,25 @@ public: static void resetGlobalAttributes() { - std::unique_lock lock(globalLogAttributesMutex_); - globalLogAttributesJson_.clear(); + globalLogAttributesJson_.store(std::make_shared()); } template static void addGlobalAttributes(TAttributesFactory&& factory) { - std::unique_lock lock(globalLogAttributesMutex_); - - auto isEmpty = globalLogAttributesJson_.empty(); - std::string buffer{std::move(globalLogAttributesJson_)}; + auto current = globalLogAttributesJson_.load(); + std::string buffer = current ? *current : std::string{}; + buffer.reserve(128); + auto isEmpty = buffer.empty(); detail::SimpleJsonWriter writer{buffer}; if (isEmpty) { writer.startObject(); } factory(writer); - globalLogAttributesJson_ = std::move(buffer); + + globalLogAttributesJson_.store(std::make_shared(std::move(buffer))); } }; diff --git a/src/libxrpl/basics/Log.cpp b/src/libxrpl/basics/Log.cpp index 197b4e16e3..0e0e2fb687 100644 --- a/src/libxrpl/basics/Log.cpp +++ b/src/libxrpl/basics/Log.cpp @@ -38,6 +38,10 @@ namespace ripple { +namespace { + constexpr auto FLUSH_INTERVAL = std::chrono::milliseconds(10); // Max delay before flush +} + Logs::Sink::Sink( std::string const& partition, beast::severities::Severity thresh, @@ -86,7 +90,6 @@ Logs::File::open(boost::filesystem::path const& path) if (stream->good()) { - std::lock_guard lock(fileMutex_); m_path = path; m_stream = std::move(stream); @@ -111,35 +114,30 @@ Logs::File::closeAndReopen() void Logs::File::close() { - std::lock_guard lock(fileMutex_); m_stream = nullptr; } void -Logs::File::write(char const* text) +Logs::File::write(std::string_view text) { - std::lock_guard lock(fileMutex_); if (m_stream != nullptr) - (*m_stream) << text; -} - -void -Logs::File::writeln(char const* text) -{ - std::lock_guard lock(fileMutex_); - if (m_stream != nullptr) - { - (*m_stream) << text << '\n'; - } + m_stream->write(text.data(), text.size()); } //------------------------------------------------------------------------------ Logs::Logs(beast::severities::Severity thresh) : thresh_(thresh) // default severity + , writeBuffer_(batchBuffer_) // Initially, entire buffer is available for writing + , readBuffer_(batchBuffer_.data(), 0) // No data ready to flush initially { } +Logs::~Logs() +{ + flushBatch(); // Ensure all logs are written on shutdown +} + bool Logs::open(boost::filesystem::path const& pathToLogFile) { @@ -195,17 +193,71 @@ Logs::write( { std::string s; format(s, text, level, partition); - file_.writeln(s); + + // 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()) { + 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); + + auto now = std::chrono::steady_clock::now(); + bool shouldFlush = (now - lastFlush_) >= FLUSH_INTERVAL; + + if (shouldFlush) { + flushBatchUnsafe(); + lastFlush_ = now; + } + } + // VFALCO TODO Fix console output // if (console) // out_.write_console(s); } +void +Logs::flushBatch() +{ + std::lock_guard lock(batchMutex_); + flushBatchUnsafe(); +} + +void +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); +} + std::string Logs::rotate() { + flushBatch(); // Flush pending logs before rotating bool const wasOpened = file_.closeAndReopen(); if (wasOpened) return "The log file was closed and reopened."; diff --git a/src/libxrpl/beast/utility/beast_Journal.cpp b/src/libxrpl/beast/utility/beast_Journal.cpp index 714fac3cd0..b318e2e00c 100644 --- a/src/libxrpl/beast/utility/beast_Journal.cpp +++ b/src/libxrpl/beast/utility/beast_Journal.cpp @@ -22,14 +22,91 @@ #include #include #include -#include #include #include +#include namespace beast { -std::string Journal::globalLogAttributesJson_; -std::shared_mutex Journal::globalLogAttributesMutex_; +namespace { + +// Fast timestamp to ISO string conversion +// Returns string like "2024-01-15T10:30:45.123Z" +std::string_view +fastTimestampToString(std::int64_t milliseconds_since_epoch) +{ + 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 + + 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 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 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; + buffer[2] = '0' + (year / 10) % 10; + buffer[3] = '0' + year % 10; + buffer[4] = '-'; + buffer[5] = digits[month * 2]; + buffer[6] = digits[month * 2 + 1]; + buffer[7] = '-'; + buffer[8] = digits[day * 2]; + buffer[9] = digits[day * 2 + 1]; + buffer[10] = 'T'; + buffer[11] = digits[hour * 2]; + buffer[12] = digits[hour * 2 + 1]; + buffer[13] = ':'; + buffer[14] = digits[min * 2]; + buffer[15] = digits[min * 2 + 1]; + buffer[16] = ':'; + buffer[17] = digits[sec * 2]; + buffer[18] = digits[sec * 2 + 1]; + buffer[19] = '.'; + buffer[20] = '0' + ms / 100; + 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; bool Journal::m_jsonLogsEnabled = false; thread_local Journal::JsonLogContext Journal::currentJsonLogContext_{}; @@ -153,25 +230,29 @@ Journal::JsonLogContext::reset( } { - std::shared_lock lock(globalLogAttributesMutex_); - if (!globalLogAttributesJson_.empty()) + auto globalAttrs = globalLogAttributesJson_.load(); + if (globalAttrs && !globalAttrs->empty()) { writer().writeKey("GlobalParams"); - writer().writeRaw(globalLogAttributesJson_); + writer().writeRaw(*globalAttrs); writer().endObject(); } } writer().writeKey("ModuleName"); writer().writeString(moduleName); - writer().writeKey("MessageParams"); + writer().writeKey("Metadata"); writer().startObject(); writer().writeKey("Function"); writer().writeString(location.function_name()); writer().writeKey("File"); - writer().writeString(location.file_name()); + std::string_view fileName = location.file_name(); + std::string_view trimmedFileName = (m_filePathOffset_ < fileName.size()) + ? fileName.substr(m_filePathOffset_) + : fileName; + writer().writeString(trimmedFileName); writer().writeKey("Line"); writer().writeUInt(location.line()); @@ -183,10 +264,17 @@ Journal::JsonLogContext::reset( writer().writeKey("Level"); writer().writeString(severityStr); + auto nowMs = std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()).count(); + writer().writeKey("Timestamp"); + writer().writeInt(nowMs); writer().writeKey("Time"); - writer().writeInt(std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()) - .count()); + writer().writeString(fastTimestampToString(nowMs)); + + writer().endObject(); + + writer().writeKey("MessageParams"); + writer().startObject(); } void @@ -216,6 +304,19 @@ 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/xrpld/app/main/Main.cpp b/src/xrpld/app/main/Main.cpp index 1531f8c3f0..3bad24de44 100644 --- a/src/xrpld/app/main/Main.cpp +++ b/src/xrpld/app/main/Main.cpp @@ -796,6 +796,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"),