Files
rippled/include/xrpl/core/PerfLog.h
Pratik Mankawde 15596f5b8d feat(telemetry): pinpoint root cause of slow TMGetObjectByHash service
Slowness on the peer object-fetch path could be observed but not
attributed. Job duration metrics carry only `job_type`, and both
`RcvGetLedger` and `RcvGetObjByHash` report as `ledgerRequest`, so a
queue-wait spike could not be traced to a handler. Nothing measured
NodeStore cost, request size, or the differential charge.

Latency now decomposes into three additive parts, each separately
measurable:

    end-to-end = queue wait + NodeStore lookup + everything else

- `handler` label on job_queued_total/_started_total/_finished_total and
  job_queued_us/job_running_us. The value is sanitised: a name passes
  through only if non-empty and all ASCII letters, else "other". Two job
  names embed a ledger sequence, so a raw label would mint one series
  per ledger; the rule bounds the domain at 43 names plus "other".
- getobject_lookup_us, _request_objects, _lookups_total{result},
  _rejected_total{reason} and _charge, recorded at their call sites.
  All three histograms get explicit bucket views: the SDK default stops
  at 10,000, which every one of them exceeds.
- Per-job-type waiting/running/deferred gauges for the 35 non-special
  job types. `deferred` is the leading indicator, since addJob never
  rejects -- it defers, so backpressure otherwise shows up only as
  latency after the fact.

`JobQueue::collect()` snapshots the counters under the queue lock and
publishes gauges after releasing it. Writing them while holding the lock
would invert a lock order against the collector's own lock, which the
collector's flush thread already holds when it calls this hook.

Tests assert exact values, including that the charge is priced on the
requested count rather than the capped iteration count.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-07-25 11:59:16 +01:00

196 lines
4.9 KiB
C++

#pragma once
#include <xrpl/basics/Log.h>
#include <xrpl/core/Job.h>
#include <xrpl/json/json_value.h>
#include <boost/filesystem.hpp>
#include <chrono>
#include <cstdint>
#include <functional>
#include <memory>
#include <string>
namespace beast {
class Journal;
} // namespace beast
namespace xrpl {
class Application;
class Section;
namespace perf {
/**
* Singleton class that maintains performance counters and optionally
* writes Json-formatted data to a distinct log. It should exist prior
* to other objects launched by Application to make it accessible for
* performance logging.
*/
class PerfLog
{
public:
using steady_clock = std::chrono::steady_clock;
using system_clock = std::chrono::system_clock;
using steady_time_point = std::chrono::time_point<steady_clock>;
using system_time_point = std::chrono::time_point<system_clock>;
using seconds = std::chrono::seconds;
using milliseconds = std::chrono::milliseconds;
using microseconds = std::chrono::microseconds;
/**
* Configuration from [perf] section of xrpld.cfg.
*/
struct Setup
{
boost::filesystem::path perfLog;
// log_interval is in milliseconds to support faster testing.
milliseconds logInterval{seconds(1)};
};
virtual ~PerfLog() = default;
virtual void
start()
{
}
virtual void
stop()
{
}
/**
* Log start of RPC call.
*
* @param method RPC command
* @param requestId Unique identifier to track command
*/
virtual void
rpcStart(std::string const& method, std::uint64_t requestId) = 0;
/**
* Log successful finish of RPC call
*
* @param method RPC command
* @param requestId Unique identifier to track command
*/
virtual void
rpcFinish(std::string const& method, std::uint64_t requestId) = 0;
/**
* Log errored RPC call
*
* @param method RPC command
* @param requestId Unique identifier to track command
*/
virtual void
rpcError(std::string const& method, std::uint64_t requestId) = 0;
/**
* Log queued job
*
* @param type Job type
* @param name Job name as given to JobQueue::addJob. Distinguishes the
* several producers that share one job type. May be empty.
*/
virtual void
jobQueue(JobType const type, std::string const& name) = 0;
/**
* Log job executing
*
* @param type Job type
* @param name Job name as given to JobQueue::addJob. Distinguishes the
* several producers that share one job type. May be empty.
* @param dur Duration enqueued in microseconds
* @param startTime Time that execution began
* @param instance JobQueue worker thread instance
*/
virtual void
jobStart(
JobType const type,
std::string const& name,
microseconds dur,
steady_time_point startTime,
int instance) = 0;
/**
* Log job finishing
*
* @param type Job type
* @param name Job name as given to JobQueue::addJob. Distinguishes the
* several producers that share one job type. May be empty.
* @param dur Duration running in microseconds
* @param instance Jobqueue worker thread instance
*/
virtual void
jobFinish(JobType const type, std::string const& name, microseconds dur, int instance) = 0;
/**
* Render performance counters in Json
*
* @return Counters Json object
*/
[[nodiscard]] virtual json::Value
countersJson() const = 0;
/**
* Render currently executing jobs and RPC calls and durations in Json
*
* @return Current executing jobs and RPC calls and durations
*/
[[nodiscard]] virtual json::Value
currentJson() const = 0;
/**
* Ensure enough room to store each currently executing job
*
* @param resize Number of JobQueue worker threads
*/
virtual void
resizeJobs(int const resize) = 0;
/**
* Rotate perf log file
*/
virtual void
rotate() = 0;
};
PerfLog::Setup
setupPerfLog(Section const& section, boost::filesystem::path const& configDir);
std::unique_ptr<PerfLog>
makePerfLog(
PerfLog::Setup const& setup,
Application& app,
beast::Journal journal,
std::function<void()>&& signalStop);
template <typename Func, class Rep, class Period>
auto
measureDurationAndLog(
Func&& func,
std::string const& actionDescription,
std::chrono::duration<Rep, Period> maxDelay,
beast::Journal const& journal)
{
auto startTime = std::chrono::high_resolution_clock::now();
auto result = func();
auto endTime = std::chrono::high_resolution_clock::now();
auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(endTime - startTime);
if (duration > maxDelay)
{
JLOG(journal.warn()) << actionDescription << " took " << duration.count() << " ms";
}
return result;
}
} // namespace perf
} // namespace xrpl