mirror of
https://github.com/XRPLF/rippled.git
synced 2026-07-29 18:10:34 +00:00
Merge branch 'pratik/otel-phase9-metric-gap-fill' into pratik/otel-phase10-workload-validation
# Conflicts: # docs/telemetry-runbook.md # src/test/nodestore/DatabaseConfig_test.cpp
This commit is contained in:
Pratik Mankawde
@@ -135,11 +135,11 @@ test.ledger > xrpl.json
|
||||
test.ledger > xrpl.ledger
|
||||
test.ledger > xrpl.protocol
|
||||
test.nodestore > test.jtx
|
||||
test.nodestore > test.unit_test
|
||||
test.nodestore > xrpl.basics
|
||||
test.nodestore > xrpl.config
|
||||
test.nodestore > xrpld.core
|
||||
test.nodestore > xrpl.nodestore
|
||||
test.nodestore > xrpl.protocol
|
||||
test.nodestore > xrpl.rdb
|
||||
test.overlay > test.jtx
|
||||
test.overlay > test.unit_test
|
||||
|
||||
55
.github/scripts/otel-naming/check_otel_naming.py
vendored
55
.github/scripts/otel-naming/check_otel_naming.py
vendored
@@ -154,9 +154,22 @@ BLOCK_COMMENT = re.compile(r"/\*.*?\*/", re.DOTALL)
|
||||
# Dashboards reference span attributes in TraceQL as `span.<attr>`; the bare
|
||||
# attribute is what must exist in L1, so strip the scope before validating.
|
||||
TRACEQL_SCOPE = re.compile(r"^(?:span|resource|event|link|instrumentation_scope)\.")
|
||||
# An OTel metric label key as emitted in C++: `Add(.., {{"label", ...}})` /
|
||||
# `{{"label", value}}` instrument calls in MetricsRegistry.
|
||||
METRIC_LABEL = re.compile(r'\{\{\s*"([a-z_][a-z0-9_]*)"\s*,')
|
||||
# An OTel metric label map as emitted in C++: the `{{...}}` argument of an
|
||||
# instrument call, e.g. `counter->Add(1, {{"job_type", a}, {"handler", b}})`.
|
||||
# Matching the whole map first, rather than scanning the file for `{"key",`,
|
||||
# keeps ordinary brace initializers (`{"http", "https", ...}`) out of the
|
||||
# label set — they are not labels and must not license a dashboard filter.
|
||||
METRIC_LABEL_MAP = re.compile(r"\{\{(.*?)\}\}", re.DOTALL)
|
||||
# One key inside such a map: a string literal, or a `kFooLabel` constant name
|
||||
# resolved through LABEL_CONST_DEF. Inside the map, each pair opens with `{`,
|
||||
# except the first, whose `{` was consumed by the map's own `{{`.
|
||||
METRIC_LABEL = re.compile(r'(?:^|\{)\s*"([a-z_][a-z0-9_]*)"\s*,')
|
||||
METRIC_LABEL_CONST = re.compile(r"(?:^|\{)\s*(k[A-Za-z0-9_]*)\s*,")
|
||||
# A label-key constant definition, with or without `inline`:
|
||||
# `constexpr char kHandlerLabel[] = "handler";`
|
||||
LABEL_CONST_DEF = re.compile(
|
||||
r'(?:inline\s+)?constexpr\s+char\s+(k[A-Za-z0-9_]*)\s*\[\s*\]\s*=\s*"([a-z_][a-z0-9_]*)"'
|
||||
)
|
||||
|
||||
|
||||
def strip_comments(text: str) -> str:
|
||||
@@ -799,16 +812,36 @@ def run_rule_c_tempo(root: Path, l1_keys: Set[str], report: Report) -> None:
|
||||
def metric_label_names(root: Path) -> Set[str]:
|
||||
"""L6: OTel native-metric label keys emitted by the telemetry code, e.g.
|
||||
`counter->Add(1, {{"job_type", value}})` in MetricsRegistry.cpp. These are
|
||||
a valid source of dashboard labels distinct from span attributes (L1)."""
|
||||
a valid source of dashboard labels distinct from span attributes (L1).
|
||||
|
||||
A label key may be written inline as a string literal or hoisted into a
|
||||
named constant (`constexpr char kHandlerLabel[] = "handler";`, then
|
||||
`{{kHandlerLabel, value}}`). Both forms are collected, and the constants
|
||||
may be declared in a header, so headers are scanned as well as sources."""
|
||||
labels: Set[str] = set()
|
||||
# Constant name -> label string, gathered across every scanned file so a
|
||||
# `{{kFooLabel, ...}}` call site resolves even when the definition lives in
|
||||
# a different file from the instrument call.
|
||||
constants: Dict[str, str] = {}
|
||||
used_constants: Set[str] = set()
|
||||
for base in ("src", "include"):
|
||||
for p in (root / base).rglob("*.cpp"):
|
||||
if not p.is_file():
|
||||
continue
|
||||
text = read_source(p)
|
||||
if "MetricsRegistry" not in p.name and "metric" not in text.lower():
|
||||
continue
|
||||
labels |= set(METRIC_LABEL.findall(text))
|
||||
for pattern in ("*.cpp", "*.h"):
|
||||
for p in (root / base).rglob(pattern):
|
||||
if not p.is_file():
|
||||
continue
|
||||
# Test code passes arbitrary literal pairs to exercise APIs
|
||||
# (`signers("alice", 1, {{"alice", 1}, {"bob", 2}})`). Those are
|
||||
# not metric labels, and must not license a dashboard filter.
|
||||
if is_test_path(p):
|
||||
continue
|
||||
text = read_source(p)
|
||||
if "MetricsRegistry" not in p.name and "metric" not in text.lower():
|
||||
continue
|
||||
constants.update(dict(LABEL_CONST_DEF.findall(text)))
|
||||
for label_map in METRIC_LABEL_MAP.findall(text):
|
||||
labels |= set(METRIC_LABEL.findall(label_map))
|
||||
used_constants |= set(METRIC_LABEL_CONST.findall(label_map))
|
||||
labels |= {constants[name] for name in used_constants if name in constants}
|
||||
return labels
|
||||
|
||||
|
||||
|
||||
@@ -835,6 +835,69 @@ class MetricLabelExtraction(unittest.TestCase):
|
||||
finally:
|
||||
shutil.rmtree(d)
|
||||
|
||||
def test_extracts_second_label_of_a_pair(self):
|
||||
"""A multi-label map opens the first pair with `{{` and later ones with
|
||||
a single `{`; every key must be collected, not just the first."""
|
||||
d = Path(tempfile.mkdtemp())
|
||||
try:
|
||||
_write(
|
||||
d / "src" / "xrpld" / "telemetry" / "MetricsRegistry.cpp",
|
||||
'h->Record(v, {{"job_type", std::string(t)}, {"handler", h2}});\n',
|
||||
)
|
||||
self.assertEqual(chk.metric_label_names(d), {"job_type", "handler"})
|
||||
finally:
|
||||
shutil.rmtree(d)
|
||||
|
||||
def test_resolves_label_key_constants(self):
|
||||
"""A key hoisted into a `constexpr char k...[]` constant resolves to its
|
||||
string, including when the constant is declared in a header."""
|
||||
d = Path(tempfile.mkdtemp())
|
||||
try:
|
||||
_write(
|
||||
d / "include" / "xrpl" / "telemetry" / "GetObjectMetricNames.h",
|
||||
"// metric name constants\n"
|
||||
'inline constexpr char kLabelResult[] = "result";\n',
|
||||
)
|
||||
_write(
|
||||
d / "src" / "xrpld" / "telemetry" / "MetricsRegistry.cpp",
|
||||
'constexpr char kHandlerLabel[] = "handler";\n'
|
||||
"counter->Add(1, {{kLabelResult, std::string(r)}});\n"
|
||||
'c2->Add(1, {{"job_type", std::string(t)}, {kHandlerLabel, h}});\n',
|
||||
)
|
||||
self.assertEqual(
|
||||
chk.metric_label_names(d), {"result", "handler", "job_type"}
|
||||
)
|
||||
finally:
|
||||
shutil.rmtree(d)
|
||||
|
||||
def test_ignores_plain_brace_initializers(self):
|
||||
"""Ordinary brace lists are not label maps: a bare `{"http", "https"}`
|
||||
array must not license a dashboard filter on `http`."""
|
||||
d = Path(tempfile.mkdtemp())
|
||||
try:
|
||||
_write(
|
||||
d / "src" / "xrpld" / "telemetry" / "MetricsRegistry.cpp",
|
||||
'std::array schemes{"http", "https", "ws"};\n'
|
||||
'for (auto const* k : {"read_request_bundle", "read_threads"})\n'
|
||||
" use(k);\n"
|
||||
'counter->Add(1, {{"job_type", std::string(t)}});\n',
|
||||
)
|
||||
self.assertEqual(chk.metric_label_names(d), {"job_type"})
|
||||
finally:
|
||||
shutil.rmtree(d)
|
||||
|
||||
def test_ignores_test_code_literals(self):
|
||||
"""Test fixtures pass arbitrary literal pairs; they define no labels."""
|
||||
d = Path(tempfile.mkdtemp())
|
||||
try:
|
||||
_write(
|
||||
d / "src" / "test" / "jtx" / "Env_test.cpp",
|
||||
"// metric\n" 'env(signers("alice", 1, {{"alice", 1}, {"bob", 2}}));\n',
|
||||
)
|
||||
self.assertEqual(chk.metric_label_names(d), set())
|
||||
finally:
|
||||
shutil.rmtree(d)
|
||||
|
||||
|
||||
class ReportExitContract(unittest.TestCase):
|
||||
@staticmethod
|
||||
|
||||
@@ -1014,6 +1014,12 @@ repeated here:
|
||||
`_running` / `_deferred`). These travel the `beast::insight` pipeline, not the
|
||||
OTel SDK one, so they are documented in
|
||||
[§2.5](#25-per-job-type-queue-gauges).
|
||||
- The sync-diagnosis signals — 13 further `nodestore_state` label values plus the
|
||||
`nodestore_read_us` histogram — which separate a write-serialized stall from a
|
||||
cold-read stall. See
|
||||
[Sync Diagnosis Signals](#sync-diagnosis-signals-observable-gauge--nodestore_state)
|
||||
and
|
||||
[NodeStore Read Latency](#nodestore-read-latency-histogram--nodestore_read_us).
|
||||
|
||||
### New Grafana Dashboards (Phase 9)
|
||||
|
||||
@@ -1176,6 +1182,96 @@ via OTLP/HTTP to the OTel Collector and scraped by Prometheus.
|
||||
| `nodestore_state{metric="write_load"}` | Gauge | `metric` | Current write load score |
|
||||
| `nodestore_state{metric="read_queue"}` | Gauge | `metric` | Items in read prefetch queue |
|
||||
|
||||
> **`node_reads_hit` is a found count, not a cache-hit rate.** `fetchHitCount_`
|
||||
> is incremented whenever the fetch returned an object
|
||||
> (`src/libxrpl/nodestore/Database.cpp:246-255`), regardless of where it came
|
||||
> from. The ratio against `node_reads_total` is therefore the fraction of fetches
|
||||
> that **found** something, and can read ~100% while every fetch went to disk.
|
||||
> Pair it with `read_mean_us` before drawing any conclusion — see
|
||||
> [Slow to reach `full`](../docs/telemetry-runbook.md#slow-to-reach-full).
|
||||
|
||||
#### Sync Diagnosis Signals (Observable Gauge — `nodestore_state`)
|
||||
|
||||
Further label values on the same instrument, added to separate the two
|
||||
bottlenecks that both present as the `ledgerData` job lane pinned at its
|
||||
concurrency cap. Observed in `MetricsRegistry::observeNodeStoreTotals()`,
|
||||
`observeWritePathDetail()`, and `observeAcquireStats()`
|
||||
(`src/xrpld/telemetry/MetricsRegistry.cpp:830-894`).
|
||||
|
||||
| Prometheus Metric | Type | Labels | Description |
|
||||
| --------------------------------------------------- | ----- | -------- | -------------------------------------------------------- |
|
||||
| `nodestore_state{metric="read_mean_us"}` | Gauge | `metric` | Mean time per backend read (microseconds) |
|
||||
| `nodestore_state{metric="write_mean_us"}` | Gauge | `metric` | Mean time per backend write (microseconds) |
|
||||
| `nodestore_state{metric="nudb_writers_in_flight"}` | Gauge | `metric` | Threads inside a NuDB insert at sample time |
|
||||
| `nodestore_state{metric="nudb_writer_depth_x100"}` | Gauge | `metric` | Mean queue depth at the NuDB insert mutex, scaled ×100 |
|
||||
| `nodestore_state{metric="nudb_insert_mean_us"}` | Gauge | `metric` | Mean NuDB insert time incl. queueing (microseconds) |
|
||||
| `nodestore_state{metric="nudb_insert_max_us"}` | Gauge | `metric` | Slowest single NuDB insert observed (microseconds) |
|
||||
| `nodestore_state{metric="acquire_deferrals"}` | Gauge | `metric` | Acquisition timer jobs skipped because the lane was full |
|
||||
| `nodestore_state{metric="acquire_timeouts"}` | Gauge | `metric` | Acquisition timer bodies that ran and advanced retry |
|
||||
| `nodestore_state{metric="acquire_give_ups"}` | Gauge | `metric` | Acquisitions that exhausted their retry budget |
|
||||
| `nodestore_state{metric="acquire_aborts"}` | Gauge | `metric` | Acquisitions destroyed before finishing |
|
||||
| `nodestore_state{metric="acquire_aborts_partial"}` | Gauge | `metric` | Subset of aborts that discarded partly built maps |
|
||||
| `nodestore_state{metric="acquire_completions"}` | Gauge | `metric` | Acquisitions that finished successfully |
|
||||
| `nodestore_state{metric="acquire_sweep_evictions"}` | Gauge | `metric` | Acquisitions evicted by the 1-minute sweep |
|
||||
|
||||
**Three properties to know before querying these.**
|
||||
|
||||
- `nudb_writer_depth_x100` is fixed-point — divide by 100. The depth sits just
|
||||
above 1.0 even under load, because NuDB takes one global mutex per insert
|
||||
(`nudb/impl/basic_store.ipp:288`, a Conan dependency this repo does not patch).
|
||||
An integral gauge would truncate 1.60 to 1 and lose the signal entirely.
|
||||
- The four `nudb_*` values are published **only when the writable backend is
|
||||
NuDB**. `observeWritePathDetail()` returns early when `getWriteStats()` is
|
||||
empty, so a memory or RocksDB backend omits them rather than reporting four
|
||||
zeros. Absent is not zero.
|
||||
- `read_mean_us` and `write_mean_us` are omitted when nothing has been read or
|
||||
written, so a dashboard shows a gap instead of a plausible wrong number. The
|
||||
seven `acquire_*` counters are published unconditionally, because for a counter
|
||||
zero is a meaningful reading.
|
||||
|
||||
**The pairs, not the individual counts, are diagnostic.** Deferrals rising while
|
||||
timeouts stay flat means the give-up path is disarmed: a deferral re-arms the
|
||||
timer without running its body, so the retry counter never advances and the
|
||||
6-timeout give-up is unreachable. Sweep evictions rising while completions stay at
|
||||
zero means partial work is discarded and redone. Neither pattern is visible from
|
||||
one counter. Documented on the class at `src/xrpld/app/ledger/AcquireStats.h`.
|
||||
|
||||
#### NodeStore Read Latency (Histogram — `nodestore_read_us`)
|
||||
|
||||
<!-- cspell:ignore ISTOGRAM -->
|
||||
<!-- The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's
|
||||
compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. -->
|
||||
|
||||
Recorded per fetch at `src/xrpld/app/main/NodeStoreScheduler.cpp` via
|
||||
`XRPL_METRIC_HISTOGRAM_RECORD_LABELED`, not as a `MetricsRegistry` member. The
|
||||
name, label keys, and all four label values are the `constexpr` constants in
|
||||
`include/xrpl/telemetry/NodeStoreMetricNames.h`, shared with the bucket-view
|
||||
registration for the same reason `GetObjectMetricNames.h` exists.
|
||||
|
||||
| Prometheus Metric | Type | Labels | Description |
|
||||
| ------------------- | --------- | ------------------------------------------------------------- | --------------------------------------------- |
|
||||
| `nodestore_read_us` | Histogram | `fetch_type="async"` \| `"sync"`, `found="true"` \| `"false"` | Per-fetch backend read latency (microseconds) |
|
||||
|
||||
**It gets its own bucket ladder, not the shared µs one.** Boundaries are
|
||||
`1, 2, 5, 10, 25, 50, 100, 250, 500, 1000, 5000, 25000` microseconds
|
||||
(`kSubMillisecondBoundaries`, registered by `addSubMillisecondHistogramView()`).
|
||||
The shared `kMicrosecondBoundaries` ladder starts at 100 µs, above the entire
|
||||
range a warm read occupies, so every warm read would fall in bucket 0 and the
|
||||
distribution would read as flat — while still needing to reach far enough to show
|
||||
a cold tail against it. That is a fifth view, alongside the four listed under
|
||||
[GetObject Request Path](#getobject-request-path-synchronous-countershistograms).
|
||||
|
||||
**Why two labels rather than one series.** A slow `async` read delays prefetch; a
|
||||
slow `sync` read blocks a caller outright. A `found=false` fetch can have to
|
||||
consult every backend, so mixing it with hits blurs the distribution that matters.
|
||||
Cardinality is fixed at four combinations. Per project convention, a panel using
|
||||
these needs matching `fetch_type` and `found` template variables.
|
||||
|
||||
Zero is a recordable value — a fetch served from a warm page cache genuinely
|
||||
rounds to 0 µs, and suppressing it would make the fastest reads invisible.
|
||||
Negative elapsed values (clock anomalies) are dropped rather than passed to the
|
||||
SDK, which would otherwise log a warning on every such call.
|
||||
|
||||
#### Cache Hit Rates & Sizes (Observable Gauge — `cache_metrics`)
|
||||
|
||||
| Prometheus Metric | Type | Labels | Description |
|
||||
@@ -1396,8 +1492,31 @@ histogram_quantile(0.95, sum by (le) (rate(getobject_lookup_us_bucket[5m])))
|
||||
|
||||
# GetObject requests refused, by reason
|
||||
sum by (reason) (rate(getobject_rejected_total[5m]))
|
||||
|
||||
# Write-path queueing: depth is fixed-point, divide by 100
|
||||
nodestore_state{metric="nudb_writer_depth_x100"} / 100
|
||||
|
||||
# Read cost, and the found rate that qualifies it (NOT a cache-hit rate)
|
||||
nodestore_state{metric="read_mean_us"}
|
||||
|
||||
# Are ledger acquisitions finishing at all? (per minute)
|
||||
increase(nodestore_state{metric="acquire_completions"}[1m])
|
||||
|
||||
# Livelock fingerprint: deferrals climbing while timeouts stay flat
|
||||
increase(nodestore_state{metric="acquire_deferrals"}[5m])
|
||||
increase(nodestore_state{metric="acquire_timeouts"}[5m])
|
||||
|
||||
# Per-fetch read latency p99, split by the two dimensions that matter
|
||||
histogram_quantile(0.99, sum by (le, fetch_type, found) (rate(nodestore_read_us_bucket[5m])))
|
||||
```
|
||||
|
||||
> **Diagnostic procedure.** These signals exist to answer one question — why a
|
||||
> node is slow to reach `full` — and the decision rule that uses them lives in
|
||||
> [docs/telemetry-runbook.md § Slow to reach `full`](../docs/telemetry-runbook.md#slow-to-reach-full),
|
||||
> with the measured reference values from both bottleneck modes. The short form:
|
||||
> the `ledgerData` lane sitting at its concurrency cap is true in **both** modes,
|
||||
> so it is never a diagnosis on its own.
|
||||
|
||||
### Phase 7+: External Dashboard Parity Metrics
|
||||
|
||||
> **Source**: [External Dashboard Parity Spec](./06-implementation-phases.md#appendix-external-dashboard-parity) — metrics inspired by the community [xrpl-validator-dashboard](https://github.com/realgrapedrop/xrpl-validator-dashboard).
|
||||
|
||||
@@ -1460,6 +1460,438 @@
|
||||
"overrides": []
|
||||
},
|
||||
"id": 29
|
||||
},
|
||||
{
|
||||
"title": "Sync Bottleneck Discrimination",
|
||||
"type": "row",
|
||||
"gridPos": {
|
||||
"h": 1,
|
||||
"w": 24,
|
||||
"x": 0,
|
||||
"y": 124
|
||||
},
|
||||
"collapsed": false,
|
||||
"panels": [],
|
||||
"id": 30
|
||||
},
|
||||
{
|
||||
"title": "NodeStore Read Latency (Bottleneck Discriminator)",
|
||||
"description": "###### What this is:\n*The single measurement that separates the two ways a ledger sync stalls. Both modes look identical from the job queue -- the ledgerData lane sits at its concurrency limit of 3 with work waiting -- so lane occupancy on its own diagnoses nothing. Read latency does separate them, because the two modes load opposite ends of the storage path.*\n\n###### How it's computed:\n*Two views of the same quantity. Lifetime is the nodestore_state{metric=\"read_mean_us\"} gauge, which is total fetch microseconds divided by total fetches since process start, so it moves slowly and shows the run as a whole. Windowed is rate(node_reads_duration_us) / rate(node_reads_total) over the panel interval, so it reacts within one scrape. The axis is logarithmic because the two modes differ by more than an order of magnitude and a linear axis flattens the lower one.*\n\n###### Reading it:\n*Below about 10 microseconds per read means the backend is answering from the page cache and reads are not the constraint; if the lane is still full, the cost is on the write side -- check NuDB Writer Queue Depth next. Above about 100 microseconds per read, together with a high hit ratio on NuDB Cache Hit Ratio, means objects are being found but paid for with disk latency on every access. High latency with a low hit ratio is a different thing again: the working set does not fit and misses are scanning every backend. The threshold lines at 10 and 100 mark the two boundaries.*\n\n###### Healthy range:\n*Single-digit microseconds per read on a warm synced node, with lifetime and windowed close together.*\n\n###### Watch for:\n*Windowed rising well above lifetime: the recent window is much worse than the run average, which is the earliest reading of a cache that has just gone cold. A measured cold-read episode peaked at 223 microseconds and settled in the 13-35 range while still hitting 88 percent or better, and that shape hung a node for roughly 25 minutes. Also treat a flat 8-9 microsecond line during a stall as informative rather than reassuring -- it rules reads out and points at the write path.*\n\n###### Source:\n[nodestore/backend/NuDBFactory.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/nodestore/backend/NuDBFactory.cpp)\n\n###### Function:\n`Database::getFetchDurationUs / NuDB backend read path`",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
"w": 12,
|
||||
"x": 0,
|
||||
"y": 125
|
||||
},
|
||||
"options": {
|
||||
"tooltip": {
|
||||
"maxHeight": 600,
|
||||
"mode": "multi",
|
||||
"sort": "desc"
|
||||
}
|
||||
},
|
||||
"targets": [
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"read_mean_us\"}, \"series\", \"Read Mean (Lifetime)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"node_reads_duration_us\"}[$__rate_interval])) / clamp_min(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"node_reads_total\"}[$__rate_interval])), 1), \"series\", \"Read Mean (Windowed)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
}
|
||||
],
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}",
|
||||
"unit": "\u00b5s",
|
||||
"thresholds": {
|
||||
"steps": [
|
||||
{
|
||||
"color": "green",
|
||||
"value": null
|
||||
},
|
||||
{
|
||||
"color": "yellow",
|
||||
"value": 10
|
||||
},
|
||||
{
|
||||
"color": "red",
|
||||
"value": 100
|
||||
}
|
||||
]
|
||||
},
|
||||
"custom": {
|
||||
"axisLabel": "Read Latency (\u00b5s/read)",
|
||||
"scaleDistribution": {
|
||||
"type": "log",
|
||||
"log": 10
|
||||
},
|
||||
"thresholdsStyle": {
|
||||
"mode": "line"
|
||||
},
|
||||
"spanNulls": 1800000,
|
||||
"insertNulls": false,
|
||||
"showPoints": "auto",
|
||||
"pointSize": 3
|
||||
}
|
||||
},
|
||||
"overrides": []
|
||||
},
|
||||
"id": 31
|
||||
},
|
||||
{
|
||||
"title": "NuDB Writer Queue Depth",
|
||||
"description": "###### What this is:\n*How many writers are queued at NuDB's insert mutex. NuDB takes one global lock per insert, so concurrent writers do not overlap -- they line up. This panel is the confirming half of the read-latency discriminator: when reads are fast and the lane is still full, the queueing is here.*\n\n###### How it's computed:\n*Mean Depth is nodestore_state{metric=\"nudb_writer_depth_x100\"} divided by 100. The exported gauge is integral, so the mean is scaled by 100 at the source to keep the fractional part; dividing it back is what makes 1.60 readable instead of 1. In Flight is the instantaneous nudb_writers_in_flight sample.*\n\n###### Reading it:\n*Depth is a queue length, so 1.0 is the floor and means every insert found the lock free. Anything meaningfully above 1.0 means inserts are waiting on each other and the write path, not the disk, is setting the pace. In Flight is a point sample from the scrape instant and will look spikier than the mean; read the mean for the trend and In Flight for the peak.*\n\n###### Healthy range:\n*Mean depth at or just above 1.0, In Flight low.*\n\n###### Watch for:\n*Mean depth above 1 while read latency stays in single-digit microseconds -- that pair is the write-lock ceiling, and no amount of read tuning will move it. A measured run of this mode held depth at 1.60 with reads flat at 8-9 microseconds and reached its ceiling in 510 seconds while completing nothing. Depth at 1.0 with slow reads is the opposite mode; look at the read panel.*\n\n###### Source:\n[telemetry/MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`MetricsRegistry::observeWritePathDetail`",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
"w": 12,
|
||||
"x": 12,
|
||||
"y": 125
|
||||
},
|
||||
"options": {
|
||||
"tooltip": {
|
||||
"maxHeight": 600,
|
||||
"mode": "multi",
|
||||
"sort": "desc"
|
||||
}
|
||||
},
|
||||
"targets": [
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"nudb_writer_depth_x100\"} / 100, \"series\", \"Writer Mean Depth\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"nudb_writers_in_flight\"}, \"series\", \"Writers In Flight\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
}
|
||||
],
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}",
|
||||
"unit": "short",
|
||||
"custom": {
|
||||
"axisLabel": "Writers Queued At Insert Mutex",
|
||||
"spanNulls": 1800000,
|
||||
"insertNulls": false,
|
||||
"showPoints": "auto",
|
||||
"pointSize": 3
|
||||
}
|
||||
},
|
||||
"overrides": []
|
||||
},
|
||||
"id": 32
|
||||
},
|
||||
{
|
||||
"title": "NuDB Insert Time (Mean & Max)",
|
||||
"description": "###### What this is:\n*Time spent inside a NuDB insert, mean and worst case, alongside the backend's overall mean write latency. Splits an insert's cost into the part that is real work and the part that is waiting for the global insert mutex.*\n\n###### How it's computed:\n*Insert Mean is nodestore_state{metric=\"nudb_insert_mean_us\"}, total insert microseconds over insert count. Insert Max is nudb_insert_max_us, a true running maximum rather than a quantile, so one bad insert is visible and never averaged away. Write Mean is the write_mean_us gauge for the whole backend write path.*\n\n###### Reading it:\n*Compare Insert Mean against the service time implied by Writer Queue Depth. Mean insert time above the unqueued service time is wait, and the gap is the fraction of every write spent queued rather than working. Insert Max far above Insert Mean means the distribution has a tail -- typically a bucket split or a commit -- which a mean alone hides.*\n\n###### Healthy range:\n*Insert Mean in the low tens of microseconds with Insert Max within roughly an order of magnitude of it.*\n\n###### Watch for:\n*A widening gap between Insert Mean and the service floor. In a measured write-lock-bound run the mean was 20 microseconds of which only 12.5 was service, leaving 7.5 -- 37 percent of every insert -- as pure queueing. That is the cost the writer-depth panel predicts, quantified. Insert Max climbing on its own without the mean moving is a tail problem, not a saturation problem.*\n\n###### Source:\n[telemetry/MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`MetricsRegistry::observeWritePathDetail`",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
"w": 12,
|
||||
"x": 0,
|
||||
"y": 133
|
||||
},
|
||||
"options": {
|
||||
"tooltip": {
|
||||
"maxHeight": 600,
|
||||
"mode": "multi",
|
||||
"sort": "desc"
|
||||
}
|
||||
},
|
||||
"targets": [
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"nudb_insert_mean_us\"}, \"series\", \"Insert Mean\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"nudb_insert_max_us\"}, \"series\", \"Insert Max\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"write_mean_us\"}, \"series\", \"Write Mean (Lifetime)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
}
|
||||
],
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}",
|
||||
"unit": "\u00b5s",
|
||||
"custom": {
|
||||
"axisLabel": "Insert Time (\u00b5s)",
|
||||
"scaleDistribution": {
|
||||
"type": "log",
|
||||
"log": 10
|
||||
},
|
||||
"spanNulls": 1800000,
|
||||
"insertNulls": false,
|
||||
"showPoints": "auto",
|
||||
"pointSize": 3
|
||||
}
|
||||
},
|
||||
"overrides": []
|
||||
},
|
||||
"id": 33
|
||||
},
|
||||
{
|
||||
"title": "Acquire Deferrals vs Timeouts (Livelock Fingerprint)",
|
||||
"description": "###### What this is:\n*The two counters that together identify an acquisition livelock. Deferrals count timer jobs that were skipped because the ledgerData lane was already at its limit. Timeouts count timer bodies that actually ran and advanced an acquisition's retry counter. Both series are on one panel deliberately: the signal is the divergence between them, and neither counter shows it alone.*\n\n###### How it's computed:\n*rate() over nodestore_state{metric=\"acquire_deferrals\"} and nodestore_state{metric=\"acquire_timeouts\"}. Both are cumulative counters, so the rate is the per-second event frequency and a restart shows as a gap rather than as a negative spike.*\n\n###### Reading it:\n*Deferrals rising while timeouts stay flat is the livelock fingerprint. Retry counts only advance when a timer body runs, so if every timer is being deferred instead, the retry budget never advances and the give-up path is effectively disarmed -- the acquisition can neither finish nor fail, and it holds its slot indefinitely. The two rates moving together is the benign case: the lane is busy but timers are still landing and acquisitions are still progressing toward either success or abandonment.*\n\n###### Healthy range:\n*Both near zero when synced. During catch-up, deferrals non-zero is expected, but timeouts should track rather than flatten.*\n\n###### Watch for:\n*A deferral rate that climbs while the timeout rate stays pinned. One measured stall recorded 5441 deferrals against 687 timeouts -- an eight-to-one ratio -- with zero completions over the same window. Cross-check Acquisition Progress: a flat completion rate confirms the acquisitions are stuck rather than merely slow.*\n\n###### Source:\n[app/ledger/InboundLedgers.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/InboundLedgers.cpp)\n\n###### Function:\n`InboundLedgers acquire retry timer / AcquireStats`",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
"w": 12,
|
||||
"x": 12,
|
||||
"y": 133
|
||||
},
|
||||
"options": {
|
||||
"tooltip": {
|
||||
"maxHeight": 600,
|
||||
"mode": "multi",
|
||||
"sort": "desc"
|
||||
}
|
||||
},
|
||||
"targets": [
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"acquire_deferrals\"}[$__rate_interval]), \"series\", \"Deferrals/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"acquire_timeouts\"}[$__rate_interval]), \"series\", \"Timeouts/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
}
|
||||
],
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}",
|
||||
"unit": "ops",
|
||||
"custom": {
|
||||
"axisLabel": "Events (Per Second)",
|
||||
"spanNulls": 1800000,
|
||||
"insertNulls": false,
|
||||
"showPoints": "auto",
|
||||
"pointSize": 3
|
||||
}
|
||||
},
|
||||
"overrides": []
|
||||
},
|
||||
"id": 34
|
||||
},
|
||||
{
|
||||
"title": "Acquisition Progress (Completions, Give-Ups & Aborts)",
|
||||
"description": "###### What this is:\n*Whether ledger acquisitions are reaching an ending at all. Completions are acquisitions that finished with the data. Give-Ups are acquisitions that exhausted their retry budget. Aborts are acquisitions destroyed before either outcome. Together they are every way an acquisition can leave the system, so the sum going to zero while work is queued means nothing is leaving.*\n\n###### How it's computed:\n*rate() over the cumulative nodestore_state{metric=\"acquire_completions\"}, acquire_give_ups and acquire_aborts counters.*\n\n###### Reading it:\n*This panel is the outcome side of the deferral panel. A healthy catch-up shows a steady completion rate; a healthy failure shows give-ups. What should never happen is all three flat while the ledgerData lane is full, because that means acquisitions are occupying slots without ever resolving. Read this together with Deferrals vs Timeouts: deferrals climbing with completions at zero narrows the stall down to the retry path.*\n\n###### Healthy range:\n*Completion rate positive whenever ledgers are being acquired. Give-ups and aborts low.*\n\n###### Watch for:\n*Zero completions sustained while the lane is busy. A measured write-bound run recorded zero completions across 510 seconds; the comparable read-bound run still managed 8, which is the difference between slow and stuck. A rising give-up rate is less alarming than a flat one -- it at least means the retry budget is being consumed and slots are being returned.*\n\n###### Source:\n[app/ledger/InboundLedgers.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/InboundLedgers.cpp)\n\n###### Function:\n`InboundLedger completion / AcquireStats`",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
"w": 12,
|
||||
"x": 0,
|
||||
"y": 141
|
||||
},
|
||||
"options": {
|
||||
"tooltip": {
|
||||
"maxHeight": 600,
|
||||
"mode": "multi",
|
||||
"sort": "desc"
|
||||
}
|
||||
},
|
||||
"targets": [
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"acquire_completions\"}[$__rate_interval]), \"series\", \"Completions/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"acquire_give_ups\"}[$__rate_interval]), \"series\", \"Give-Ups/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"acquire_aborts\"}[$__rate_interval]), \"series\", \"Aborts/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
}
|
||||
],
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}",
|
||||
"unit": "ops",
|
||||
"custom": {
|
||||
"axisLabel": "Outcomes (Per Second)",
|
||||
"spanNulls": 1800000,
|
||||
"insertNulls": false,
|
||||
"showPoints": "auto",
|
||||
"pointSize": 3
|
||||
}
|
||||
},
|
||||
"overrides": []
|
||||
},
|
||||
"id": 35
|
||||
},
|
||||
{
|
||||
"title": "Discarded Acquire Work (Sweeps & Partial Aborts)",
|
||||
"description": "###### What this is:\n*Work that was fetched and then thrown away. Sweep Evictions are acquisitions removed by the one-minute idle sweep. Partial Aborts are the subset of aborted acquisitions that had already built part of a map when they were destroyed, so the bytes fetched for them were wasted.*\n\n###### How it's computed:\n*rate() over the cumulative nodestore_state{metric=\"acquire_sweep_evictions\"} and acquire_aborts_partial counters.*\n\n###### Reading it:\n*Sweep evictions are the sweeper reclaiming acquisitions that stopped making progress, so a sustained non-zero rate means acquisitions are going idle rather than finishing -- it is the sweeper cleaning up after the stall on the adjacent panels, not a cause of its own. Partial aborts quantify the waste: each one is fetch bandwidth and nodestore writes spent on a map that was discarded, which then has to be fetched again.*\n\n###### Healthy range:\n*Both at or near zero.*\n\n###### Watch for:\n*A sweep-eviction rate that persists after the sync should have settled -- acquisitions are being started and abandoned in a loop, and each cycle re-pays the fetch cost. Two measured runs of the same duration differed sharply here, 127 sweeps in the write-bound case against 38 in the read-bound one, so a high sweep count is itself weak evidence for the write-bound mode. Confirm with read latency and writer depth before acting on it.*\n\n###### Source:\n[app/ledger/InboundLedgers.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/InboundLedgers.cpp)\n\n###### Function:\n`InboundLedgers::sweep / AcquireStats`",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
"w": 12,
|
||||
"x": 12,
|
||||
"y": 141
|
||||
},
|
||||
"options": {
|
||||
"tooltip": {
|
||||
"maxHeight": 600,
|
||||
"mode": "multi",
|
||||
"sort": "desc"
|
||||
}
|
||||
},
|
||||
"targets": [
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"acquire_sweep_evictions\"}[$__rate_interval]), \"series\", \"Sweep Evictions/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(rate(nodestore_state{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\", metric=\"acquire_aborts_partial\"}[$__rate_interval]), \"series\", \"Partial Aborts/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
}
|
||||
],
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}",
|
||||
"unit": "ops",
|
||||
"custom": {
|
||||
"axisLabel": "Discarded Acquisitions (Per Second)",
|
||||
"spanNulls": 1800000,
|
||||
"insertNulls": false,
|
||||
"showPoints": "auto",
|
||||
"pointSize": 3
|
||||
}
|
||||
},
|
||||
"overrides": []
|
||||
},
|
||||
"id": 36
|
||||
},
|
||||
{
|
||||
"title": "NodeStore Read Latency Distribution By Fetch Type & Found",
|
||||
"description": "###### What this is:\n*Per-fetch nodestore read latency as a distribution rather than a mean, split by whether the fetch was a read-ahead or a blocking one and by whether the object was found. A mean cannot tell \"every read took 9 microseconds\" apart from \"most took 2 and a few took 900\", and the second is the cold-store shape. The split matters because a slow async fetch only delays prefetch while a slow sync fetch blocks a caller outright, and because a miss can cost a read of every backend.*\n\n###### How it's computed:\n*p50, p95 and p99 from histogram_quantile over rate(nodestore_read_us_bucket[$__rate_interval]), grouped by fetch_type and found. The instrument carries explicit sub-millisecond bucket boundaries starting at 1 microsecond, because the default ladder's lowest edge sits above the entire warm-read range and would make every warm read land in bucket zero.*\n\n###### Reading it:\n*Use the Fetch Type and Found template filters at the top of the dashboard to isolate a dimension. sync + found is the series that maps most directly to caller-visible stall time. A p99 that pulls away from p50 while p50 stays low is the cold-read signature the mean-based panels can only hint at: most reads are cached and a minority are paying full disk latency. found=false rising in absolute terms points at working-set misses rather than at cold cache.*\n\n###### Healthy range:\n*p99 within a small multiple of p50, both in the single-digit-to-low-tens of microseconds warm.*\n\n###### Watch for:\n*p99 above roughly 100 microseconds on the sync + found series while the hit ratio stays high -- objects are present but every access reaches disk. Note this instrument is separate from the read_mean_us gauge on the first panel of this row; if the histogram is empty but the gauge is populated, the exporter on that build predates the histogram and only the mean-based panels apply.*\n\n###### Source:\n[app/main/NodeStoreScheduler.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/main/NodeStoreScheduler.cpp)\n\n###### Function:\n`NodeStoreScheduler::onFetch`",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
"w": 24,
|
||||
"x": 0,
|
||||
"y": 149
|
||||
},
|
||||
"options": {
|
||||
"tooltip": {
|
||||
"maxHeight": 600,
|
||||
"mode": "multi",
|
||||
"sort": "desc"
|
||||
},
|
||||
"legend": {
|
||||
"displayMode": "table",
|
||||
"placement": "right",
|
||||
"calcs": ["mean", "max"]
|
||||
}
|
||||
},
|
||||
"targets": [
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(label_join(histogram_quantile(0.5, sum by (le, fetch_type, found, service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_read_us_bucket{fetch_type=~\"$fetch_type\", found=~\"$found\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"read_dims\", \"-\", \"fetch_type\", \"found\"), \"series\", \"Read p50 [$1]\", \"read_dims\", \"(.*)\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(label_join(histogram_quantile(0.95, sum by (le, fetch_type, found, service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_read_us_bucket{fetch_type=~\"$fetch_type\", found=~\"$found\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"read_dims\", \"-\", \"fetch_type\", \"found\"), \"series\", \"Read p95 [$1]\", \"read_dims\", \"(.*)\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
},
|
||||
{
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(label_join(histogram_quantile(0.99, sum by (le, fetch_type, found, service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_read_us_bucket{fetch_type=~\"$fetch_type\", found=~\"$found\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"read_dims\", \"-\", \"fetch_type\", \"found\"), \"series\", \"Read p99 [$1]\", \"read_dims\", \"(.*)\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")"
|
||||
}
|
||||
],
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}",
|
||||
"unit": "\u00b5s",
|
||||
"thresholds": {
|
||||
"steps": [
|
||||
{
|
||||
"color": "green",
|
||||
"value": null
|
||||
},
|
||||
{
|
||||
"color": "yellow",
|
||||
"value": 10
|
||||
},
|
||||
{
|
||||
"color": "red",
|
||||
"value": 100
|
||||
}
|
||||
]
|
||||
},
|
||||
"custom": {
|
||||
"axisLabel": "Read Latency (\u00b5s)",
|
||||
"scaleDistribution": {
|
||||
"type": "log",
|
||||
"log": 10
|
||||
},
|
||||
"thresholdsStyle": {
|
||||
"mode": "line"
|
||||
},
|
||||
"spanNulls": 1800000,
|
||||
"insertNulls": false,
|
||||
"showPoints": "auto",
|
||||
"pointSize": 3
|
||||
}
|
||||
},
|
||||
"overrides": []
|
||||
},
|
||||
"id": 37
|
||||
}
|
||||
],
|
||||
"schemaVersion": 39,
|
||||
@@ -1625,6 +2057,46 @@
|
||||
"multi": true,
|
||||
"refresh": 2,
|
||||
"sort": 1
|
||||
},
|
||||
{
|
||||
"name": "fetch_type",
|
||||
"label": "Fetch Type",
|
||||
"description": "Filter nodestore read latency by fetch kind (async read-ahead / sync blocking)",
|
||||
"type": "query",
|
||||
"query": "label_values(nodestore_read_us_bucket, fetch_type)",
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "prometheus"
|
||||
},
|
||||
"includeAll": true,
|
||||
"allValue": ".*",
|
||||
"current": {
|
||||
"text": "All",
|
||||
"value": "$__all"
|
||||
},
|
||||
"multi": true,
|
||||
"refresh": 2,
|
||||
"sort": 1
|
||||
},
|
||||
{
|
||||
"name": "found",
|
||||
"label": "Found",
|
||||
"description": "Filter nodestore read latency by whether the fetch found the object",
|
||||
"type": "query",
|
||||
"query": "label_values(nodestore_read_us_bucket, found)",
|
||||
"datasource": {
|
||||
"type": "prometheus",
|
||||
"uid": "prometheus"
|
||||
},
|
||||
"includeAll": true,
|
||||
"allValue": ".*",
|
||||
"current": {
|
||||
"text": "All",
|
||||
"value": "$__all"
|
||||
},
|
||||
"multi": true,
|
||||
"refresh": 2,
|
||||
"sort": 1
|
||||
}
|
||||
]
|
||||
},
|
||||
|
||||
@@ -1528,11 +1528,57 @@ These gauges are exported via the OTel Metrics SDK `PeriodicMetricReader` (10s i
|
||||
| `db_metrics{metric="historical_perminute"}` | MetricsRegistry.cpp | Historical ledger fetches per minute |
|
||||
| `cache_metrics{metric="AL_size"}` | MetricsRegistry.cpp | AcceptedLedger cache size |
|
||||
| `nodestore_state{metric="node_reads_duration_us"}` | MetricsRegistry.cpp | Cumulative read time (microseconds) |
|
||||
| `nodestore_state{metric="node_writes_duration_us"}` | MetricsRegistry.cpp | Cumulative write time (microseconds) |
|
||||
| `nodestore_state{metric="read_request_bundle"}` | MetricsRegistry.cpp | Read request bundle count |
|
||||
| `nodestore_state{metric="read_threads_running"}` | MetricsRegistry.cpp | Active read threads |
|
||||
| `nodestore_state{metric="read_threads_total"}` | MetricsRegistry.cpp | Total read threads configured |
|
||||
| `rpc_in_flight_requests` | PerfLogImp.cpp | RPC requests currently executing (UpDownCounter) |
|
||||
|
||||
#### Sync Diagnosis Signals
|
||||
|
||||
More label values on the same `nodestore_state` gauge. They exist to separate the
|
||||
two different reasons a node is slow to reach `full` — see
|
||||
[Slow to reach `full`](#slow-to-reach-full). The `nudb_*` group is published only
|
||||
when the writable backend is NuDB; a memory or RocksDB backend omits those four
|
||||
label values rather than reporting them as zero.
|
||||
|
||||
| Prometheus Metric | Source | Description |
|
||||
| --------------------------------------------------- | ------------------- | -------------------------------------------------------- |
|
||||
| `nodestore_state{metric="read_mean_us"}` | MetricsRegistry.cpp | Mean time per backend read (microseconds) |
|
||||
| `nodestore_state{metric="write_mean_us"}` | MetricsRegistry.cpp | Mean time per backend write (microseconds) |
|
||||
| `nodestore_state{metric="nudb_writers_in_flight"}` | MetricsRegistry.cpp | Threads inside a NuDB insert right now |
|
||||
| `nodestore_state{metric="nudb_writer_depth_x100"}` | MetricsRegistry.cpp | Mean queue depth at the NuDB insert mutex, ×100 |
|
||||
| `nodestore_state{metric="nudb_insert_mean_us"}` | MetricsRegistry.cpp | Mean NuDB insert time, queueing included (microseconds) |
|
||||
| `nodestore_state{metric="nudb_insert_max_us"}` | MetricsRegistry.cpp | Slowest single NuDB insert seen (microseconds) |
|
||||
| `nodestore_state{metric="acquire_deferrals"}` | MetricsRegistry.cpp | Acquisition timer jobs skipped because the lane was full |
|
||||
| `nodestore_state{metric="acquire_timeouts"}` | MetricsRegistry.cpp | Acquisition timer bodies that ran and advanced retry |
|
||||
| `nodestore_state{metric="acquire_give_ups"}` | MetricsRegistry.cpp | Acquisitions that exhausted their retry budget |
|
||||
| `nodestore_state{metric="acquire_aborts"}` | MetricsRegistry.cpp | Acquisitions destroyed before finishing |
|
||||
| `nodestore_state{metric="acquire_aborts_partial"}` | MetricsRegistry.cpp | Subset of aborts that discarded partly built maps |
|
||||
| `nodestore_state{metric="acquire_completions"}` | MetricsRegistry.cpp | Acquisitions that finished successfully |
|
||||
| `nodestore_state{metric="acquire_sweep_evictions"}` | MetricsRegistry.cpp | Acquisitions evicted by the 1-minute sweep |
|
||||
|
||||
`nudb_writer_depth_x100` is fixed-point: divide by 100 to read it. The depth sits
|
||||
just above 1.0 even under load, so an integer gauge would truncate the whole
|
||||
signal away.
|
||||
|
||||
#### NodeStore Read Latency Histogram
|
||||
|
||||
| Prometheus Metric | Kind | Labels | Description |
|
||||
| ------------------- | --------- | ------------------------------------------------------------- | ----------------------------------- |
|
||||
| `nodestore_read_us` | Histogram | `fetch_type` = `async` \| `sync`, `found` = `true` \| `false` | Per-fetch backend read latency (µs) |
|
||||
|
||||
Bucket edges are 1, 2, 5, 10, 25, 50, 100, 250, 500, 1000, 5000, 25000
|
||||
microseconds — a dedicated sub-millisecond ladder, not the shared µs ladder the
|
||||
job histograms use. The shared ladder starts at 100 µs, which is above the entire
|
||||
range a warm read occupies, so every warm read would land in one bucket and the
|
||||
distribution would read flat.
|
||||
|
||||
The two labels separate cases with different consequences. An `async` read that is
|
||||
slow only delays prefetch; a `sync` read that is slow blocks a caller outright.
|
||||
A `found=false` fetch can have to consult every backend, so mixing it with hits
|
||||
blurs the distribution that matters.
|
||||
|
||||
#### Counters
|
||||
|
||||
| Prometheus Metric | Source | Description |
|
||||
@@ -2248,7 +2294,7 @@ flowchart LR
|
||||
answer.
|
||||
|
||||
> **Scope every query to one node.** All snippets below carry
|
||||
> `service_instance_id="$node"`. On a shared Grafana stack an unscoped selector
|
||||
> `service_instance_id=~"$node"`. On a shared Grafana stack an unscoped selector
|
||||
> aggregates across every node and branch reporting to it, so another node's
|
||||
> saturation would be attributed to this one. Substitute the node's public key
|
||||
> for `$node` when querying Prometheus directly rather than from a dashboard.
|
||||
@@ -2256,27 +2302,27 @@ answer.
|
||||
1. Split queue wait from run time. Compare the two p99s for the handler:
|
||||
|
||||
```promql
|
||||
histogram_quantile(0.99, sum by (le) (rate(job_queued_us_bucket{handler="RcvGetObjByHash", service_instance_id="$node"}[5m])))
|
||||
histogram_quantile(0.99, sum by (le) (rate(job_running_us_bucket{handler="RcvGetObjByHash", service_instance_id="$node"}[5m])))
|
||||
histogram_quantile(0.99, sum by (le) (rate(job_queued_us_bucket{handler="RcvGetObjByHash", service_instance_id=~"$node"}[5m])))
|
||||
histogram_quantile(0.99, sum by (le) (rate(job_running_us_bucket{handler="RcvGetObjByHash", service_instance_id=~"$node"}[5m])))
|
||||
```
|
||||
|
||||
2. If run time is the larger term, split it against the fetch loop:
|
||||
|
||||
```promql
|
||||
histogram_quantile(0.99, sum by (le) (rate(getobject_lookup_us_bucket{service_instance_id="$node"}[5m])))
|
||||
histogram_quantile(0.99, sum by (le) (rate(getobject_lookup_us_bucket{service_instance_id=~"$node"}[5m])))
|
||||
```
|
||||
|
||||
3. Match the outcome below.
|
||||
|
||||
| Observation | Root cause and next step |
|
||||
| -------------------------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| `job_queued_us{handler="RcvGetObjByHash"}` high, `job_running_us` normal | **Queue contention** — the work is cheap, the wait is not. Confirm with `jobq_ledgerrequest_deferred{service_instance_id="$node"} > 0`, then compare `job_queued_us{handler="RcvGetLedger"}`: if it is also high, both producers are starved by the limit of 3, not by each other. |
|
||||
| `job_running_us` high and within ~10% of `getobject_lookup_us` | **NodeStore is the bottleneck** — nearly all run time is in the fetch loop. Check `rate(getobject_lookups_total{result="miss"}[5m])` and the existing NuDB / `nodestore_state` panels. A miss-heavy mix means real disk seeks. |
|
||||
| `job_running_us` high but `getobject_lookup_us` low | **Cost is outside the fetch loop** — protobuf, serialization, or reply construction. Storage is fine. Look at reply size: a large `getobject_request_objects` with a high hit rate means big replies to build and send. |
|
||||
| `getobject_request_objects` p99 large | **Peers are sending big batches** — the work is real, not a regression. Nothing is broken; the node is being asked to do more. Decide whether to accept the load or price it higher. |
|
||||
| `rate(getobject_rejected_total{reason="oversize"}[5m])` rising | **Non-conforming traffic** — requests above `kHardMaxReplyNodes` are being refused before any NodeStore access. Check `getobject_charge` to confirm the pricing escalates for the requests that _are_ accepted. |
|
||||
| `rate(getobject_rejected_total{reason="malformed_ledgerhash"}[5m])` rising | **Malformed requests** — a peer is sending a ledgerhash that is not 32 bytes. Refused at the gate; no queue or storage cost incurred. |
|
||||
| All GetObject metrics normal, `jobq_*_deferred` high on another type | **This path is exonerated** — the slowness is elsewhere. Find the saturated type with `topk(5, {__name__=~"jobq_.*_deferred", service_instance_id="$node"} > 0)` and investigate that producer instead. |
|
||||
| Observation | Root cause and next step |
|
||||
| -------------------------------------------------------------------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| `job_queued_us{handler="RcvGetObjByHash"}` high, `job_running_us` normal | **Queue contention** — the work is cheap, the wait is not. Confirm with `jobq_ledgerrequest_deferred{service_instance_id=~"$node"} > 0`, then compare `job_queued_us{handler="RcvGetLedger"}`: if it is also high, both producers are starved by the limit of 3, not by each other. |
|
||||
| `job_running_us` high and within ~10% of `getobject_lookup_us` | **NodeStore is the bottleneck** — nearly all run time is in the fetch loop. Check `rate(getobject_lookups_total{result="miss"}[5m])` and the existing NuDB / `nodestore_state` panels. A miss-heavy mix means real disk seeks. |
|
||||
| `job_running_us` high but `getobject_lookup_us` low | **Cost is outside the fetch loop** — protobuf, serialization, or reply construction. Storage is fine. Look at reply size: a large `getobject_request_objects` with a high hit rate means big replies to build and send. |
|
||||
| `getobject_request_objects` p99 large | **Peers are sending big batches** — the work is real, not a regression. Nothing is broken; the node is being asked to do more. Decide whether to accept the load or price it higher. |
|
||||
| `rate(getobject_rejected_total{reason="oversize"}[5m])` rising | **Non-conforming traffic** — requests above `kHardMaxReplyNodes` are being refused before any NodeStore access. Check `getobject_charge` to confirm the pricing escalates for the requests that _are_ accepted. |
|
||||
| `rate(getobject_rejected_total{reason="malformed_ledgerhash"}[5m])` rising | **Malformed requests** — a peer is sending a ledgerhash that is not 32 bytes. Refused at the gate; no queue or storage cost incurred. |
|
||||
| All GetObject metrics normal, `jobq_*_deferred` high on another type | **This path is exonerated** — the slowness is elsewhere. Find the saturated type with `topk(5, {__name__=~"jobq_.*_deferred", service_instance_id=~"$node"} > 0)` and investigate that producer instead. |
|
||||
|
||||
Row 2 says "within ~10%", not "equal", deliberately: `job_running_us` also
|
||||
covers the charge computation (PeerImp.cpp:2757) and the reply `send()` that
|
||||
@@ -2306,6 +2352,206 @@ which a slowness-only metric cannot.
|
||||
a rejection spike will _not_ show up as latency. Check the rejection counters
|
||||
before concluding that traffic is normal.
|
||||
|
||||
### Slow to reach `full`
|
||||
|
||||
Use this when a node takes far longer than expected to sync. Two completely
|
||||
different bottlenecks look identical from outside: in both, the `ledgerData` job
|
||||
lane sits pinned at its concurrency cap of 3 with jobs waiting behind it.
|
||||
|
||||
**Lane occupancy on its own distinguishes nothing.** It is true in both cases, so
|
||||
it is never a diagnosis. Two tuning experiments were spent before that was known —
|
||||
do not repeat them. Read the storage-side signals below instead.
|
||||
|
||||
The two modes and the signal that separates them:
|
||||
|
||||
```mermaid
|
||||
flowchart TB
|
||||
L["`**ledgerData lane at cap 3**
|
||||
jobs waiting behind it
|
||||
TRUE IN BOTH MODES
|
||||
diagnoses nothing`"]
|
||||
|
||||
L --> W["`**Mode W — write-bound**
|
||||
fresh or empty store`"]
|
||||
L --> R["`**Mode R — cold-read-bound**
|
||||
populated store, cold pages`"]
|
||||
|
||||
W --> W1["`reads cheap and always miss
|
||||
data comes from peers`"]
|
||||
W1 --> W2["`cost is on the WRITE side
|
||||
one global mutex per insert
|
||||
so inserts queue`"]
|
||||
W2 --> W3["`**Look at:** writer depth
|
||||
above 1, insert mean well
|
||||
above service time`"]
|
||||
|
||||
R --> R1["`no write contention
|
||||
writer depth 1.00`"]
|
||||
R1 --> R2["`reads pay disk latency
|
||||
on every fetch —
|
||||
found but cold`"]
|
||||
R2 --> R3["`**Look at:** read mean and
|
||||
peak high while the
|
||||
found rate is near 100%`"]
|
||||
|
||||
style L fill:#7b3f00,color:#ffffff
|
||||
style W fill:#1f4e79,color:#ffffff
|
||||
style R fill:#4a148c,color:#ffffff
|
||||
style W1 fill:#37474f,color:#ffffff
|
||||
style W2 fill:#37474f,color:#ffffff
|
||||
style W3 fill:#2d5016,color:#ffffff
|
||||
style R1 fill:#37474f,color:#ffffff
|
||||
style R2 fill:#37474f,color:#ffffff
|
||||
style R3 fill:#2d5016,color:#ffffff
|
||||
```
|
||||
|
||||
#### `node_reads_hit` is a found count, not a cache-hit rate
|
||||
|
||||
This is the most misleading signal on the board, so read it first.
|
||||
`fetchHitCount_` is incremented whenever the fetch **returned an object**
|
||||
(`src/libxrpl/nodestore/Database.cpp:246-255`) — not when a cache served it. So
|
||||
`node_reads_hit / node_reads_total` is the fraction of fetches that **found**
|
||||
something, and it can read ~100% while every one of those fetches went to disk.
|
||||
|
||||
A ~100% "hit rate" at 113 µs per read is therefore not a contradiction. It is the
|
||||
cold-read signature: the data is on disk, found every time, and paid for every
|
||||
time. A real devnet incident hung a client-handler node for 25 minutes in exactly
|
||||
this state — 112.7 µs per read against 4.95 µs on a healthy peer, both reporting
|
||||
~99.98%.
|
||||
|
||||
A node configured with `online_delete` runs `DatabaseRotatingImp`, which has **no
|
||||
NodeObject cache** at all (0 `cache_` references in
|
||||
`src/libxrpl/nodestore/DatabaseRotatingImp.cpp` versus 11 in
|
||||
`DatabaseNodeImp.cpp`), so every fetch reaches the backend. That is why the
|
||||
cold-read mode shows up on exactly those nodes.
|
||||
|
||||
#### The decision rule
|
||||
|
||||
**Procedure** — all of it assumes the `ledgerData` lane is already at its cap; if
|
||||
it is not, this procedure does not apply.
|
||||
|
||||
1. Ask whether acquisitions are completing at all: read `acquire_completions` as a
|
||||
rate over the window. That single answer picks which half of the table below
|
||||
you are in.
|
||||
2. Within that half, read the storage signal named in the row. The first row that
|
||||
matches is the answer.
|
||||
3. Confirm it against the measured reference points in the next section before
|
||||
acting.
|
||||
|
||||
| Completions per minute | Storage signal | Root cause and next step |
|
||||
| ---------------------- | ------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| Zero | Read time high **and** found rate near 100% | **Cold-read stall on a populated store.** The walk pays disk latency on data the node already has. Check store size and the sweep counters. |
|
||||
| Zero | Anything else | **Look upstream of the write path.** Storage is not the constraint — the work is either not arriving or being discarded before it lands. |
|
||||
| Continuing | Read time low **and** writer depth above 1 | **Serialized write path.** The queue is at the backend's insert mutex, not at the device. Tuning the disk will not help; see the note below. |
|
||||
| Continuing | Anything else | **Genuinely disk-bound.** The device is the limit. This is the only branch where storage hardware is the right thing to change. |
|
||||
|
||||
Queries, scoped to one node as everywhere else in this runbook:
|
||||
|
||||
```promql
|
||||
# Are acquisitions finishing? (per minute)
|
||||
increase(nodestore_state{metric="acquire_completions", service_instance_id=~"$node"}[1m])
|
||||
|
||||
# Read cost and the found rate that qualifies it
|
||||
nodestore_state{metric="read_mean_us", service_instance_id=~"$node"}
|
||||
rate(nodestore_state{metric="node_reads_hit", service_instance_id=~"$node"}[5m])
|
||||
/ rate(nodestore_state{metric="node_reads_total", service_instance_id=~"$node"}[5m])
|
||||
|
||||
# Write-side queueing: depth is fixed-point, divide by 100
|
||||
nodestore_state{metric="nudb_writer_depth_x100", service_instance_id=~"$node"} / 100
|
||||
nodestore_state{metric="nudb_insert_mean_us", service_instance_id=~"$node"}
|
||||
|
||||
# Read latency distribution, split by the two dimensions that matter
|
||||
histogram_quantile(0.99, sum by (le, fetch_type, found) (rate(nodestore_read_us_bucket{service_instance_id=~"$node"}[5m])))
|
||||
```
|
||||
|
||||
#### Measured reference points
|
||||
|
||||
Two runs on the same host, same build, differing only in the state of the store.
|
||||
Use these as the shape to compare against, not as thresholds.
|
||||
|
||||
| Signal | Mode W: clean store | Mode R: populated store, cold pages |
|
||||
| -------------------- | ------------------- | ----------------------------------- |
|
||||
| Time to `full` | 510 s | 260 s |
|
||||
| Read time, mean | 8.8 µs | 31.8 µs |
|
||||
| Read time, peak | 9 µs | 223 µs |
|
||||
| Found rate | 0.00 % | 88.3 % |
|
||||
| Insert time, mean | 20.0 µs | 15.9 µs |
|
||||
| Writer depth, mean | 1.60 | 1.00 |
|
||||
| Queueing per insert | 37 % | 0 % |
|
||||
| Deferrals over run | +5441 | +1845 |
|
||||
| Timeouts over run | +687 | +399 |
|
||||
| Completions over run | 0 | 8 |
|
||||
| Sweep evictions | +127 | +38 |
|
||||
|
||||
What healthy looks like: read mean in the single-digit microseconds, writer depth
|
||||
at 1.00, queueing near 0%, and `acquire_completions` advancing. Any one of a read
|
||||
mean in the tens or hundreds of microseconds, a writer depth above ~1.2, or
|
||||
completions flat at zero is worth chasing.
|
||||
|
||||
**How the 37% is derived.** It is not measured directly — it comes from the two
|
||||
gauges by Little's Law. With mean queue depth L and mean insert time W, the
|
||||
service time is `S = W / L` and the queueing component is `W − S`. Mode W's
|
||||
20.0 µs at depth 1.60 gives S = 12.5 µs, so 7.5 µs of every insert — 37% — is
|
||||
spent waiting for the mutex rather than writing. Mode R's depth of exactly 1.00
|
||||
gives S = W and no queueing, which is why it shows 0%.
|
||||
|
||||
**Why the write path serializes.** NuDB takes one global mutex per insert
|
||||
(`nudb/impl/basic_store.ipp:288`). It is a Conan dependency and is not patched
|
||||
here, so this is a property to observe and design around, not a bug to fix
|
||||
locally. `nudb_writer_depth_x100` is the queue length at that mutex.
|
||||
|
||||
#### The deferral/timeout pair
|
||||
|
||||
Read these two together or not at all. The livelock fingerprint is **deferrals
|
||||
rising while timeouts stay flat**.
|
||||
|
||||
A deferral happens when the acquisition timer job finds its lane already full. The
|
||||
timer is re-armed but its **body does not run**, so the retry counter never
|
||||
advances and the 6-timeout give-up becomes unreachable — the give-up path is
|
||||
disarmed and the acquisition can never end on its own. Neither counter alone shows
|
||||
this: deferrals rising looks like ordinary backpressure, and timeouts flat looks
|
||||
like health. Only the divergence is diagnostic. See the counter documentation in
|
||||
`src/xrpld/app/ledger/AcquireStats.h`.
|
||||
|
||||
Two more pairs from the same family:
|
||||
|
||||
- `acquire_sweep_evictions` rising while `acquire_completions` stays at zero →
|
||||
partial work is being discarded and redone. The sweep drops any acquisition
|
||||
idle for more than one minute
|
||||
(`src/xrpld/app/ledger/detail/InboundLedgers.cpp:400`), taking whatever it had
|
||||
built with it.
|
||||
- `acquire_aborts_partial` rising → the expensive form of an abort, where partly
|
||||
built maps were thrown away. `acquire_aborts` alone does not separate the cheap
|
||||
case from this one.
|
||||
|
||||
#### Honest limits of this diagnosis
|
||||
|
||||
- **The populated-store run was twice as fast, not slower** — 260 s against 510 s,
|
||||
despite reads being roughly 4× more expensive. Reusing local data beats fetching
|
||||
from peers even when every read is cold. Slow cold reads therefore do **not**
|
||||
on their own explain the 25-minute devnet incident.
|
||||
- Something compounds it there. The most likely candidate is a much larger store,
|
||||
where the walk takes long enough that the 1-minute sweep destroys partial work
|
||||
faster than it can complete — which is why the sweep and completion counters are
|
||||
in the table. This is not confirmed; treat it as the next thing to test, not as
|
||||
the answer.
|
||||
- The `nudb_*` label values are absent entirely on a non-NuDB writable backend.
|
||||
Absent is not zero — a missing series means "not applicable", so a panel showing
|
||||
a gap there is correct behaviour.
|
||||
- These gauges are sampled on the `MetricsRegistry` reader's 10 s cadence, while
|
||||
the `jobq_*` lane gauges are sampled at 1 s by a different provider. Widen the
|
||||
window when correlating them rather than reading a single scrape; see the caveat
|
||||
under [Slow TMGetObjectByHash service](#slow-tmgetobjectbyhash-service).
|
||||
- `read_mean_us` and `write_mean_us` are omitted rather than reported as zero when
|
||||
nothing has been read or written yet, so an idle node legitimately shows no
|
||||
series.
|
||||
|
||||
Existing panels that already carry part of this picture, on the _Ledger Data &
|
||||
Sync_ dashboard: **NuDB Read Latency**, **NuDB Cache Hit Ratio** (the found rate
|
||||
described above, under its historical name), **NuDB Read Pressure**, and **Job
|
||||
Queue Backlog and Deferred by Type** for the lane occupancy that this procedure
|
||||
tells you to distrust on its own.
|
||||
|
||||
### High memory usage
|
||||
|
||||
- Reduce trace volume with collector-side tail sampling (xrpld head sampling is
|
||||
|
||||
199
include/xrpl/telemetry/NodeStoreMetricNames.h
Normal file
199
include/xrpl/telemetry/NodeStoreMetricNames.h
Normal file
@@ -0,0 +1,199 @@
|
||||
#pragma once
|
||||
|
||||
// cspell:ignore ISTOGRAM
|
||||
// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's
|
||||
// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here.
|
||||
|
||||
/**
|
||||
* Metric name, description, label key and label values for the per-fetch
|
||||
* NodeStore read-latency histogram.
|
||||
*
|
||||
* The name is referenced from two translation units in two different
|
||||
* levelization modules, which is why these constants live in a header rather
|
||||
* than in either unit's unnamed namespace:
|
||||
*
|
||||
* NodeStoreMetricNames.h
|
||||
* |
|
||||
* +--> NodeStoreScheduler.cpp (xrpld.app -- the record site, via
|
||||
* | XRPL_METRIC_HISTOGRAM_RECORD_LABELED)
|
||||
* |
|
||||
* +--> MetricsRegistry.cpp (xrpld.telemetry -- registers the
|
||||
* explicit sub-millisecond bucket
|
||||
* boundaries for the same name)
|
||||
*
|
||||
* A copy-pasted literal would let the two drift, and a drifted name silently
|
||||
* drops the bucket override: the histogram would fall back to the SDK default
|
||||
* boundaries, whose lowest edge is far above the single-digit-microsecond
|
||||
* range a warm read occupies, so every warm read would land in bucket 0 and
|
||||
* the distribution would read as flat. This mirrors the reason
|
||||
* GetObjectMetricNames.h exists for the `getobject_*` family.
|
||||
*
|
||||
* Placed under `include/xrpl/telemetry/` for the same levelization reason as
|
||||
* GetObjectMetricNames.h: `xrpld.app > xrpl.telemetry` and
|
||||
* `xrpld.telemetry > xrpl.telemetry` are both existing edges (see
|
||||
* `.github/scripts/levelization/results/ordering.txt`), so `include/xrpl/` is
|
||||
* the one level both consumers can already reach. Both sites include this file
|
||||
* as `<xrpl/telemetry/NodeStoreMetricNames.h>`.
|
||||
*
|
||||
* Example usage -- registering the bucket view (MetricsRegistry.cpp):
|
||||
* @code
|
||||
* addHistogramView(
|
||||
* *views,
|
||||
* kNodeStoreReadUs,
|
||||
* {kSubMillisecondBoundaries.begin(), kSubMillisecondBoundaries.end()});
|
||||
* @endcode
|
||||
*
|
||||
* Example usage -- edge case: the record site labels one instrument with two
|
||||
* independent dimensions, which is why the keys and all four values are
|
||||
* constants rather than literals (a misspelling on either side would create a
|
||||
* second, silently disjoint series):
|
||||
* @code
|
||||
* XRPL_METRIC_HISTOGRAM_RECORD_LABELED(
|
||||
* app, kNodeStoreReadUs, kNodeStoreReadUsDesc, elapsed.count(),
|
||||
* {{kFetchTypeLabel, std::string(kFetchTypeAsync)},
|
||||
* {kFetchFoundLabel, std::string(kFetchFoundTrue)}});
|
||||
* @endcode
|
||||
*
|
||||
* @note These are `constexpr char[]`, not `constexpr std::string_view`. The
|
||||
* OTel C++ API takes `nostd::string_view`, which on this build is OTel's own
|
||||
* type; it converts from `char const*` and from `std::string` but has no
|
||||
* converting constructor from `std::string_view`, so a `string_view` constant
|
||||
* would not compile at the call sites. Same reasoning as
|
||||
* GetObjectMetricNames.h.
|
||||
*
|
||||
* @note Header-only constants with no runtime state, so there is nothing to
|
||||
* synchronize -- safe to include from any thread context.
|
||||
*/
|
||||
|
||||
namespace xrpl::telemetry {
|
||||
|
||||
// ===== Metric name and description ==========================================
|
||||
|
||||
/**
|
||||
* Per-fetch NodeStore backend read latency, in microseconds.
|
||||
*
|
||||
* Referenced twice: at the record site in NodeStoreScheduler.cpp, and by the
|
||||
* sub-millisecond `addHistogramView()` call in MetricsRegistry.cpp. Both must
|
||||
* use this one constant.
|
||||
*/
|
||||
inline constexpr char kNodeStoreReadUs[] = "nodestore_read_us";
|
||||
|
||||
/**
|
||||
* Description for kNodeStoreReadUs.
|
||||
*/
|
||||
inline constexpr char kNodeStoreReadUsDesc[] = "NodeStore backend fetch latency in microseconds";
|
||||
|
||||
// ===== Label keys ===========================================================
|
||||
|
||||
/**
|
||||
* Label key separating an async (read-ahead) fetch from a synchronous one.
|
||||
*
|
||||
* The two mean different things: a slow async read delays prefetch, while a
|
||||
* slow synchronous read blocks a caller outright. Merged into one series they
|
||||
* cannot be told apart.
|
||||
*/
|
||||
inline constexpr char kFetchTypeLabel[] = "fetch_type";
|
||||
|
||||
/**
|
||||
* Label key recording whether the fetch found the object.
|
||||
*
|
||||
* A miss and a hit have different cost profiles -- a miss can require reading
|
||||
* every backend -- so mixing them would blur the distribution that matters.
|
||||
*/
|
||||
inline constexpr char kFetchFoundLabel[] = "found";
|
||||
|
||||
// ===== Label values =========================================================
|
||||
|
||||
/** @{ */
|
||||
/**
|
||||
* kFetchTypeLabel values, one per node_store::FetchType enumerator.
|
||||
*/
|
||||
inline constexpr char kFetchTypeAsync[] = "async";
|
||||
inline constexpr char kFetchTypeSync[] = "sync";
|
||||
/** @} */
|
||||
|
||||
/** @{ */
|
||||
/**
|
||||
* kFetchFoundLabel values. Spelled out rather than emitted as a bool
|
||||
* AttributeValue so the exported label text is stable and matches the
|
||||
* string-valued convention every other label in this codebase follows.
|
||||
*/
|
||||
inline constexpr char kFetchFoundTrue[] = "true";
|
||||
inline constexpr char kFetchFoundFalse[] = "false";
|
||||
/** @} */
|
||||
|
||||
// ===== Record-site helpers ==================================================
|
||||
|
||||
/**
|
||||
* Map a fetch's async-ness to its kFetchTypeLabel value.
|
||||
*
|
||||
* Takes a bool rather than a node_store::FetchType because this header sits in
|
||||
* `xrpl.telemetry`, which has no levelization edge to `xrpl.nodestore`. The
|
||||
* caller does the one-line enum comparison; this function owns the mapping so
|
||||
* the two label spellings live in exactly one place and are unit-testable.
|
||||
*
|
||||
* @param isAsync True for node_store::FetchType::Async.
|
||||
* @return kFetchTypeAsync when @p isAsync, else kFetchTypeSync.
|
||||
*
|
||||
* @note Pure and reentrant: holds no state and performs no I/O.
|
||||
*
|
||||
* Example:
|
||||
* @code
|
||||
* fetchTypeLabelValue(true); // "async"
|
||||
* fetchTypeLabelValue(false); // "sync"
|
||||
* @endcode
|
||||
*/
|
||||
[[nodiscard]] constexpr char const*
|
||||
fetchTypeLabelValue(bool isAsync) noexcept
|
||||
{
|
||||
return isAsync ? kFetchTypeAsync : kFetchTypeSync;
|
||||
}
|
||||
|
||||
/**
|
||||
* Map a fetch's hit/miss outcome to its kFetchFoundLabel value.
|
||||
*
|
||||
* @param wasFound node_store::FetchReport::wasFound.
|
||||
* @return kFetchFoundTrue when @p wasFound, else kFetchFoundFalse.
|
||||
*
|
||||
* @note Pure and reentrant: holds no state and performs no I/O.
|
||||
*
|
||||
* Example:
|
||||
* @code
|
||||
* fetchFoundLabelValue(true); // "true"
|
||||
* fetchFoundLabelValue(false); // "false"
|
||||
* @endcode
|
||||
*/
|
||||
[[nodiscard]] constexpr char const*
|
||||
fetchFoundLabelValue(bool wasFound) noexcept
|
||||
{
|
||||
return wasFound ? kFetchFoundTrue : kFetchFoundFalse;
|
||||
}
|
||||
|
||||
/**
|
||||
* Whether an elapsed microsecond count may be handed to the histogram.
|
||||
*
|
||||
* The OTel SDK rejects a negative histogram value and logs a warning on every
|
||||
* such call, so a clock anomaly on a per-fetch path would turn into a log
|
||||
* flood. Filtering here drops the bad sample instead.
|
||||
*
|
||||
* Zero is recordable: a fetch served from a warm page cache can genuinely
|
||||
* round to 0 us, and suppressing that would make the fastest reads invisible.
|
||||
*
|
||||
* @param elapsedUs Measured fetch duration in microseconds.
|
||||
* @return True when @p elapsedUs is zero or positive.
|
||||
*
|
||||
* @note Pure and reentrant: holds no state and performs no I/O.
|
||||
*
|
||||
* Example:
|
||||
* @code
|
||||
* shouldRecordFetchLatency(0); // true -- genuinely instant read
|
||||
* shouldRecordFetchLatency(-1); // false -- clock anomaly, skip
|
||||
* @endcode
|
||||
*/
|
||||
[[nodiscard]] constexpr bool
|
||||
shouldRecordFetchLatency(long long elapsedUs) noexcept
|
||||
{
|
||||
return elapsedUs >= 0;
|
||||
}
|
||||
|
||||
} // namespace xrpl::telemetry
|
||||
@@ -541,7 +541,7 @@ public:
|
||||
env.app().config().getValueFor(SizedItem::TreeCacheAge, std::nullopt)));
|
||||
}
|
||||
|
||||
NodeStoreScheduler scheduler(env.app().getJobQueue());
|
||||
NodeStoreScheduler scheduler(env.app(), env.app().getJobQueue());
|
||||
|
||||
std::string const writableDb = "write";
|
||||
std::string const archiveDb = "archive";
|
||||
|
||||
@@ -25,7 +25,6 @@
|
||||
#include <chrono>
|
||||
#include <condition_variable>
|
||||
#include <cstdint>
|
||||
#include <functional>
|
||||
#include <limits>
|
||||
#include <map>
|
||||
#include <memory>
|
||||
@@ -473,7 +472,7 @@ class JobQueue_test : public beast::unit_test::Suite
|
||||
{
|
||||
testcase("Saturation gauge creation");
|
||||
|
||||
GaugeFixture fixture(1);
|
||||
GaugeFixture const fixture(1);
|
||||
|
||||
// JtLedgerReq has limit 3, so it is not special and must be gauged.
|
||||
BEAST_EXPECT(!JobTypes::instance().get(JtLedgerReq).special());
|
||||
@@ -660,7 +659,7 @@ class JobQueue_test : public beast::unit_test::Suite
|
||||
{
|
||||
testcase("Saturation gauge coverage");
|
||||
|
||||
GaugeFixture fixture(1);
|
||||
GaugeFixture const fixture(1);
|
||||
fixture.collector->runHooks();
|
||||
|
||||
// Sanity-check the fixture against the job-type table itself, so the
|
||||
|
||||
@@ -6,6 +6,7 @@
|
||||
#include <xrpld/core/Config.h>
|
||||
|
||||
#include <xrpl/basics/Blob.h>
|
||||
#include <xrpl/basics/ByteUtilities.h>
|
||||
#include <xrpl/basics/base_uint.h>
|
||||
#include <xrpl/basics/random.h>
|
||||
#include <xrpl/beast/unit_test/suite.h>
|
||||
@@ -22,7 +23,6 @@
|
||||
#include <xrpl/nodestore/NodeObject.h>
|
||||
#include <xrpl/nodestore/Types.h>
|
||||
#include <xrpl/nodestore/detail/DatabaseRotatingImp.h>
|
||||
#include <xrpl/protocol/SystemParameters.h>
|
||||
#include <xrpl/rdb/DatabaseCon.h>
|
||||
|
||||
#include <cstddef>
|
||||
|
||||
@@ -98,10 +98,22 @@ if(telemetry)
|
||||
HINTS "${opentelemetry-cpp_PACKAGE_FOLDER_RELEASE}/lib"
|
||||
REQUIRED
|
||||
)
|
||||
# The metric side of the in-memory exporter is a SEPARATE archive
|
||||
# (libopentelemetry_exporter_in_memory_metric.a) with the same
|
||||
# no-declared-libs problem, so it needs its own find_library. The
|
||||
# nodestore read-latency histogram tests use it to read exported
|
||||
# histogram points back and assert per-bucket counts.
|
||||
find_library(
|
||||
OTEL_IN_MEMORY_METRIC_EXPORTER_LIB
|
||||
NAMES opentelemetry_exporter_in_memory_metric
|
||||
HINTS "${opentelemetry-cpp_PACKAGE_FOLDER_RELEASE}/lib"
|
||||
REQUIRED
|
||||
)
|
||||
target_link_libraries(
|
||||
xrpl_tests
|
||||
PRIVATE
|
||||
"${OTEL_IN_MEMORY_EXPORTER_LIB}"
|
||||
"${OTEL_IN_MEMORY_METRIC_EXPORTER_LIB}"
|
||||
opentelemetry-cpp::opentelemetry-cpp
|
||||
)
|
||||
# ValidationTracker lives in src/xrpld/ (not libxrpl), so we compile its
|
||||
|
||||
526
src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp
Normal file
526
src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp
Normal file
@@ -0,0 +1,526 @@
|
||||
/**
|
||||
* @file NodeStoreMetricNames.cpp
|
||||
* Unit tests for the nodestore read-latency histogram wiring.
|
||||
*
|
||||
* Two independent groups, split by what they can link:
|
||||
*
|
||||
* 1. The shared name/label constants and the three record-site helpers from
|
||||
* `<xrpl/telemetry/NodeStoreMetricNames.h>`. Header-only and free of any
|
||||
* OTel dependency, so these run in **both** builds. That matters: the
|
||||
* constants are what keeps the bucket-view registration in
|
||||
* MetricsRegistry.cpp and the record site in NodeStoreScheduler.cpp
|
||||
* agreeing on one instrument name, and a divergence there silently drops
|
||||
* the sub-millisecond bucket override.
|
||||
*
|
||||
* 2. An end-to-end record-and-read-back over a real SDK MeterProvider fitted
|
||||
* with the same explicit sub-millisecond boundaries production registers,
|
||||
* asserting the exact bucket counts a set of known latencies must land in.
|
||||
* Guarded on XRPL_ENABLE_TELEMETRY because the metrics SDK headers only
|
||||
* exist in that build.
|
||||
*
|
||||
* Why the second group does not drive NodeStoreScheduler directly: that class
|
||||
* lives in xrpld (`src/xrpld/app/main/`) and its onFetch() needs a live
|
||||
* JobQueue plus a ServiceRegistry, neither of which the standalone xrpl_tests
|
||||
* binary can supply -- the same reason MetricsRegistry.cpp is only compiled
|
||||
* into this binary on the no-op path (see src/tests/libxrpl/CMakeLists.txt).
|
||||
* What is testable here is everything that decides *what* gets recorded: the
|
||||
* instrument name, the two label values, the negative-value guard, and the
|
||||
* bucket ladder the value is filed into. The remaining step -- that
|
||||
* Database::fetchNodeObject actually reaches onFetch -- is covered by the
|
||||
* existing nodestore suites, which already exercise that call path.
|
||||
*/
|
||||
|
||||
#include <xrpl/telemetry/NodeStoreMetricNames.h>
|
||||
|
||||
#include <gtest/gtest.h>
|
||||
|
||||
#include <string_view>
|
||||
|
||||
namespace {
|
||||
|
||||
using namespace xrpl::telemetry;
|
||||
|
||||
// ---------------------------------------------------------------------------
|
||||
// Group 1: shared constants and record-site helpers. Compile-time first, so a
|
||||
// regression is a build failure rather than only a test failure; the runtime
|
||||
// duplicates below name the offending case when one does fail.
|
||||
// ---------------------------------------------------------------------------
|
||||
|
||||
// The instrument name is the contract between the two call sites. Pinned to
|
||||
// the exact literal: bare lower snake_case, no `xrpld_` prefix (no metric in
|
||||
// this codebase carries one), and the `_us` suffix stating the unit.
|
||||
static_assert(std::string_view{kNodeStoreReadUs} == "nodestore_read_us");
|
||||
|
||||
// Label keys. `found` rather than `was_found` and `fetch_type` rather than
|
||||
// `type`, matching what the dashboards query.
|
||||
static_assert(std::string_view{kFetchTypeLabel} == "fetch_type");
|
||||
static_assert(std::string_view{kFetchFoundLabel} == "found");
|
||||
|
||||
// Label values.
|
||||
static_assert(std::string_view{kFetchTypeAsync} == "async");
|
||||
static_assert(std::string_view{kFetchTypeSync} == "sync");
|
||||
static_assert(std::string_view{kFetchFoundTrue} == "true");
|
||||
static_assert(std::string_view{kFetchFoundFalse} == "false");
|
||||
|
||||
// The helpers map each input to exactly one value, and the two arms differ.
|
||||
static_assert(std::string_view{fetchTypeLabelValue(true)} == "async");
|
||||
static_assert(std::string_view{fetchTypeLabelValue(false)} == "sync");
|
||||
static_assert(std::string_view{fetchFoundLabelValue(true)} == "true");
|
||||
static_assert(std::string_view{fetchFoundLabelValue(false)} == "false");
|
||||
|
||||
// The negative guard. Zero is admitted on purpose -- a page-cache hit really
|
||||
// can round to 0 us -- while anything below it is refused.
|
||||
static_assert(shouldRecordFetchLatency(0));
|
||||
static_assert(shouldRecordFetchLatency(1));
|
||||
static_assert(shouldRecordFetchLatency(25'000));
|
||||
static_assert(!shouldRecordFetchLatency(-1));
|
||||
|
||||
} // namespace
|
||||
|
||||
TEST(NodeStoreMetricNames, instrument_name_is_the_exact_shared_literal)
|
||||
{
|
||||
// Both the view registration (MetricsRegistry.cpp) and the record site
|
||||
// (NodeStoreScheduler.cpp) read this one constant. If it changes, the
|
||||
// dashboard query and the reference doc must change with it, so the exact
|
||||
// string is asserted rather than merely its shape.
|
||||
EXPECT_EQ(std::string_view{kNodeStoreReadUs}, "nodestore_read_us");
|
||||
EXPECT_EQ(std::string_view{kNodeStoreReadUs}.size(), 17u);
|
||||
|
||||
// No `xrpld_` prefix: verified against the live metric surface, where 0 of
|
||||
// 537 exported names carry one. A prefix here would make this the only
|
||||
// odd metric out and break every dashboard that globs the family.
|
||||
EXPECT_FALSE(std::string_view{kNodeStoreReadUs}.starts_with("xrpld_"));
|
||||
|
||||
// The `_us` suffix is load-bearing: FetchReport::elapsed is
|
||||
// std::chrono::microseconds, and a name implying milliseconds would make
|
||||
// every reading 1000x wrong to a reader.
|
||||
EXPECT_TRUE(std::string_view{kNodeStoreReadUs}.ends_with("_us"));
|
||||
|
||||
// The description must name the unit too, since that is all a Prometheus
|
||||
// consumer sees alongside the metric.
|
||||
EXPECT_EQ(
|
||||
std::string_view{kNodeStoreReadUsDesc}, "NodeStore backend fetch latency in microseconds");
|
||||
}
|
||||
|
||||
TEST(NodeStoreMetricNames, label_keys_and_values_are_the_exact_literals)
|
||||
{
|
||||
EXPECT_EQ(std::string_view{kFetchTypeLabel}, "fetch_type");
|
||||
EXPECT_EQ(std::string_view{kFetchFoundLabel}, "found");
|
||||
|
||||
EXPECT_EQ(std::string_view{kFetchTypeAsync}, "async");
|
||||
EXPECT_EQ(std::string_view{kFetchTypeSync}, "sync");
|
||||
EXPECT_EQ(std::string_view{kFetchFoundTrue}, "true");
|
||||
EXPECT_EQ(std::string_view{kFetchFoundFalse}, "false");
|
||||
|
||||
// The two keys must differ, or one label would overwrite the other in the
|
||||
// attribute map and a whole dimension would vanish.
|
||||
EXPECT_NE(std::string_view{kFetchTypeLabel}, std::string_view{kFetchFoundLabel});
|
||||
}
|
||||
|
||||
TEST(NodeStoreMetricNames, helpers_map_each_input_to_its_own_value)
|
||||
{
|
||||
// Positive path for both arms of both helpers.
|
||||
EXPECT_EQ(std::string_view{fetchTypeLabelValue(true)}, "async");
|
||||
EXPECT_EQ(std::string_view{fetchTypeLabelValue(false)}, "sync");
|
||||
EXPECT_EQ(std::string_view{fetchFoundLabelValue(true)}, "true");
|
||||
EXPECT_EQ(std::string_view{fetchFoundLabelValue(false)}, "false");
|
||||
|
||||
// Cause, not just state: the two arms are genuinely distinct, so a
|
||||
// copy-paste that returned the same value for both would fail here rather
|
||||
// than quietly collapsing async and sync into one series.
|
||||
EXPECT_NE(
|
||||
std::string_view{fetchTypeLabelValue(true)}, std::string_view{fetchTypeLabelValue(false)});
|
||||
EXPECT_NE(
|
||||
std::string_view{fetchFoundLabelValue(true)},
|
||||
std::string_view{fetchFoundLabelValue(false)});
|
||||
|
||||
// Each helper returns one of its own two constants and never the other
|
||||
// helper's, which is what keeps the two dimensions independent.
|
||||
EXPECT_EQ(fetchTypeLabelValue(true), kFetchTypeAsync);
|
||||
EXPECT_EQ(fetchTypeLabelValue(false), kFetchTypeSync);
|
||||
EXPECT_EQ(fetchFoundLabelValue(true), kFetchFoundTrue);
|
||||
EXPECT_EQ(fetchFoundLabelValue(false), kFetchFoundFalse);
|
||||
}
|
||||
|
||||
TEST(NodeStoreMetricNames, latency_guard_admits_zero_and_refuses_negatives)
|
||||
{
|
||||
// Negative path -- the reason the guard exists. The OTel SDK drops a
|
||||
// negative histogram value AND logs a warning for it; on a per-fetch path
|
||||
// that is a log flood, so the sample is filtered before it gets there.
|
||||
EXPECT_FALSE(shouldRecordFetchLatency(-1));
|
||||
EXPECT_FALSE(shouldRecordFetchLatency(-1'000));
|
||||
|
||||
// Zero must NOT be filtered: a read served from the page cache genuinely
|
||||
// truncates to 0 us, and suppressing it would hide the fastest reads and
|
||||
// bias the whole distribution upward.
|
||||
EXPECT_TRUE(shouldRecordFetchLatency(0));
|
||||
|
||||
// Ordinary and cold-tail values pass.
|
||||
EXPECT_TRUE(shouldRecordFetchLatency(1));
|
||||
EXPECT_TRUE(shouldRecordFetchLatency(9));
|
||||
EXPECT_TRUE(shouldRecordFetchLatency(250));
|
||||
EXPECT_TRUE(shouldRecordFetchLatency(30'000));
|
||||
|
||||
// The boundary is exactly at zero, not near it.
|
||||
EXPECT_TRUE(shouldRecordFetchLatency(0));
|
||||
EXPECT_FALSE(shouldRecordFetchLatency(-1));
|
||||
}
|
||||
|
||||
// ---------------------------------------------------------------------------
|
||||
// Group 2: record into a real histogram carrying production's explicit
|
||||
// sub-millisecond boundaries, then read the exported point back and assert the
|
||||
// exact per-bucket counts.
|
||||
//
|
||||
// This is what proves the signal is usable rather than merely emitted. The
|
||||
// SDK's default boundaries begin at 0/5/10/25... but top out at 10,000, and
|
||||
// the microsecond ladder used by the other duration histograms begins at 100
|
||||
// us -- above the entire range a warm read occupies. Under that ladder every
|
||||
// warm read files into bucket 0 and the distribution reads flat. The
|
||||
// assertions below pin warm reads into distinct low buckets, which is exactly
|
||||
// the property the sub-millisecond ladder exists to provide.
|
||||
// ---------------------------------------------------------------------------
|
||||
|
||||
#ifdef XRPL_ENABLE_TELEMETRY
|
||||
|
||||
#include <opentelemetry/context/context.h>
|
||||
#include <opentelemetry/exporters/memory/in_memory_metric_data.h>
|
||||
#include <opentelemetry/exporters/memory/in_memory_metric_exporter_factory.h>
|
||||
#include <opentelemetry/metrics/meter.h>
|
||||
#include <opentelemetry/nostd/variant.h>
|
||||
#include <opentelemetry/sdk/metrics/aggregation/aggregation_config.h>
|
||||
#include <opentelemetry/sdk/metrics/data/metric_data.h>
|
||||
#include <opentelemetry/sdk/metrics/data/point_data.h>
|
||||
#include <opentelemetry/sdk/metrics/export/periodic_exporting_metric_reader_factory.h>
|
||||
#include <opentelemetry/sdk/metrics/export/periodic_exporting_metric_reader_options.h>
|
||||
#include <opentelemetry/sdk/metrics/instruments.h>
|
||||
#include <opentelemetry/sdk/metrics/meter_provider.h>
|
||||
#include <opentelemetry/sdk/metrics/meter_provider_factory.h>
|
||||
#include <opentelemetry/sdk/metrics/view/instrument_selector_factory.h>
|
||||
#include <opentelemetry/sdk/metrics/view/meter_selector_factory.h>
|
||||
#include <opentelemetry/sdk/metrics/view/view_factory.h>
|
||||
#include <opentelemetry/sdk/metrics/view/view_registry.h>
|
||||
|
||||
#include <array>
|
||||
#include <chrono>
|
||||
#include <cstdint>
|
||||
#include <memory>
|
||||
#include <string>
|
||||
#include <utility>
|
||||
#include <vector>
|
||||
|
||||
namespace {
|
||||
|
||||
namespace metric_sdk = opentelemetry::sdk::metrics;
|
||||
namespace in_memory = opentelemetry::exporter::memory;
|
||||
|
||||
/**
|
||||
* The same edges MetricsRegistry.cpp's kSubMillisecondBoundaries holds.
|
||||
*
|
||||
* Deliberately a second, independent copy rather than an include of the
|
||||
* production array: that constant lives in an unnamed namespace inside
|
||||
* MetricsRegistry.cpp and is unreachable from here, and re-deriving the edges
|
||||
* from the implementation would make the bucket-index assertions below
|
||||
* tautological. Written out by hand, they pin the ladder -- so silently
|
||||
* re-tuning an edge in production without revisiting this file fails here.
|
||||
*/
|
||||
constexpr std::array kExpectedBoundaries{
|
||||
1.0,
|
||||
2.0,
|
||||
5.0,
|
||||
10.0,
|
||||
25.0,
|
||||
50.0,
|
||||
100.0,
|
||||
250.0,
|
||||
500.0,
|
||||
1'000.0,
|
||||
5'000.0,
|
||||
25'000.0};
|
||||
|
||||
/**
|
||||
* Meter identity used by the production view selector, so the view this
|
||||
* fixture registers matches the instrument the fixture creates.
|
||||
*/
|
||||
constexpr char kMeterName[] = "xrpld";
|
||||
constexpr char kMeterVersion[] = "1.0.0";
|
||||
|
||||
/**
|
||||
* A MeterProvider carrying one explicit-bucket view for kNodeStoreReadUs and
|
||||
* an in-memory exporter, so a test can record values and read the resulting
|
||||
* histogram point back without any network or OTLP involvement.
|
||||
*
|
||||
* Mirrors what MetricsRegistry::initExporterAndProvider() builds for this
|
||||
* instrument, minus the OTLP exporter.
|
||||
*/
|
||||
class HistogramFixture
|
||||
{
|
||||
public:
|
||||
HistogramFixture()
|
||||
{
|
||||
// The view: same instrument type, same name, same meter selector and
|
||||
// the same boundaries production registers.
|
||||
auto config = std::make_shared<metric_sdk::HistogramAggregationConfig>();
|
||||
config->boundaries_ = {kExpectedBoundaries.begin(), kExpectedBoundaries.end()};
|
||||
|
||||
auto views = std::make_unique<metric_sdk::ViewRegistry>();
|
||||
views->AddView(
|
||||
metric_sdk::InstrumentSelectorFactory::Create(
|
||||
metric_sdk::InstrumentType::kHistogram, kNodeStoreReadUs, ""),
|
||||
metric_sdk::MeterSelectorFactory::Create(kMeterName, kMeterVersion, ""),
|
||||
metric_sdk::ViewFactory::Create(
|
||||
kNodeStoreReadUs, "", metric_sdk::AggregationType::kHistogram, config));
|
||||
|
||||
provider_ = metric_sdk::MeterProviderFactory::Create(std::move(views));
|
||||
|
||||
// A long export interval keeps the background thread from exporting
|
||||
// on its own schedule; the test drives collection via ForceFlush().
|
||||
metric_sdk::PeriodicExportingMetricReaderOptions readerOpts;
|
||||
readerOpts.export_interval_millis = std::chrono::milliseconds(600'000);
|
||||
readerOpts.export_timeout_millis = std::chrono::milliseconds(5'000);
|
||||
provider_->AddMetricReader(
|
||||
metric_sdk::PeriodicExportingMetricReaderFactory::Create(
|
||||
in_memory::InMemoryMetricExporterFactory::Create(data_), readerOpts));
|
||||
|
||||
histogram_ = provider_->GetMeter(kMeterName, kMeterVersion)
|
||||
->CreateDoubleHistogram(kNodeStoreReadUs, kNodeStoreReadUsDesc);
|
||||
}
|
||||
|
||||
~HistogramFixture()
|
||||
{
|
||||
provider_->Shutdown();
|
||||
}
|
||||
|
||||
HistogramFixture(HistogramFixture const&) = delete;
|
||||
HistogramFixture&
|
||||
operator=(HistogramFixture const&) = delete;
|
||||
|
||||
/**
|
||||
* Record one latency with the exact label set the production record site
|
||||
* attaches, built through the same two helpers.
|
||||
*
|
||||
* @param elapsedUs Latency in microseconds.
|
||||
* @param isAsync True for an async (prefetch) read.
|
||||
* @param wasFound True when the object was found.
|
||||
*/
|
||||
void
|
||||
record(double elapsedUs, bool isAsync, bool wasFound)
|
||||
{
|
||||
histogram_->Record(
|
||||
elapsedUs,
|
||||
{{kFetchTypeLabel, std::string(fetchTypeLabelValue(isAsync))},
|
||||
{kFetchFoundLabel, std::string(fetchFoundLabelValue(wasFound))}},
|
||||
opentelemetry::context::Context{});
|
||||
}
|
||||
|
||||
/**
|
||||
* Flush the reader, then return every exported histogram point for
|
||||
* kNodeStoreReadUs keyed by its attribute set.
|
||||
*/
|
||||
[[nodiscard]] in_memory::SimpleAggregateInMemoryMetricData::AttributeToPoint const&
|
||||
collect()
|
||||
{
|
||||
provider_->ForceFlush();
|
||||
return data_->Get(kMeterName, kNodeStoreReadUs);
|
||||
}
|
||||
|
||||
private:
|
||||
/**
|
||||
* Sink the in-memory exporter writes each collection into.
|
||||
*/
|
||||
std::shared_ptr<in_memory::SimpleAggregateInMemoryMetricData> data_ =
|
||||
std::make_shared<in_memory::SimpleAggregateInMemoryMetricData>();
|
||||
|
||||
/**
|
||||
* Provider owning the view registry and the in-memory reader.
|
||||
*/
|
||||
std::shared_ptr<metric_sdk::MeterProvider> provider_;
|
||||
|
||||
/**
|
||||
* The instrument under test.
|
||||
*/
|
||||
opentelemetry::nostd::unique_ptr<opentelemetry::metrics::Histogram<double>> histogram_;
|
||||
};
|
||||
|
||||
/**
|
||||
* Extract the HistogramPointData for the one series matching @p isAsync and
|
||||
* @p wasFound, or nullptr when no such series was exported.
|
||||
*
|
||||
* @param points Exported points keyed by attribute set.
|
||||
* @param isAsync fetch_type dimension to match.
|
||||
* @param wasFound found dimension to match.
|
||||
*/
|
||||
[[nodiscard]] metric_sdk::HistogramPointData const*
|
||||
findPoint(
|
||||
in_memory::SimpleAggregateInMemoryMetricData::AttributeToPoint const& points,
|
||||
bool isAsync,
|
||||
bool wasFound)
|
||||
{
|
||||
for (auto const& [attributes, point] : points)
|
||||
{
|
||||
auto const type = attributes.find(kFetchTypeLabel);
|
||||
auto const found = attributes.find(kFetchFoundLabel);
|
||||
if (type == attributes.end() || found == attributes.end())
|
||||
continue;
|
||||
|
||||
if (opentelemetry::nostd::get<std::string>(type->second) != fetchTypeLabelValue(isAsync) ||
|
||||
opentelemetry::nostd::get<std::string>(found->second) != fetchFoundLabelValue(wasFound))
|
||||
continue;
|
||||
|
||||
return &opentelemetry::nostd::get<metric_sdk::HistogramPointData>(point);
|
||||
}
|
||||
return nullptr;
|
||||
}
|
||||
|
||||
} // namespace
|
||||
|
||||
TEST(NodeStoreReadHistogram, view_applies_the_sub_millisecond_boundaries)
|
||||
{
|
||||
HistogramFixture fixture;
|
||||
fixture.record(9.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
|
||||
auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true);
|
||||
ASSERT_NE(point, nullptr);
|
||||
|
||||
// The exported point must carry OUR boundaries, not the SDK defaults. This
|
||||
// is the assertion that catches a name mismatch between the view selector
|
||||
// and the instrument: on a mismatch the view is never applied and the
|
||||
// default ladder appears here instead.
|
||||
ASSERT_EQ(point->boundaries_.size(), kExpectedBoundaries.size());
|
||||
for (std::size_t i = 0; i < kExpectedBoundaries.size(); ++i)
|
||||
EXPECT_EQ(point->boundaries_[i], kExpectedBoundaries[i]) << "boundary index " << i;
|
||||
|
||||
// The first edge is 1 us, three orders of magnitude below the microsecond
|
||||
// ladder's 100 us first edge. That difference is the entire point: without
|
||||
// it a warm read cannot be distinguished from an instant one.
|
||||
EXPECT_EQ(point->boundaries_.front(), 1.0);
|
||||
EXPECT_EQ(point->boundaries_.back(), 25'000.0);
|
||||
}
|
||||
|
||||
TEST(NodeStoreReadHistogram, warm_reads_land_in_distinct_low_buckets)
|
||||
{
|
||||
HistogramFixture fixture;
|
||||
|
||||
// Four warm latencies, each chosen to fall in a different low bucket.
|
||||
// Bucket i counts values in (boundaries[i-1], boundaries[i]].
|
||||
// 0.5 us -> bucket 0 ( <= 1 )
|
||||
// 3 us -> bucket 2 ( 2 < v <= 5 )
|
||||
// 9 us -> bucket 3 ( 5 < v <= 10 )
|
||||
// 40 us -> bucket 5 ( 25 < v <= 50 )
|
||||
fixture.record(0.5, /*isAsync=*/false, /*wasFound=*/true);
|
||||
fixture.record(3.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
fixture.record(9.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
fixture.record(40.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
|
||||
auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true);
|
||||
ASSERT_NE(point, nullptr);
|
||||
|
||||
// Exact counts, bucket by bucket -- not merely "the total is 4". Under the
|
||||
// microsecond ladder all four would sit in bucket 0 and this test would
|
||||
// fail, which is precisely the regression it guards against.
|
||||
ASSERT_EQ(point->counts_.size(), kExpectedBoundaries.size() + 1);
|
||||
EXPECT_EQ(point->counts_[0], 1u); // 0.5 us
|
||||
EXPECT_EQ(point->counts_[1], 0u);
|
||||
EXPECT_EQ(point->counts_[2], 1u); // 3 us
|
||||
EXPECT_EQ(point->counts_[3], 1u); // 9 us
|
||||
EXPECT_EQ(point->counts_[4], 0u);
|
||||
EXPECT_EQ(point->counts_[5], 1u); // 40 us
|
||||
for (std::size_t i = 6; i < point->counts_.size(); ++i)
|
||||
EXPECT_EQ(point->counts_[i], 0u) << "bucket " << i << " should be empty";
|
||||
|
||||
// Aggregate state must agree with the per-bucket detail.
|
||||
EXPECT_EQ(point->count_, 4u);
|
||||
EXPECT_EQ(opentelemetry::nostd::get<double>(point->sum_), 52.5);
|
||||
EXPECT_EQ(opentelemetry::nostd::get<double>(point->min_), 0.5);
|
||||
EXPECT_EQ(opentelemetry::nostd::get<double>(point->max_), 40.0);
|
||||
}
|
||||
|
||||
TEST(NodeStoreReadHistogram, a_cold_read_lands_in_the_tail_not_the_ceiling)
|
||||
{
|
||||
HistogramFixture fixture;
|
||||
|
||||
// A cold read and an outlier beyond the top edge. 800 us falls in bucket 9
|
||||
// ( 500 < v <= 1000 ); 30000 us exceeds the 25000 top edge and so lands in
|
||||
// the overflow bucket, index 12.
|
||||
fixture.record(800.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
fixture.record(30'000.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
|
||||
auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true);
|
||||
ASSERT_NE(point, nullptr);
|
||||
|
||||
EXPECT_EQ(point->counts_[9], 1u); // 800 us -- resolved, not saturated
|
||||
EXPECT_EQ(point->counts_[12], 1u); // 30 ms -- overflow bucket
|
||||
EXPECT_EQ(point->count_, 2u);
|
||||
EXPECT_EQ(opentelemetry::nostd::get<double>(point->max_), 30'000.0);
|
||||
}
|
||||
|
||||
TEST(NodeStoreReadHistogram, the_two_labels_split_the_series_four_ways)
|
||||
{
|
||||
HistogramFixture fixture;
|
||||
|
||||
// One record per (fetch_type, found) combination, each with a distinct
|
||||
// latency so the series cannot be confused with one another.
|
||||
fixture.record(3.0, /*isAsync=*/true, /*wasFound=*/true);
|
||||
fixture.record(9.0, /*isAsync=*/true, /*wasFound=*/false);
|
||||
fixture.record(40.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
fixture.record(800.0, /*isAsync=*/false, /*wasFound=*/false);
|
||||
|
||||
auto const& points = fixture.collect();
|
||||
|
||||
// Four distinct label sets means four distinct time series. If either
|
||||
// label were dropped or misspelled these would collapse into fewer.
|
||||
EXPECT_EQ(points.size(), 4u);
|
||||
|
||||
struct Expected
|
||||
{
|
||||
bool isAsync;
|
||||
bool wasFound;
|
||||
double value;
|
||||
std::size_t bucket;
|
||||
};
|
||||
|
||||
// Each series holds exactly its own one sample, in its own bucket. This is
|
||||
// the assertion that a label mix-up would break: swapping two values would
|
||||
// put a sample in the wrong series and fail here.
|
||||
for (auto const& [isAsync, wasFound, value, bucket] : std::array<Expected, 4>{
|
||||
{{true, true, 3.0, 2},
|
||||
{true, false, 9.0, 3},
|
||||
{false, true, 40.0, 5},
|
||||
{false, false, 800.0, 9}}})
|
||||
{
|
||||
auto const* point = findPoint(points, isAsync, wasFound);
|
||||
ASSERT_NE(point, nullptr) << "missing series for fetch_type="
|
||||
<< fetchTypeLabelValue(isAsync)
|
||||
<< " found=" << fetchFoundLabelValue(wasFound);
|
||||
EXPECT_EQ(point->count_, 1u);
|
||||
EXPECT_EQ(opentelemetry::nostd::get<double>(point->sum_), value);
|
||||
EXPECT_EQ(point->counts_[bucket], 1u);
|
||||
}
|
||||
}
|
||||
|
||||
TEST(NodeStoreReadHistogram, a_guarded_negative_latency_never_reaches_the_instrument)
|
||||
{
|
||||
HistogramFixture fixture;
|
||||
|
||||
// Negative path, end to end: the record site consults
|
||||
// shouldRecordFetchLatency() before calling Record(), so a clock anomaly
|
||||
// produces no sample at all. Reproduced here with the same guard.
|
||||
for (double const elapsedUs : {-1.0, -1'000.0})
|
||||
{
|
||||
if (shouldRecordFetchLatency(static_cast<long long>(elapsedUs)))
|
||||
fixture.record(elapsedUs, /*isAsync=*/false, /*wasFound=*/true);
|
||||
}
|
||||
|
||||
// No series at all: nothing was recorded, so the instrument exported
|
||||
// nothing rather than exporting a zero-count point.
|
||||
EXPECT_TRUE(fixture.collect().empty());
|
||||
|
||||
// Cause, not just state: the same fixture DOES accept a valid sample, so
|
||||
// the emptiness above is the guard working and not a broken fixture.
|
||||
fixture.record(9.0, /*isAsync=*/false, /*wasFound=*/true);
|
||||
auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true);
|
||||
ASSERT_NE(point, nullptr);
|
||||
EXPECT_EQ(point->count_, 1u);
|
||||
EXPECT_EQ(point->counts_[3], 1u);
|
||||
}
|
||||
|
||||
#endif // XRPL_ENABLE_TELEMETRY
|
||||
@@ -393,7 +393,11 @@ public:
|
||||
logs_->journal("JobQueue"),
|
||||
*logs_,
|
||||
*perfLog_))
|
||||
, nodeStoreScheduler_(*jobQueue_)
|
||||
// `*this` is passed as a ServiceRegistry only to reach the
|
||||
// MetricsRegistry later, from onFetch(). It is not dereferenced here,
|
||||
// and metricsRegistry_ does not exist yet at this point in the
|
||||
// initializer list -- the metric macros null-check it per call.
|
||||
, nodeStoreScheduler_(*this, *jobQueue_)
|
||||
, shaMapStore_(makeSHAMapStore(*this, nodeStoreScheduler_, logs_->journal("SHAMapStore")))
|
||||
, tempNodeCache_(
|
||||
"NodeCache",
|
||||
|
||||
@@ -1,15 +1,29 @@
|
||||
// cspell:ignore ISTOGRAM
|
||||
// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD_LABELED trips cspell's
|
||||
// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here.
|
||||
|
||||
#include <xrpld/app/main/NodeStoreScheduler.h>
|
||||
|
||||
#include <xrpld/telemetry/MetricMacros.h>
|
||||
|
||||
#include <xrpl/core/Job.h>
|
||||
#include <xrpl/core/JobQueue.h>
|
||||
#include <xrpl/core/ServiceRegistry.h>
|
||||
#include <xrpl/nodestore/Scheduler.h>
|
||||
#include <xrpl/nodestore/Task.h>
|
||||
#include <xrpl/telemetry/NodeStoreMetricNames.h>
|
||||
|
||||
#include <chrono>
|
||||
#include <string>
|
||||
|
||||
namespace xrpl {
|
||||
|
||||
NodeStoreScheduler::NodeStoreScheduler(JobQueue& jobQueue) : jobQueue_(jobQueue)
|
||||
NodeStoreScheduler::NodeStoreScheduler([[maybe_unused]] ServiceRegistry& app, JobQueue& jobQueue)
|
||||
#ifdef XRPL_ENABLE_TELEMETRY
|
||||
: app_(app), jobQueue_(jobQueue)
|
||||
#else
|
||||
: jobQueue_(jobQueue)
|
||||
#endif
|
||||
{
|
||||
}
|
||||
|
||||
@@ -33,14 +47,36 @@ NodeStoreScheduler::onFetch(node_store::FetchReport const& report)
|
||||
if (jobQueue_.isStopped())
|
||||
return;
|
||||
|
||||
auto const isAsync = report.fetchType == node_store::FetchType::Async;
|
||||
|
||||
// The report is in microseconds but addLoadEvents takes milliseconds, so
|
||||
// cast explicitly. The load monitor only tracks whole-millisecond load,
|
||||
// so the sub-millisecond detail is deliberately dropped here; telemetry
|
||||
// reads the microsecond value from the nodestore instead.
|
||||
// so the sub-millisecond detail is deliberately dropped here; the
|
||||
// histogram below keeps it.
|
||||
jobQueue_.addLoadEvents(
|
||||
report.fetchType == node_store::FetchType::Async ? JtNsAsyncRead : JtNsSyncRead,
|
||||
isAsync ? JtNsAsyncRead : JtNsSyncRead,
|
||||
1,
|
||||
std::chrono::duration_cast<std::chrono::milliseconds>(report.elapsed));
|
||||
|
||||
// Skip a negative elapsed time rather than hand it to the SDK, which
|
||||
// rejects it and logs a warning on every single call. The clock is
|
||||
// monotonic, so this needs a clock bug to happen -- but a per-fetch log
|
||||
// flood would be worse than the missing sample.
|
||||
if (!telemetry::shouldRecordFetchLatency(report.elapsed.count()))
|
||||
return;
|
||||
|
||||
// Two labels, both already on the report. fetch_type because a slow async
|
||||
// read only delays prefetch while a slow sync read blocks a caller;
|
||||
// found because a miss can cost a read of every backend, so mixing the
|
||||
// two blurs the distribution.
|
||||
XRPL_METRIC_HISTOGRAM_RECORD_LABELED(
|
||||
app_,
|
||||
telemetry::kNodeStoreReadUs,
|
||||
telemetry::kNodeStoreReadUsDesc,
|
||||
report.elapsed.count(),
|
||||
{{telemetry::kFetchTypeLabel, std::string(telemetry::fetchTypeLabelValue(isAsync))},
|
||||
{telemetry::kFetchFoundLabel,
|
||||
std::string(telemetry::fetchFoundLabelValue(report.wasFound))}});
|
||||
}
|
||||
|
||||
void
|
||||
|
||||
@@ -6,13 +6,57 @@
|
||||
|
||||
namespace xrpl {
|
||||
|
||||
// Forward-declared rather than included: only a reference is stored, and
|
||||
// ServiceRegistry.h pulls in <boost/asio.hpp>, which every file including this
|
||||
// header would then pay for. The .cpp includes the full definition.
|
||||
class ServiceRegistry;
|
||||
|
||||
/**
|
||||
* A node_store::Scheduler which uses the JobQueue.
|
||||
*
|
||||
* Two responsibilities, both delegating outward: it turns backend write
|
||||
* requests into JobQueue jobs, and it forwards completion reports to the
|
||||
* load monitor and to the OTel metrics pipeline.
|
||||
*
|
||||
* Collaborator diagram (ASCII):
|
||||
*
|
||||
* node_store::Database / Backend
|
||||
* |
|
||||
* | scheduleTask / onFetch / onBatchWrite
|
||||
* v
|
||||
* +---------------------+
|
||||
* | NodeStoreScheduler |
|
||||
* +---------------------+
|
||||
* | |
|
||||
* v v
|
||||
* JobQueue ServiceRegistry
|
||||
* (jobs + (-> MetricsRegistry,
|
||||
* load events) read-latency histogram)
|
||||
*
|
||||
* @note Thread safety: onFetch() and onBatchWrite() are called from backend
|
||||
* read/write threads, concurrently. Both members are references to
|
||||
* objects that outlive this one, and every call they make
|
||||
* (JobQueue::addLoadEvents, OTel Histogram::Record) is itself
|
||||
* thread-safe, so no locking is needed here.
|
||||
* @note Lifetime: constructed early, in the Application member initializer
|
||||
* list, which is BEFORE the MetricsRegistry exists. It therefore stores
|
||||
* the ServiceRegistry and resolves the registry per call; the metric
|
||||
* macros null-check it, so fetches completing before the registry is
|
||||
* created are simply not recorded.
|
||||
*/
|
||||
class NodeStoreScheduler : public node_store::Scheduler
|
||||
{
|
||||
public:
|
||||
explicit NodeStoreScheduler(JobQueue& jobQueue);
|
||||
/**
|
||||
* Construct a scheduler.
|
||||
*
|
||||
* @param app Service registry, used only to reach the
|
||||
* MetricsRegistry when reporting read latency. Must
|
||||
* outlive this object.
|
||||
* @param jobQueue Queue that runs scheduled write tasks and receives
|
||||
* load events. Must outlive this object.
|
||||
*/
|
||||
NodeStoreScheduler(ServiceRegistry& app, JobQueue& jobQueue);
|
||||
|
||||
void
|
||||
scheduleTask(node_store::Task& task) override;
|
||||
@@ -22,6 +66,21 @@ public:
|
||||
onBatchWrite(node_store::BatchWriteReport const& report) override;
|
||||
|
||||
private:
|
||||
#ifdef XRPL_ENABLE_TELEMETRY
|
||||
/**
|
||||
* Service registry, resolved to a MetricsRegistry on each onFetch().
|
||||
*
|
||||
* Only needed when OTel is compiled in, since the record site is the
|
||||
* only reader. Held under the guard for the same reason
|
||||
* MetricsRegistry::app_ is: without OTel it would be an unused private
|
||||
* field, which -Wall rejects.
|
||||
*/
|
||||
ServiceRegistry& app_;
|
||||
#endif // XRPL_ENABLE_TELEMETRY
|
||||
|
||||
/**
|
||||
* Queue used for scheduled tasks and load-event reporting.
|
||||
*/
|
||||
JobQueue& jobQueue_;
|
||||
};
|
||||
|
||||
|
||||
@@ -46,6 +46,7 @@
|
||||
#include <xrpl/server/LoadFeeTrack.h>
|
||||
#include <xrpl/server/NetworkOPs.h>
|
||||
#include <xrpl/telemetry/GetObjectMetricNames.h>
|
||||
#include <xrpl/telemetry/NodeStoreMetricNames.h>
|
||||
|
||||
#include <opentelemetry/context/context.h>
|
||||
#include <opentelemetry/exporters/otlp/otlp_http_metric_exporter_factory.h>
|
||||
@@ -135,11 +136,10 @@ constexpr std::array kMicrosecondBoundaries{
|
||||
* range instead, while still reaching far enough to show a cold tail against
|
||||
* it.
|
||||
*
|
||||
* Currently unused: no sub-millisecond histogram instrument exists yet. The
|
||||
* edges live here so the instrument that records nodestore read latency gets
|
||||
* a ladder that fits it, rather than silently inheriting the wrong one.
|
||||
* Used by the kNodeStoreReadUs view registered in
|
||||
* initExporterAndProvider().
|
||||
*/
|
||||
[[maybe_unused]] constexpr std::array kSubMillisecondBoundaries{
|
||||
constexpr std::array kSubMillisecondBoundaries{
|
||||
1.0,
|
||||
2.0,
|
||||
5.0,
|
||||
@@ -196,6 +196,23 @@ addMicrosecondHistogramView(metric_sdk::ViewRegistry& views, std::string const&
|
||||
addHistogramView(views, name, {kMicrosecondBoundaries.begin(), kMicrosecondBoundaries.end()});
|
||||
}
|
||||
|
||||
/**
|
||||
* Register the sub-millisecond-ladder view for a duration instrument.
|
||||
*
|
||||
* For latencies that normally sit below one millisecond, where the
|
||||
* microsecond ladder's 100 µs first edge would swallow the whole healthy
|
||||
* range. See kSubMillisecondBoundaries.
|
||||
*
|
||||
* @param views The registry to add the view to.
|
||||
* @param name Instrument name to match.
|
||||
*/
|
||||
void
|
||||
addSubMillisecondHistogramView(metric_sdk::ViewRegistry& views, std::string const& name)
|
||||
{
|
||||
addHistogramView(
|
||||
views, name, {kSubMillisecondBoundaries.begin(), kSubMillisecondBoundaries.end()});
|
||||
}
|
||||
|
||||
} // namespace
|
||||
|
||||
#endif // XRPL_ENABLE_TELEMETRY
|
||||
@@ -280,6 +297,13 @@ MetricsRegistry::initExporterAndProvider(std::string const& endpoint, std::strin
|
||||
// comes from the shared constant both sites use.
|
||||
addMicrosecondHistogramView(*views, kGetObjectLookupUs);
|
||||
|
||||
// Per-fetch nodestore read latency. Recorded at its NodeStoreScheduler.cpp
|
||||
// call site, so again the name comes from the shared constant. This one
|
||||
// gets the sub-millisecond ladder, not the microsecond one: a warm read
|
||||
// answers in single-digit microseconds, which is below the microsecond
|
||||
// ladder's first edge.
|
||||
addSubMillisecondHistogramView(*views, kNodeStoreReadUs);
|
||||
|
||||
// The remaining two GetObject histograms are not durations, so the
|
||||
// microsecond ladder above does not fit them. Both still need explicit
|
||||
// boundaries: the SDK default stops at 10,000 and both ranges exceed it.
|
||||
|
||||
Reference in New Issue
Block a user