mirror of
https://github.com/XRPLF/rippled.git
synced 2026-08-19 13:20:54 +00:00
Merge branch 'pratik/otel-phase10-workload-validation' into pratik/otel-sync-diagnostics
Resolves the nodestore latency-accumulator conflict by keeping this branch's API surface and applying the incoming nanosecond fix to it. This branch had renamed storeDurationStats() to recordStoreDuration() and given it noexcept, an explicit relaxed fetch_add, and call-frequency and thread-safety notes. The incoming change fixed the accumulators to hold nanoseconds so sub-microsecond backend calls stop rounding to zero. Both are kept: the name, signature and documentation from here, the nanosecond accumulation from there. The incoming duplicate getFetchDurationUs()/getStoreDurationUs() pair is dropped in favour of this branch's noexcept versions, which now read the nanosecond members and convert on read. recordStoreDuration()'s `if (us > 0)` guard is gone: it discarded every sub-microsecond store, which is the same rounding the incoming change removes one level up. Also updates a MetricMacros comment that explained the zero write mean in terms of that removed guard; the injected totals it asserts on are unchanged.
This commit is contained in:
@@ -242,6 +242,10 @@ public:
|
||||
*
|
||||
* @return Total microseconds accumulated across every completed store.
|
||||
*
|
||||
* @note Accumulated in nanoseconds and converted here, so the total is
|
||||
* exact to within one microsecond however fast the stores are. Truncated
|
||||
* rather than rounded: stores totalling under a microsecond read as 0 until
|
||||
* they sum past 1000 ns.
|
||||
* @note Thread-safe: a single relaxed atomic load. Cheap enough for a
|
||||
* periodic observer (the telemetry reader ticks every ~10 s). Relaxed is
|
||||
* sufficient because the value is a monotonic statistic, not a
|
||||
@@ -254,7 +258,7 @@ public:
|
||||
[[nodiscard]] std::uint64_t
|
||||
getStoreDurationUs() const noexcept
|
||||
{
|
||||
return storeDurationUs_.load(std::memory_order_relaxed);
|
||||
return storeDurationNs_.load(std::memory_order_relaxed) / kNanosecondsPerMicrosecond;
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -269,13 +273,13 @@ public:
|
||||
*
|
||||
* @return Total microseconds accumulated across every completed fetch.
|
||||
*
|
||||
* @note Same threading and monotonicity contract as
|
||||
* getStoreDurationUs().
|
||||
* @note Same threading, monotonicity and nanosecond-accumulation contract
|
||||
* as getStoreDurationUs().
|
||||
*/
|
||||
[[nodiscard]] std::uint64_t
|
||||
getFetchDurationUs() const noexcept
|
||||
{
|
||||
return fetchDurationUs_.load(std::memory_order_relaxed);
|
||||
return fetchDurationNs_.load(std::memory_order_relaxed) / kNanosecondsPerMicrosecond;
|
||||
}
|
||||
|
||||
void
|
||||
@@ -337,10 +341,14 @@ protected:
|
||||
* The write counterpart of the timing fetchNodeObject() already does for
|
||||
* reads. `store()` is pure virtual, so unlike the read path there is no
|
||||
* non-virtual wrapper in this class to time — each concrete database calls
|
||||
* this once per store it completes, and the single conversion to
|
||||
* microseconds lives here rather than being repeated per subclass. Each
|
||||
* concrete store path times only its backend call, so the total reflects
|
||||
* disk work and excludes cache bookkeeping.
|
||||
* this once per store it completes, and the single conversion lives here
|
||||
* rather than being repeated per subclass. Each concrete store path times
|
||||
* only its backend call, so the total reflects disk work and excludes cache
|
||||
* bookkeeping.
|
||||
*
|
||||
* Takes the raw duration rather than a converted integer, so every caller
|
||||
* accumulates at the same resolution. See storeDurationNs_ for the
|
||||
* accumulate-then-convert contract.
|
||||
*
|
||||
* @param elapsed Wall time the store took, as measured by the caller.
|
||||
*
|
||||
@@ -351,28 +359,37 @@ protected:
|
||||
* @note Thread-safe: one relaxed atomic add, no lock. Relaxed ordering is
|
||||
* correct because the total is a statistic that is only ever read by a
|
||||
* periodic observer, never used to order other memory operations.
|
||||
* @note A negative duration cannot occur (steady_clock is monotonic), but
|
||||
* a caller passing one would be clamped to zero rather than wrapping the
|
||||
* unsigned total to a huge value.
|
||||
* @note A negative duration cannot occur (steady_clock is monotonic); one
|
||||
* would convert to a large unsigned value here, so callers must pass an
|
||||
* end-minus-begin span from a single clock.
|
||||
*/
|
||||
void
|
||||
recordStoreDuration(std::chrono::steady_clock::duration elapsed) noexcept
|
||||
{
|
||||
auto const us = std::chrono::duration_cast<std::chrono::microseconds>(elapsed).count();
|
||||
if (us > 0)
|
||||
storeDurationUs_.fetch_add(static_cast<std::uint64_t>(us), std::memory_order_relaxed);
|
||||
storeDurationNs_.fetch_add(
|
||||
static_cast<std::uint64_t>(
|
||||
std::chrono::duration_cast<std::chrono::nanoseconds>(elapsed).count()),
|
||||
std::memory_order_relaxed);
|
||||
}
|
||||
|
||||
// Called by the public import function
|
||||
void
|
||||
importInternal(Backend& dstBackend, Database& srcDB);
|
||||
|
||||
/**
|
||||
* Fold an imported database's read counters into this one's.
|
||||
*
|
||||
* @param fetches Number of completed fetches to add.
|
||||
* @param hits Number of those fetches that found their object.
|
||||
* @param durationUs Wall time of those fetches, in microseconds. Scaled up
|
||||
* to nanoseconds internally to match the accumulator's unit.
|
||||
*/
|
||||
void
|
||||
updateFetchMetrics(uint64_t fetches, uint64_t hits, uint64_t duration)
|
||||
updateFetchMetrics(uint64_t fetches, uint64_t hits, uint64_t durationUs)
|
||||
{
|
||||
fetchTotalCount_ += fetches;
|
||||
fetchHitCount_ += hits;
|
||||
fetchDurationUs_ += duration;
|
||||
fetchDurationNs_ += durationUs * kNanosecondsPerMicrosecond;
|
||||
}
|
||||
|
||||
private:
|
||||
@@ -397,20 +414,35 @@ private:
|
||||
std::atomic<std::uint64_t> fetchSz_{0};
|
||||
|
||||
/**
|
||||
* Wall time spent in backend fetches, in microseconds.
|
||||
* Divisor converting the nanosecond accumulators to microseconds.
|
||||
*
|
||||
* Named rather than inline so the two accessors and updateFetchMetrics()
|
||||
* cannot drift onto different scale factors.
|
||||
*/
|
||||
static constexpr std::uint64_t kNanosecondsPerMicrosecond = 1000;
|
||||
|
||||
/**
|
||||
* Wall time spent in backend fetches, in nanoseconds.
|
||||
*
|
||||
* Written by fetchNodeObject(), which times the whole fetch including a
|
||||
* cache lookup that misses.
|
||||
*
|
||||
* Nanoseconds, the clock's own resolution, because a warm store answers a
|
||||
* read in a few hundred of them. Accumulating here and converting once, in
|
||||
* getFetchDurationUs(), keeps the total exact to within one microsecond
|
||||
* regardless of how fast the reads are. A 64-bit nanosecond counter spans
|
||||
* roughly 584 years, so it cannot wrap on any real node.
|
||||
*/
|
||||
std::atomic<std::uint64_t> fetchDurationUs_{0};
|
||||
std::atomic<std::uint64_t> fetchDurationNs_{0};
|
||||
|
||||
/**
|
||||
* Wall time spent in backend stores, in microseconds.
|
||||
* Wall time spent in backend stores, in nanoseconds.
|
||||
*
|
||||
* Written by each concrete store path via recordStoreDuration(), which
|
||||
* times only the backend call.
|
||||
* times only the backend call. Nanoseconds for the same
|
||||
* accumulate-then-convert reason as fetchDurationNs_.
|
||||
*/
|
||||
std::atomic<std::uint64_t> storeDurationUs_{0};
|
||||
std::atomic<std::uint64_t> storeDurationNs_{0};
|
||||
|
||||
mutable std::mutex readLock_;
|
||||
std::condition_variable readCondVar_;
|
||||
|
||||
@@ -250,11 +250,14 @@ Database::fetchNodeObject(
|
||||
auto nodeObject{fetchNodeObject(hash, ledgerSeq, fetchReport, duplicate)};
|
||||
auto dur = steady_clock::now() - begin;
|
||||
|
||||
// Measured once and used for both the cumulative counter and the
|
||||
// scheduler report, so the two can never disagree about how long this
|
||||
// fetch took.
|
||||
// One measurement, dur, feeds both the cumulative counter and the scheduler
|
||||
// report, so the two can never disagree about how long this fetch took.
|
||||
// They express it in different units: the counter accumulates nanoseconds,
|
||||
// the clock's own resolution, so a run of reads each faster than a
|
||||
// microsecond still sums to the right total; the report carries
|
||||
// microseconds, the unit FetchReport::elapsed declares.
|
||||
fetchDurationNs_ += static_cast<std::uint64_t>(duration_cast<nanoseconds>(dur).count());
|
||||
auto const elapsedUs = duration_cast<microseconds>(dur);
|
||||
fetchDurationUs_ += elapsedUs.count();
|
||||
if (nodeObject)
|
||||
{
|
||||
++fetchHitCount_;
|
||||
@@ -286,8 +289,10 @@ Database::getCountsJson(json::Value& obj)
|
||||
obj[jss::node_reads_hit] = std::to_string(fetchHitCount_);
|
||||
obj[jss::node_written_bytes] = std::to_string(storeSz_);
|
||||
obj[jss::node_read_bytes] = std::to_string(fetchSz_);
|
||||
obj[jss::node_reads_duration_us] = std::to_string(fetchDurationUs_);
|
||||
obj[jss::node_writes_duration_us] = std::to_string(storeDurationUs_);
|
||||
// Through the accessors: the accumulators hold nanoseconds and these two
|
||||
// fields are declared in microseconds.
|
||||
obj[jss::node_reads_duration_us] = std::to_string(getFetchDurationUs());
|
||||
obj[jss::node_writes_duration_us] = std::to_string(getStoreDurationUs());
|
||||
}
|
||||
|
||||
} // namespace xrpl::node_store
|
||||
|
||||
@@ -161,20 +161,17 @@ private:
|
||||
};
|
||||
|
||||
/**
|
||||
* Assert the read accumulator holds exactly what the fetch reports carried.
|
||||
* Assert the read accumulator agrees with what the fetch reports carried.
|
||||
*
|
||||
* Deliberately not `getFetchDurationUs() > 0`: an individual read served
|
||||
* from NuDB's in-memory buckets can genuinely measure under one
|
||||
* microsecond and truncate to zero, so on a fast enough host every read
|
||||
* truncates and the total stays at zero with nothing wrong. That makes
|
||||
* `> 0` an assertion about the machine rather than about the code, and it
|
||||
* is what failed on the macOS runner.
|
||||
* The accumulator keeps nanoseconds and each report carries its own fetch
|
||||
* truncated to whole microseconds, so the reported sum is the accumulated
|
||||
* total minus one sub-microsecond remainder per fetch. That gives a bound
|
||||
* rather than an equality, and the bound is machine-independent: an
|
||||
* accumulator that dropped a fetch, double-counted one, or reported the
|
||||
* write member instead would break it however fast the host is.
|
||||
*
|
||||
* The equality below is machine-independent and strictly stronger: each
|
||||
* fetch is measured once and that one value feeds both the accumulator
|
||||
* and the report, so an accumulator that dropped a fetch, double-counted
|
||||
* one, or reported the write member instead would break the equality
|
||||
* however fast the host is.
|
||||
* Deliberately not `getFetchDurationUs() > 0` on its own: that is an
|
||||
* assertion about how fast the host reads, not about the code.
|
||||
*
|
||||
* @param db Database whose read accumulator is checked.
|
||||
* @param scheduler Scheduler that received the reports for @p db.
|
||||
@@ -187,7 +184,10 @@ private:
|
||||
std::uint64_t expectedReports)
|
||||
{
|
||||
BEAST_EXPECT(scheduler.fetchReports.load() == expectedReports);
|
||||
BEAST_EXPECT(db.getFetchDurationUs() == scheduler.reportedFetchUs.load());
|
||||
auto const accumulatedUs = db.getFetchDurationUs();
|
||||
auto const reportedUs = scheduler.reportedFetchUs.load();
|
||||
BEAST_EXPECT(reportedUs <= accumulatedUs);
|
||||
BEAST_EXPECT(accumulatedUs - reportedUs <= expectedReports);
|
||||
}
|
||||
|
||||
public:
|
||||
|
||||
@@ -321,22 +321,21 @@ TEST(NodeStoreDatabase, sub_millisecond_fetch_latency_is_reported)
|
||||
ASSERT_EQ(scheduler.fetchCount.load(), kNumStored);
|
||||
EXPECT_EQ(scheduler.foundCount.load(), kNumStored);
|
||||
|
||||
// The nodestore's own microsecond accumulator moved, so there is real
|
||||
// measured time for the reports to carry.
|
||||
// The accumulator keeps nanoseconds internally, so 256 reads sum past a
|
||||
// microsecond and register here even when each individual read finishes in
|
||||
// well under one. This is a statement about the accumulator's resolution,
|
||||
// not about this machine's speed: to still read zero, all 256 reads would
|
||||
// have to complete inside a single microsecond in total.
|
||||
auto const internalUs = db->getFetchDurationUs();
|
||||
ASSERT_GT(internalUs, 0u);
|
||||
|
||||
// The core assertion. Database::fetchNodeObject() measures each fetch once
|
||||
// and uses that one value for both the internal accumulator and the
|
||||
// report, so the two totals must agree exactly. A millisecond-typed report
|
||||
// truncates every sub-millisecond fetch to zero and this fails.
|
||||
EXPECT_EQ(scheduler.totalReportedUs.load(), internalUs);
|
||||
|
||||
// Independent of the equality above, and independent of how fast this
|
||||
// machine is: a millisecond-typed duration always converts to a whole
|
||||
// multiple of 1000 microseconds, so at least one report carrying a
|
||||
// non-multiple proves the field itself holds sub-millisecond resolution.
|
||||
EXPECT_GT(scheduler.subMillisecondCount.load(), 0u);
|
||||
// Each report truncates its own fetch to whole microseconds, while the
|
||||
// accumulator keeps the remainder. The reported total can therefore only be
|
||||
// smaller than the accumulated one, and only by the discarded remainder of
|
||||
// each fetch, which is strictly under 1 us per fetch.
|
||||
auto const reportedUs = scheduler.totalReportedUs.load();
|
||||
EXPECT_LE(reportedUs, internalUs);
|
||||
EXPECT_LE(internalUs - reportedUs, kNumStored);
|
||||
|
||||
// Negative path: a miss is still a fetch, so it is still reported and
|
||||
// still timed, but it is not a hit. A report that only fired on hits
|
||||
@@ -350,16 +349,18 @@ TEST(NodeStoreDatabase, sub_millisecond_fetch_latency_is_reported)
|
||||
EXPECT_EQ(scheduler.fetchCount.load(), kNumStored + kNumMissing);
|
||||
EXPECT_EQ(scheduler.foundCount.load(), kNumStored);
|
||||
|
||||
// The totals still agree once misses are included, so the miss path
|
||||
// reports exactly what it measured rather than substituting a zero.
|
||||
// The same bound still holds once misses are included, so the miss path
|
||||
// reports what it measured rather than substituting a zero.
|
||||
//
|
||||
// GE and not GT: a cumulative total cannot shrink, but an individual miss
|
||||
// served from NuDB's in-memory buckets can genuinely measure under one
|
||||
// microsecond and truncate to zero, so requiring growth here would be a
|
||||
// statement about this machine's speed rather than about the code.
|
||||
// GE and not GT: a cumulative total cannot shrink, but the microsecond view
|
||||
// of it only advances once the accumulated nanoseconds cross the next
|
||||
// thousand, so requiring growth from 32 more reads would be a statement
|
||||
// about this machine's speed rather than about the code.
|
||||
auto const internalUsWithMisses = db->getFetchDurationUs();
|
||||
EXPECT_GE(internalUsWithMisses, internalUs);
|
||||
EXPECT_EQ(scheduler.totalReportedUs.load(), internalUsWithMisses);
|
||||
auto const reportedUsWithMisses = scheduler.totalReportedUs.load();
|
||||
EXPECT_LE(reportedUsWithMisses, internalUsWithMisses);
|
||||
EXPECT_LE(internalUsWithMisses - reportedUsWithMisses, kNumStored + kNumMissing);
|
||||
|
||||
// Reads perform no writes, so the write-report count cannot have moved.
|
||||
EXPECT_EQ(scheduler.batchWriteCount.load(), kNumStored);
|
||||
|
||||
@@ -2847,14 +2847,14 @@ TEST(MetricMacros, nodestore_state_gauge_observes_exact_derived_means)
|
||||
EXPECT_EQ(truncating.at("nodestore_state").count(attrs("metric", "read_mean_us")), 0u);
|
||||
EXPECT_EQ(gaugeValue(truncating, "nodestore_state", attrs("metric", "node_reads_total")), 0);
|
||||
|
||||
// EDGE CASE: stores counted, but every one measured below a microsecond.
|
||||
// recordStoreDuration() only adds when the cast to microseconds is > 0, so
|
||||
// sub-microsecond stores leave the duration total at 0 while the count
|
||||
// climbs. scaledMean divides on the COUNT alone, so it reports a genuine
|
||||
// mean of 0 here rather than omitting the series. That is the correct
|
||||
// reading: the stores really did complete
|
||||
// in under a microsecond each, and the total beside it proves they
|
||||
// happened. Absence is reserved for "no samples at all".
|
||||
// EDGE CASE: stores counted, but the duration total still reads zero.
|
||||
// The accumulator keeps nanoseconds and getStoreDurationUs() truncates, so
|
||||
// a total under one microsecond reads as 0 while the count climbs.
|
||||
// scaledMean divides on the COUNT alone, so it reports a genuine mean of 0
|
||||
// here rather than omitting the series. That is the correct reading: the
|
||||
// stores really did complete in under a microsecond in total, and the count
|
||||
// beside it proves they happened. Absence is reserved for "no samples at
|
||||
// all".
|
||||
totals = NodeStoreTotals{
|
||||
.storeCount = 9000, .storeDurationUs = 0, .fetchCount = 10, .fetchDurationUs = 50};
|
||||
auto const subMicrosecond = collectWith(totals);
|
||||
|
||||
Reference in New Issue
Block a user