Optimisation

Signed-off-by: JCW <a1q123456@users.noreply.github.com>
This commit is contained in:
JCW
2025-09-04 16:03:52 +01:00
parent 0223443452
commit bb787e3995
5 changed files with 215 additions and 59 deletions

View File

@@ -31,6 +31,9 @@
#include <memory>
#include <mutex>
#include <utility>
#include <chrono>
#include <array>
#include <span>
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<std::ofstream> 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<char, BATCH_BUFFER_SIZE> batchBuffer_;
std::span<char> writeBuffer_; // Points to available write space
std::span<char> 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

View File

@@ -22,10 +22,11 @@
#include <xrpl/beast/utility/instrumentation.h>
#include <atomic>
#include <charconv>
#include <cstring>
#include <memory>
#include <mutex>
#include <shared_mutex>
#include <source_location>
#include <sstream>
#include <string>
@@ -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<std::shared_ptr<const std::string>> 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<const std::string>());
}
template <typename TAttributesFactory>
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<const std::string>(std::move(buffer)));
}
};

View File

@@ -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<char>(batchBuffer_.data(), totalUsed);
writeBuffer_ = std::span<char>(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<char>(batchBuffer_);
readBuffer_ = std::span<char>(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.";

View File

@@ -22,14 +22,91 @@
#include <ios>
#include <ostream>
#include <ranges>
#include <shared_mutex>
#include <string>
#include <thread>
#include <chrono>
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<std::shared_ptr<const std::string>> 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::milliseconds>(
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::milliseconds>(
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()

View File

@@ -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"),