diff --git a/.cspell.config.yaml b/.cspell.config.yaml index c1ad0ae2f8..d43bcdf98b 100644 --- a/.cspell.config.yaml +++ b/.cspell.config.yaml @@ -145,6 +145,7 @@ words: - hwrap - ifndef - inequation + - initialiser - insuf - insuff - invasively @@ -284,6 +285,11 @@ words: - rustfmt - rustup - sahyadri + - sanitisation + - sanitise + - sanitised + - sanitiser + - sanitising - Satoshi - scons - Schnorr @@ -303,6 +309,7 @@ words: - sles - soci - socidb + - speciality - sponsee - sponsees - SRPMS @@ -362,6 +369,7 @@ words: - unsquelch - unsquelched - unsquelching + - unstored - unvalidated - unveto - unvetoed @@ -372,6 +380,7 @@ words: - vfalco - vinnie - wasmi + - werror - wextra - wptr - writeme diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 7c292a94e4..5ad7af800e 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -50,6 +50,7 @@ graph LR style A fill:#4a90d9,color:#fff,stroke:#2a6db5 style B fill:#4a90d9,color:#fff,stroke:#2a6db5 + style C fill:#4a90d9,color:#fff,stroke:#2a6db5 style R1 fill:#5cb85c,color:#fff,stroke:#3d8b3d style BP fill:#449d44,color:#fff,stroke:#2d6e2d style SM fill:#449d44,color:#fff,stroke:#2d6e2d @@ -63,10 +64,11 @@ graph LR style viz fill:#1a2d33,color:#ccc,stroke:#5bc0de ``` -There are two independent telemetry pipelines entering a single **OTel Collector** via the same OTLP receiver: +There are three independent telemetry pipelines entering a single **OTel Collector** via the same OTLP receiver — nodes **A**, **B**, and **C** in the diagram above: -1. **OpenTelemetry Traces** — Distributed spans with attributes, exported via OTLP/HTTP (:4318) to the collector's **OTLP Receiver**. The **Batch Processor** groups spans (1s timeout, batch size 100) before forwarding to trace backends. The **SpanMetrics Connector** derives RED metrics (rate, errors, duration) from every span and feeds them into the metrics pipeline. -2. **beast::insight OTel Metrics** — System-level gauges, counters, and histograms exported natively via OTLP/HTTP (:4318) to the same **OTLP Receiver**. These are batched and exported to Prometheus alongside span-derived metrics. The StatsD UDP transport has been replaced by native OTLP; `server=statsd` remains available as a fallback. +1. **OpenTelemetry Traces** (**A**) — Distributed spans with attributes, exported via OTLP/HTTP (:4318) to the collector's **OTLP Receiver**. The **Batch Processor** groups spans (1s timeout, batch size 100) before forwarding to trace backends. The **SpanMetrics Connector** derives RED metrics (rate, errors, duration) from every span and feeds them into the metrics pipeline. +2. **beast::insight OTel Metrics** (**B**) — System-level gauges, counters, and histograms exported natively via OTLP/HTTP (:4318) to the same **OTLP Receiver**. These are batched and exported to Prometheus alongside span-derived metrics. The StatsD UDP transport has been replaced by native OTLP; `server=statsd` remains available as a fallback. +3. **MetricsRegistry OTel SDK Metrics** (**C**) — Counters, histograms, and observable gauges registered directly with the OTel Metrics SDK, exported via OTLP/HTTP (:4318). This pipeline owns its own `MeterProvider` and reader, separate from **B**'s, so its export cadence is independent — see [§2.5](#25-per-job-type-queue-gauges) for why that matters when comparing the two. **Trace backend** — The collector exports traces via OTLP/gRPC to: @@ -629,6 +631,73 @@ For each of the 45+ overlay traffic categories (defined in `TrafficCount.h`), fo **Grafana dashboards**: _Network Traffic_ (`network-traffic`), _Overlay Traffic Detail_ (`overlay-traffic-detail`), _Ledger Data & Sync_ (`ledger-data-sync`) +### 2.5 Per-Job-Type Queue Gauges + +Three gauge families give per-job-type queue pressure. Before them the only +exported queue signal was the process-wide `jobq_job_count` +([§2.1](#21-gauges)), which cannot attribute pressure to a job type. + +| Prometheus Metric | Description | +| ------------------------- | --------------------------------------------------- | +| `jobq__waiting` | Backlog for this type: enqueued but not yet started | +| `jobq__running` | Currently executing for this type | +| `jobq__deferred` | Held back by this type's concurrency limit | + +The gauge members live on `JobTypeData` (`include/xrpl/core/JobTypeData.h`) and +are published by `JobQueue::collect()` +(`src/libxrpl/core/detail/JobQueue.cpp`), which reads the same +`waiting`/`running`/`deferred` counters under the mutex that guards them. Values +are clamped at zero before publication, because the gauge value type is unsigned +and an unclamped negative would wrap to ~1.8e19 and swamp every panel reading +the family. + +**Name derivation.** The collector is the `"jobq"` group +(`src/xrpld/app/main/Application.cpp`), so `GroupImp::makeName()` +(`src/libxrpl/beast/insight/Groups.cpp`) joins with a `.`, then +`OTelCollectorImp::formatName()` +(`src/libxrpl/beast/insight/OTelCollector.cpp`) lowercases and maps `.` to +`_`. The exported +name for `JtLedgerReq`, whose `JobTypeInfo` name is `ledgerRequest`, is +therefore `jobq_ledgerrequest_deferred` — bare and lowercase, with no `xrpld` +prefix. The same chain produces `jobq_job_count` from the gauge registered as +`job_count`. + +**Coverage.** Emitted for the **35** job types that are not special. `JobTypes` +defines 46 entries plus the `invalid` sentinel +(`include/xrpl/core/JobTypes.h`); `JobTypeInfo::special()` is `limit_ == 0`, and +11 of the 46 have `limit == 0`, so `JobTypeData`'s constructor creates gauges for +the remaining 35. A special type's gauge stays default-constructed, and a +default `beast::insight::Gauge` holds a null impl whose mutators are no-ops, so +assigning to it publishes nothing. + +**Why `deferred` is the metric to alert on.** `JobQueue::addJob()` never +rejects — it defers. A capped type under pressure therefore surfaces as latency +only after the fact, whereas a non-zero `deferred` reading precedes it. The +types where this bites are the ones with a low concurrency limit +(`JobTypes.h`): `JtPack` = 1 and `JtUpdatePf` = 1, `JtLedgerReq` = 3 and +`JtLedgerData` = 3, `JtTxnData` = 5. + +> **Sampling caveat.** These are sampled, not integrated. The values are read +> when the SDK's periodic reader invokes the observable callbacks, which run the +> collector hooks; the export interval is 1000 ms +> (`export_interval_millis` in `src/libxrpl/telemetry/Telemetry.cpp:441`) and +> hook invocation is debounced to at most once per 500 ms. A spike shorter than +> the interval can be missed entirely, so read these as pressure indicators +> rather than as exact peak depths. + +**Pipeline note.** Unlike the Phase 9 `job_*` counters and histograms, this +family flows through `beast::insight` → `OTelCollector`, **not** the +`XRPL_METRIC_*` macros. `JobQueue.cpp` is in `libxrpl` and those macros are +`xrpld`-only. The two are distinct pipelines — arrows **B** and **C** in the +[Data Flow Overview](#data-flow-overview) — each with its own `MeterProvider`, +reader, and OTLP/HTTP exporter, even though both request a meter named +`xrpld` / `1.0.0`. `OTelCollector` takes its meter from the **global** provider, +which `Telemetry` publishes and reads every 1000 ms; `MetricsRegistry` builds a +private provider it does not publish, read every 10000 ms +(`src/xrpld/telemetry/MetricsRegistry.cpp`). So `jobq__*` and +`job_*_total` reach Prometheus on different cadences and should not be assumed +sampled at the same instant. + --- ## 3. Grafana Dashboard Reference @@ -915,6 +984,21 @@ async callbacks for new categories. | `nodestore_state{metric="read_threads_running"}` | Gauge | `metric` | Active read threads | | `nodestore_state{metric="read_threads_total"}` | Gauge | `metric` | Total read threads configured | +#### Job Queue and GetObject Additions + +Three further additions are catalogued with the families they extend rather than +repeated here: + +- A `handler` label on the five `job_*` instruments, so producers sharing one + job type stay individually attributable — see + [Per-Job-Type Metrics](#per-job-type-metrics-synchronous-countershistogram). +- Five `getobject_*` instruments covering the `TMGetObjectByHash` request path — + see [GetObject Request Path](#getobject-request-path-synchronous-countershistograms). +- Three per-job-type queue gauge families (`jobq__waiting` / + `_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). + ### New Grafana Dashboards (Phase 9) | Dashboard | UID | Data Source | Key Panels | @@ -942,15 +1026,28 @@ Phase 10 builds a 5-node validator docker-compose harness with RPC load generato > below as **families currently emitting** (idle nodes under-report — workload-gated metrics such as > per-RPC/error counters appear only once exercised, which is Phase 10's purpose). -| Category | Expected Count | Validation Method | -| ---------------------- | ------------------- | -------------------------------- | -| Trace spans | 16 | Jaeger/Tempo API query | -| Span attributes | 22 | Per-span attribute assertion | -| Legacy `*` families | ~270 (≈224 traffic) | Prometheus `__name__` query | -| Native MetricsRegistry | 35 instruments | Prometheus query | -| SpanMetrics RED | 4 per span | Prometheus query | -| Grafana dashboards | 10 | Dashboard API "no data" check | -| Log-trace links | Present | Loki query + Tempo reverse check | +| Category | Expected Count | Validation Method | +| ------------------------- | ------------------- | -------------------------------- | +| Trace spans | 16 | Jaeger/Tempo API query | +| Span attributes | 22 | Per-span attribute assertion | +| Legacy `*` families | ~270 (≈224 traffic) | Prometheus `__name__` query | +| Native MetricsRegistry | 35 instruments | Prometheus query | +| Call-site `XRPL_METRIC_*` | 7 instruments | Prometheus query | +| Per-job-type gauges | 105 (35 types × 3) | Prometheus `__name__` query | +| SpanMetrics RED | 4 per span | Prometheus query | +| Grafana dashboards | 10 | Dashboard API "no data" check | +| Log-trace links | Present | Loki query + Tempo reverse check | + +The two added rows are the families that do not originate as `MetricsRegistry` +members. **Call-site** instruments are declared by the `XRPL_METRIC_*` macros +(7 distinct names: `rpc_in_flight_requests`, `ledgers_closed_total`, and the +five `getobject_*`). Two of those seven are workload-gated in a way that makes a +zero reading uninformative: `getobject_rejected_total` needs a non-conforming +request, and the `getobject_*` family as a whole needs an inbound +`TMGetObjectByHash`. **Per-job-type gauges** are the `beast::insight` families +from [§2.5](#25-per-job-type-queue-gauges); all 105 should be present on any +running node, but `_deferred` reads zero unless a capped type is actually +saturated. --- @@ -1081,13 +1178,124 @@ reserved for monotonic counters). #### Per-Job-Type Metrics (Synchronous Counters/Histogram) -| Prometheus Metric | Type | Labels | Description | -| -------------------- | --------- | ------------------- | --------------------------------- | -| `job_queued_total` | Counter | `job_type=""` | Jobs enqueued | -| `job_started_total` | Counter | `job_type=""` | Jobs started | -| `job_finished_total` | Counter | `job_type=""` | Jobs completed | -| `job_queued_us` | Histogram | `job_type=""` | Queue wait time distribution (us) | -| `job_running_us` | Histogram | `job_type=""` | Execution time distribution (us) | +| Prometheus Metric | Type | Labels | Description | +| -------------------- | --------- | --------------------------------------- | --------------------------------- | +| `job_queued_total` | Counter | `job_type=""`, `handler=""` | Jobs enqueued | +| `job_started_total` | Counter | `job_type=""`, `handler=""` | Jobs started | +| `job_finished_total` | Counter | `job_type=""`, `handler=""` | Jobs completed | +| `job_queued_us` | Histogram | `job_type=""`, `handler=""` | Queue wait time distribution (us) | +| `job_running_us` | Histogram | `job_type=""`, `handler=""` | Execution time distribution (us) | + +All five are recorded from `PerfLogImp` (`jobQueue()`, `jobStart()`, +`jobFinish()`) through `MetricsRegistry::recordJobQueued/Started/Finished`. +A counter and its paired histogram always carry the identical label set, so +the two can be joined in a query. + +**The `handler` label.** `job_type` alone cannot attribute load to a producer, +because several producers share one job type: `RcvGetLedger` and +`RcvGetObjByHash` both run as `JtLedgerReq`, and before this label they were +indistinguishable. `handler` is the `addJob` name, so each producer gets its +own series. + +The name is not used raw. `MetricsRegistry::sanitiseHandler()` keeps it only +when it is non-empty **and** every character is an ASCII letter; anything else +becomes the constant `MetricsRegistry::kHandlerOther`, `"other"`. The rule +exists because two job names embed a ledger sequence — `"Pub" + seq` in +`LedgerPersistence.cpp` and `"OB" + seq` in `OrderBookDBImpl.cpp` — which raw +would mint a fresh series per ledger. Both always contain digits, so both +always fold to `other` by construction. The label domain is therefore a +function of the string literals in the source and cannot grow at runtime; +a name added later that fails the rule degrades to `other` rather than +becoming unbounded. + +Current cardinality: **44 values** — 43 names pass through unchanged, plus +`other`. Five production names fail the letters-only rule and fold into +`other`: + +| Job Name | Job Type | Why it folds | +| ------------- | ------------------- | ------------ | +| `GetConsL1` | `JtAdvance` | digits | +| `GetConsL2` | `JtAdvance` | digits | +| `gRPC-Client` | `JtRpc` | hyphen | +| `RPC-Client` | `JtClientRpc` | hyphen | +| `WS-Client` | `JtClientWebsocket` | hyphen | + +> **`handler="other"` is a mixed bucket, not one producer.** It aggregates the +> five names above plus both dynamic names, so a rate or quantile on it is a +> sum across unrelated work. `GetConsL1` and `GetConsL2` are the sharpest case: +> they are two distinct `JtAdvance` producers that land in the same bucket and +> are mutually inseparable. Filter by `job_type` alongside `handler` to narrow +> it, and read `handler="other"` series as an aggregate only. + +#### GetObject Request Path (Synchronous Counters/Histograms) + +Instruments for the `TMGetObjectByHash` peer request path. Names, label keys, +and label values are the `constexpr` constants in +`include/xrpl/telemetry/GetObjectMetricNames.h`. All five are declared at their +call sites in `src/xrpld/overlay/detail/PeerImp.cpp` via the `XRPL_METRIC_*` +macros, not as `MetricsRegistry` members: the two rejection counters in +`onMessage(TMGetObjectByHash)`, the other three in the +`recordGetObjectMetrics()` helper. + +| Prometheus Metric | Type | Labels | Description | +| --------------------------- | --------- | ----------------------------------------------- | ------------------------------------------------------------ | +| `getobject_lookup_us` | Histogram | (none) | Wall time in the NodeStore fetch loop (us), once per request | +| `getobject_request_objects` | Histogram | (none) | Objects requested per message | +| `getobject_lookups_total` | Counter | `result="hit"` \| `"miss"` | NodeStore lookups, added once per request with batch totals | +| `getobject_rejected_total` | Counter | `reason="oversize"` \| `"malformed_ledgerhash"` | Requests refused before any NodeStore access | +| `getobject_charge` | Histogram | (none) | Dynamic component of the differential resource charge | + +**Per request, not per object.** `getobject_lookup_us` times the whole fetch +loop once, and `getobject_lookups_total` adds the batch hit and miss totals in +two calls. Incrementing per object on a loop bounded by +`Tuning::kHardMaxReplyNodes` (12288) would cost measurably and add no +information the batch totals do not already carry. + +**All three histograms need an explicit bucket view.** The SDK's default +histogram boundaries top out at 10000. Every one of these three exceeds that, so +without a view their top quantiles would all read as a flat 10000. Six views are +registered in `src/xrpld/telemetry/MetricsRegistry.cpp`, and three of the six are +for this family: + +| Instrument | View helper | Boundaries | +| --------------------------- | ------------------------------- | ------------------------------------------------------ | +| `getobject_lookup_us` | `addMicrosecondHistogramView()` | The shared µs ladder, 100 µs to 60 s (16 buckets) | +| `getobject_request_objects` | `addHistogramView()`, own set | `1, 2, 4, 8, 16, 64, 256, 1024, 4096, 12288` | +| `getobject_charge` | `addHistogramView()`, own set | `0, 100, 500, 1000, 5000, 10000, 25000, 50000, 100000` | + +The other three views are `addMicrosecondHistogramView()` on `job_queued_us`, +`job_running_us`, and `rpc_method_us` — four µs-ladder views plus these two +custom sets. + +**Why the latter two do not use the µs ladder.** They are not durations. The µs +ladder's buckets are chosen for time (sub-millisecond jobs through multi-second +stalls), so applying it to a count or a charge would place almost every +observation in one or two buckets and make the distribution unreadable. +`addHistogramView()` exists to take caller-supplied boundaries for exactly this +case. + +- **Counts** run 1 to `Tuning::kHardMaxReplyNodes` (12288). The low end is + fine-grained because the honest sync path asks for at most 8 objects, so the + interesting distinction is between a normal request and a large one. The upper + bounds follow the charge size bands — `kBandSmallMax` (64) and + `kBandMediumMax` (1024) — up to the hard cap, so a bucket boundary coincides + with each price change. +- **Charges** run 0 to roughly 99k for a full-size all-miss request. Two of the + boundaries are the resource thresholds that decide a peer's fate: + `Resource::kWarningThreshold` (5000) and `Resource::kDropThreshold` (25000), + both in `include/xrpl/resource/detail/Tuning.h`. Placing bucket edges exactly + there lets a panel read off how close real charges run to a warning or a drop, + rather than interpolating across an edge. + +`getobject_lookup_us` is named by a shared constant rather than a literal because +it is referenced from both the record site and the view registration; a drifted +spelling would silently drop the override. + +> **A zero `getobject_rejected_total` does not prove the counter works.** Both +> gates it counts (`reason="oversize"`, `reason="malformed_ledgerhash"`) fire +> only on non-conforming requests, so on a healthy network the expected reading +> is zero. Validate it with a deliberately malformed request, not by looking for +> a series. #### Counted Object Instances (Observable Gauge — `object_count`) @@ -1127,11 +1335,28 @@ rate(rpc_method_errored_total{method="server_info"}[5m]) # Job queue wait time p95 histogram_quantile(0.95, sum by (le) (rate(job_queued_us_bucket[5m]))) +# Job run time p95 split by producer, for one job type +histogram_quantile(0.95, sum by (le, handler) (rate(job_running_us_bucket{job_type="ledgerRequest"}[5m]))) + # TxQ utilization percentage txq_metrics{metric="txq_count"} / txq_metrics{metric="txq_max_size"} # High load factor alert candidate load_factor_metrics{metric="load_factor"} > 5 + +# Job types currently hitting their concurrency limit (backpressure). +# Scoped to one node: unscoped, this aggregates every node on the stack. +max by (__name__) ({__name__=~"jobq_.*_deferred", service_instance_id="$node"}) > 0 + +# GetObject NodeStore hit ratio +sum(rate(getobject_lookups_total{result="hit"}[5m])) + / sum(rate(getobject_lookups_total[5m])) + +# GetObject fetch-loop p95 (microseconds) +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])) ``` ### Phase 7+: External Dashboard Parity Metrics @@ -1282,12 +1507,13 @@ counters), observed from an existing cumulative source each collection cycle: ## 6. Known Issues -| Issue | Impact | Status | -| ------------------------------------------------------------------ | ------------------------------------------------ | -------------------------------------------------------------------- | -| `warn` and `drop` metrics use non-standard StatsD `\|m` meter type | Metrics silently dropped by OTel StatsD receiver | Phase 6 Task 6.1 — needs `\|m` → `\|c` change in StatsDCollector.cpp | -| `jobq_job_count` may not emit in standalone mode | Missing from Prometheus in some test configs | Requires active job queue activity | -| `rpc_requests` depends on `[insight]` config | Zero series if StatsD not configured | Requires `[insight] server=statsd` in xrpld.cfg | -| Peer tracing enabled by default | `peer.*` spans emit unless `trace_peer=0` | High volume — set `trace_peer=0` to opt out on busy mainnet nodes | +| Issue | Impact | Status | +| ------------------------------------------------------------------ | ------------------------------------------------ | ------------------------------------------------------------------------------------------------------------------- | +| `warn` and `drop` metrics use non-standard StatsD `\|m` meter type | Metrics silently dropped by OTel StatsD receiver | Phase 6 Task 6.1 — needs `\|m` → `\|c` change in StatsDCollector.cpp | +| `jobq_job_count` may not emit in standalone mode | Missing from Prometheus in some test configs | Requires active job queue activity | +| `rpc_requests` depends on `[insight]` config | Zero series if StatsD not configured | Requires `[insight] server=statsd` in xrpld.cfg | +| Peer tracing enabled by default | `peer.*` spans emit unless `trace_peer=0` | High volume — set `trace_peer=0` to opt out on busy mainnet nodes | +| `handler="other"` mixes several producers | Cannot separate `GetConsL1` from `GetConsL2` | By design — the cardinality bound; see [§Per-Job-Type Metrics](#per-job-type-metrics-synchronous-countershistogram) | --- diff --git a/docker/telemetry/grafana/dashboards/job-queue.json b/docker/telemetry/grafana/dashboards/job-queue.json index e72f8496f8..2ffbf8e0b1 100644 --- a/docker/telemetry/grafana/dashboards/job-queue.json +++ b/docker/telemetry/grafana/dashboards/job-queue.json @@ -34,19 +34,19 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(histogram_quantile(0.99, sum by (le, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{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\", job_type=~\"$job_type\"}[5m]))), \"series\", \"p99 Wait\", \"\", \"\")" + "expr": "label_replace(histogram_quantile(0.99, sum by (le, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[5m]))), \"series\", \"p99 Wait\", \"\", \"\")" }, { "datasource": { "type": "prometheus" }, - "expr": "label_replace(histogram_quantile(0.99, sum by (le, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\"}[5m]))), \"series\", \"p99 Exec\", \"\", \"\")" + "expr": "label_replace(histogram_quantile(0.99, sum by (le, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[5m]))), \"series\", \"p99 Exec\", \"\", \"\")" } ], "fieldConfig": { "defaults": { "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", - "unit": "\u00b5s", + "unit": "µs", "min": 0, "thresholds": { "mode": "absolute", @@ -92,19 +92,19 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_total{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\", job_type=~\"$job_type\"}[$__rate_interval])), \"series\", \"Queued/s\", \"\", \"\")" + "expr": "label_replace(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_total{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[$__rate_interval])), \"series\", \"Queued/s\", \"\", \"\")" }, { "datasource": { "type": "prometheus" }, - "expr": "label_replace(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_started_total{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\", job_type=~\"$job_type\"}[$__rate_interval])), \"series\", \"Started/s\", \"\", \"\")" + "expr": "label_replace(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_started_total{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[$__rate_interval])), \"series\", \"Started/s\", \"\", \"\")" }, { "datasource": { "type": "prometheus" }, - "expr": "label_replace(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_finished_total{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\", job_type=~\"$job_type\"}[$__rate_interval])), \"series\", \"Finished/s\", \"\", \"\")" + "expr": "label_replace(sum by (service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_finished_total{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[$__rate_interval])), \"series\", \"Finished/s\", \"\", \"\")" } ], "fieldConfig": { @@ -156,7 +156,7 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(topk(10, rate(job_queued_total{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\", job_type=~\"$job_type\"}[$__rate_interval])), \"series\", \"$1\", \"job_type\", \"(.*)\")" + "expr": "label_replace(topk(10, sum by (job_type, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_total{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[$__rate_interval]))), \"series\", \"$1\", \"job_type\", \"(.*)\")" } ], "fieldConfig": { @@ -208,7 +208,7 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(topk(10, rate(job_finished_total{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\", job_type=~\"$job_type\"}[$__rate_interval])), \"series\", \"$1\", \"job_type\", \"(.*)\")" + "expr": "label_replace(topk(10, sum by (job_type, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_finished_total{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[$__rate_interval]))), \"series\", \"$1\", \"job_type\", \"(.*)\")" } ], "fieldConfig": { @@ -255,24 +255,24 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(histogram_quantile(0.75, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{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\", job_type=~\"$job_type\"}[5m]))), \"series\", \"p75 Wait\", \"\", \"\")" + "expr": "label_replace(histogram_quantile(0.75, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[5m]))), \"series\", \"p75 Wait\", \"\", \"\")" }, { "datasource": { "type": "prometheus" }, - "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{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\", job_type=~\"$job_type\"}[5m]))), \"series\", \"p99 Wait\", \"\", \"\")" + "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[5m]))), \"series\", \"p99 Wait\", \"\", \"\")" } ], "fieldConfig": { "defaults": { "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", - "unit": "\u00b5s", + "unit": "µs", "custom": { "drawStyle": "line", "lineWidth": 2, "fillOpacity": 5, - "axisLabel": "Duration (\u03bcs)", + "axisLabel": "Duration (μs)", "spanNulls": 1800000, "insertNulls": false, "showPoints": "auto", @@ -308,24 +308,24 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(histogram_quantile(0.75, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\"}[5m]))), \"series\", \"p75 Exec\", \"\", \"\")" + "expr": "label_replace(histogram_quantile(0.75, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[5m]))), \"series\", \"p75 Exec\", \"\", \"\")" }, { "datasource": { "type": "prometheus" }, - "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\"}[5m]))), \"series\", \"p99 Exec\", \"\", \"\")" + "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[5m]))), \"series\", \"p99 Exec\", \"\", \"\")" } ], "fieldConfig": { "defaults": { "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", - "unit": "\u00b5s", + "unit": "µs", "custom": { "drawStyle": "line", "lineWidth": 2, "fillOpacity": 5, - "axisLabel": "Duration (\u03bcs)", + "axisLabel": "Duration (μs)", "spanNulls": 1800000, "insertNulls": false, "showPoints": "auto", @@ -366,18 +366,18 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(topk(10, histogram_quantile(0.99, sum by (le, job_type, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\"}[5m])))), \"series\", \"$1\", \"job_type\", \"(.*)\")" + "expr": "label_replace(topk(10, histogram_quantile(0.99, sum by (le, job_type, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{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\", job_type=~\"$job_type\", handler=~\"$handler\"}[5m])))), \"series\", \"$1\", \"job_type\", \"(.*)\")" } ], "fieldConfig": { "defaults": { "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", - "unit": "\u00b5s", + "unit": "µs", "custom": { "drawStyle": "line", "lineWidth": 1, "fillOpacity": 5, - "axisLabel": "Duration (\u03bcs)", + "axisLabel": "Duration (μs)", "spanNulls": 1800000, "insertNulls": false, "showPoints": "auto", @@ -393,7 +393,7 @@ }, { "title": "Transaction Overflow Rate", - "description": "###### What this is:\n*Rate at which transaction jobs are shed when the queue's transaction limit is exceeded.*\n\n###### How it's computed:\n*Per-second rate of the overflow counter over the dashboard's rate interval, scaled to per minute. The counter is observed from the overlay's cumulative overflow tally.*\n\n###### Reading it:\n*Near zero is healthy; a rising rate means the job queue is shedding transaction work under load.*\n\n###### Healthy range:\n*0 overflows per minute.*\n\n###### Watch for:\n*Any sustained non-zero rate \u2014 the node is dropping transaction jobs because the queue is saturated.*\n\n###### Source:\n[MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`registerParityCounters (observed from Overlay::getJqTransOverflow)`", + "description": "###### What this is:\n*Rate at which transaction jobs are shed when the queue's transaction limit is exceeded.*\n\n###### How it's computed:\n*Per-second rate of the overflow counter over the dashboard's rate interval, scaled to per minute. The counter is observed from the overlay's cumulative overflow tally.*\n\n###### Reading it:\n*Near zero is healthy; a rising rate means the job queue is shedding transaction work under load.*\n\n###### Healthy range:\n*0 overflows per minute.*\n\n###### Watch for:\n*Any sustained non-zero rate — the node is dropping transaction jobs because the queue is saturated.*\n\n###### Source:\n[MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`registerParityCounters (observed from Overlay::getJqTransOverflow)`", "type": "timeseries", "gridPos": { "h": 8, @@ -618,6 +618,26 @@ "multi": true, "refresh": 2, "sort": 1 + }, + { + "name": "handler", + "label": "Handler", + "description": "Filter by enqueueing handler (sanitised addJob name, e.g. RcvGetLedger)", + "type": "query", + "query": "label_values(job_queued_total, handler)", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "includeAll": true, + "allValue": ".*", + "current": { + "text": "All", + "value": "$__all" + }, + "multi": true, + "refresh": 2, + "sort": 1 } ] }, diff --git a/docker/telemetry/grafana/dashboards/ledger-data-sync.json b/docker/telemetry/grafana/dashboards/ledger-data-sync.json index 2909d877cd..dca49c7afc 100644 --- a/docker/telemetry/grafana/dashboards/ledger-data-sync.json +++ b/docker/telemetry/grafana/dashboards/ledger-data-sync.json @@ -1356,6 +1356,115 @@ "overrides": [] }, "id": 26 + }, + { + "title": "Job Queue Saturation", + "type": "row", + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 115 + }, + "collapsed": false, + "panels": [], + "id": 27 + }, + { + "title": "Job Queue Backlog and Deferred by Type", + "description": "###### What this is:\n*Per-job-type queue depth, two series per type. Waiting is the whole backlog: every job enqueued for that type that has not started yet. Deferred is the subset of that backlog that is blocked specifically because the type is already running at its concurrency limit. Deferred is the leading indicator of backpressure, because JobQueue::addJob never rejects a job -- it always returns success and defers instead, so a capped type under pressure produces no error and no dropped work. Without these the only evidence is latency, which appears after the harm is already done.*\n\n###### How it's computed:\n*Two targets, each the top 10 gauges by current value: jobq__waiting and jobq__deferred. Both are live depths published by JobQueue::collect() under the same mutex that guards the counters, so the pair is always read at the same instant and is directly comparable. Gauges exist only for non-special job types, so the 11 special types -- the ones declared with a limit of 0, which bypass the limit logic entirely and therefore never defer -- do not appear on either series.*\n\n###### Reading it:\n*Read the two together; the ratio is the diagnostic, not either value alone. Deferred is always a subset of waiting, because addRefCountedJob increments waiting for every job and deferred only for the ones that arrive while the type is at its limit. Waiting high with deferred at zero means the type has spare slots and the backlog is just arrival burstiness -- it will drain without intervention. Waiting high with deferred also high means the concurrency limit is the binding constraint, not the work. Both near zero is the normal state. These are depths, not rates: the value is how many jobs are queued right now. finishJob drains deferred one per completion, so a deferred line that stays elevated means arrivals are outpacing completions rather than one isolated burst. Only the 10 highest series per state are drawn, which on an idle node is arbitrary among the zeros and under load is exactly the types under pressure.*\n\n###### Healthy range:\n*Deferred zero on all types. Waiting near zero, with brief spikes during ledger close.*\n\n###### Watch for:\n*ledgerrequest deferred above zero: the 3-slot ledgerRequest queue is full, so TMGetLedger service to syncing peers is being delayed. Use LedgerReq Wait by Handler next to see which of its two producers is responsible. ledgerdata or fetchtxndata deferred: inbound ledger data cannot be absorbed fast enough, which is what makes validated ledger age grow. A waiting line that climbs steadily while deferred stays flat points at the worker pool or at slow jobs rather than at the limit. Note both are sampled by the collector hook once per interval, so a sub-second spike can be missed; a reading of zero is not proof that nothing was ever queued or deferred.*\n\n###### Source:\n[core/JobQueue.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/core/detail/JobQueue.cpp)\n\n###### Function:\n`JobQueue::addRefCountedJob / JobQueue::collect`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 12, + "x": 0, + "y": 116 + }, + "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(topk(10, {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\", __name__=~\"jobq_.*_deferred\"}), \"series\", \"$1 Deferred\", \"__name__\", \"jobq_(.*)_deferred\"), \"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(topk(10, {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\", __name__=~\"jobq_.*_waiting\"}), \"series\", \"$1 Waiting\", \"__name__\", \"jobq_(.*)_waiting\"), \"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": "Queued Jobs (Waiting / Deferred)", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3 + } + }, + "overrides": [] + }, + "id": 28 + }, + { + "title": "LedgerReq Wait by Handler", + "description": "###### What this is:\n*Queue wait for the ledgerRequest job type, split by which handler enqueued the job. The type has a concurrency limit of 3 and two producers that compete for those slots: RcvGetLedger, which serves TMGetLedger to syncing peers, and RcvGetObjByHash, which serves TMGetObjectByHash. Both report the same job_type, so without the handler split a wait spike cannot be attributed to either.*\n\n###### How it's computed:\n*p99 of job_queued_us for job_type=\"ledgerRequest\", grouped by the handler label. The handler value is the addJob name passed through a sanitiser that keeps letters-only names and folds anything else to \"other\", which bounds the label domain.*\n\n###### Reading it:\n*This is the panel that answers which producer is starving the 3-slot queue. Both lines high together means the queue is genuinely oversubscribed and both kinds of peer request are being delayed. One line high while the other is flat means that producer is arriving faster than 3 concurrent slots can absorb, and it is the one delaying the other. Wait is queue time only, so a high line here is contention, not slow work; the work itself is on the GetObject Handler Latency Breakdown panel.*\n\n###### Healthy range:\n*Single-digit to low-tens of milliseconds p99 for both handlers, matching the wider Job Queue Wait p95 By Type panel.*\n\n###### Watch for:\n*RcvGetObjByHash wait climbing: one in-bounds TMGetObjectByHash request can perform thousands of NodeStore lookups, so a few concurrent ones occupy every slot and delay TMGetLedger to peers that are themselves syncing. Cross-check Job Queue Backlog and Deferred by Type for jobq_ledgerrequest_deferred above zero to confirm the limit, not the work, is the binding constraint.*\n\n###### Source:\n[core/JobQueue.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/core/detail/JobQueue.cpp)\n\n###### Function:\n`JobQueue::processTask -> PerfLog::jobStart`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 12, + "x": 12, + "y": 116 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.99, sum by (le, handler, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{job_type=\"ledgerRequest\", handler=~\"$handler\", 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]))), \"series\", \"$1 q-wait p99\", \"handler\", \"(.*)\"), \"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": "p99 Wait (\u03bcs)", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3 + } + }, + "overrides": [] + }, + "id": 29 } ], "schemaVersion": 39, @@ -1501,6 +1610,26 @@ "multi": true, "refresh": 2, "sort": 1 + }, + { + "name": "handler", + "label": "Handler", + "description": "Filter by enqueueing handler (sanitised addJob name, e.g. RcvGetLedger)", + "type": "query", + "query": "label_values(job_queued_total, handler)", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "includeAll": true, + "allValue": ".*", + "current": { + "text": "All", + "value": "$__all" + }, + "multi": true, + "refresh": 2, + "sort": 1 } ] }, diff --git a/docker/telemetry/grafana/dashboards/node-health.json b/docker/telemetry/grafana/dashboards/node-health.json index d36a9e779f..2564a7195d 100644 --- a/docker/telemetry/grafana/dashboards/node-health.json +++ b/docker/telemetry/grafana/dashboards/node-health.json @@ -2511,6 +2511,111 @@ }, "overrides": [] } + }, + { + "title": "Job Queue Concurrency Limits", + "type": "row", + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 146 + }, + "collapsed": false, + "panels": [] + }, + { + "title": "Job Queue Saturation (Running vs Limit)", + "description": "###### What this is:\n*How close each concurrency-capped job type is to its ceiling. JobQueue enforces a per-type limit on how many jobs of that type may run at once, and the tight ones carry ledger-sync traffic: makeFetchPack 1, ledgerRequest 3, ledgerData 3, updatePaths 1, fetchTxnData 5. A type at its ceiling cannot start more work no matter how many workers are idle, so this is a different kind of limit from CPU or disk.*\n\n###### How it's computed:\n*Each jobq__running gauge divided by that type's own limit from JobTypes.h, so every line shares one 0-to-1 axis. 1.0 means running equals the limit. Multiply a reading by the limit shown in its legend to recover the raw job count. The gauges are published by JobQueue::collect() under the mutex that guards the counters.*\n\n###### Reading it:\n*Read the distance to 1.0, not the absolute height. Below 1.0 the type has spare slots and its queue wait is not the limit's fault. Touching 1.0 briefly is normal work. Sitting at 1.0 means the type is pinned at its ceiling and every further job of that type is being deferred rather than started, which is what turns into queue wait downstream. Because the limits differ, a raw count of 3 is saturation for ledgerRequest but only 60 percent for fetchTxnData; normalising is what makes the lines comparable.*\n\n###### Healthy range:\n*Below 1.0, with brief touches under load.*\n\n###### Watch for:\n*A line flat at 1.0: that type is the binding constraint. ledgerRequest pinned means the 3 slots shared by RcvGetLedger and RcvGetObjByHash are full, so peer ledger and object requests are queueing behind each other; the Ledger Data and Sync dashboard splits that wait by handler and shows the matching deferred depth. ledgerData or fetchTxnData pinned means inbound ledger data cannot be absorbed and validated ledger age will grow. makeFetchPack or updatePaths pinned at their limit of 1 means a single long job is blocking the whole type. Note the collector samples once per interval, so a line that never reaches 1.0 is not proof the type was never momentarily saturated.*\n\n###### Source:\n[core/JobQueue.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/core/detail/JobQueue.cpp)\n\n###### Function:\n`JobQueue::getNextJob (limit enforcement) / JobQueue::collect (publication)`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 24, + "x": 0, + "y": 147 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + }, + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": ["mean", "max"] + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(jobq_makefetchpack_running{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\"} / 1, \"series\", \"makeFetchPack (Limit 1)\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(jobq_ledgerrequest_running{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\"} / 3, \"series\", \"ledgerRequest (Limit 3)\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(jobq_ledgerdata_running{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\"} / 3, \"series\", \"ledgerData (Limit 3)\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(jobq_updatepaths_running{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\"} / 1, \"series\", \"updatePaths (Limit 1)\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(jobq_fetchtxndata_running{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\"} / 5, \"series\", \"fetchTxnData (Limit 5)\", \"\", \"\")" + } + ], + "fieldConfig": { + "defaults": { + "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", + "unit": "percentunit", + "max": 1, + "min": 0, + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "green", + "value": null + }, + { + "color": "red", + "value": 1 + } + ] + }, + "custom": { + "axisLabel": "Running / Limit", + "drawStyle": "line", + "lineWidth": 2, + "fillOpacity": 10, + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3, + "thresholdsStyle": { + "mode": "line" + } + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + } } ], "schemaVersion": 39, diff --git a/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json b/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json index f86a75b68c..f7bf0823c6 100644 --- a/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json +++ b/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json @@ -530,6 +530,257 @@ }, "overrides": [] } + }, + { + "title": "GetObject Handler (TMGetObjectByHash)", + "type": "row", + "gridPos": { + "h": 1, + "w": 24, + "x": 0, + "y": 32 + }, + "collapsed": false, + "panels": [] + }, + { + "title": "GetObject Handler Latency Breakdown", + "description": "###### What this is:\n*The three additive parts of TMGetObjectByHash service time, drawn on one axis so the expensive part names itself. Queue Wait is how long the RcvGetObjByHash job sat queued before a worker took it; its job type, ledgerRequest, allows only 3 to run at once. Handler Total is the whole job body once running. NodeStore Lookup is only the fetch loop inside that body. End-to-end service time is Queue Wait plus Handler Total, and Handler Total itself splits into NodeStore Lookup plus everything else.*\n\n###### How it's computed:\n*p99 of job_queued_us and job_running_us, both filtered to handler=\"RcvGetObjByHash\", plus p99 of getobject_lookup_us. Each is histogram_quantile over the microsecond bucket series, summed by le so the quantile is computed across the whole bucket set. The handler label is the sanitised addJob name, so RcvGetObjByHash is separated from RcvGetLedger even though both are job type ledgerRequest.*\n\n###### Reading it:\n*Read it as a subtraction, not as three independent lines. The vertical gap between Handler Total and NodeStore Lookup is the serialization and protobuf reply-building cost, because those are the only other things the job body does. So: Queue Wait tall with Handler Total flat means queue contention and the work itself is fine. Handler Total tracking NodeStore Lookup closely means storage is the bottleneck. Handler Total well above NodeStore Lookup means the cost has moved out of the fetch loop into reply construction. All three flat means this path is not the source of the slowness.*\n\n###### Healthy range:\n*All three sub-millisecond while peers ask for the usual 8 hashes per request; workload-dependent above that.*\n\n###### Watch for:\n*Queue Wait climbing while the other two stay flat: the ledgerRequest queue is saturated, so cross-check Job Queue Backlog and Deferred by Type and LedgerReq Wait by Handler on the Ledger Data and Sync dashboard to see which producer is starving it. A widening Handler Total minus NodeStore Lookup gap: reply construction regressed. NodeStore Lookup rising on its own: check getobject_lookups_total misses and the NuDB panels.*\n\n###### Source:\n[PeerImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/overlay/detail/PeerImp.cpp)\n\n###### Function:\n`PeerImp::recordGetObjectMetrics (lookup) / MetricsRegistry::recordJobStarted, recordJobFinished (queue, total)`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 24, + "x": 0, + "y": 33 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + }, + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": ["mean", "max"] + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_queued_us_bucket{handler=\"RcvGetObjByHash\", 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]))), \"series\", \"Queue Wait p99\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(job_running_us_bucket{handler=\"RcvGetObjByHash\", 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]))), \"series\", \"Handler Total p99\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(getobject_lookup_us_bucket{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]))), \"series\", \"NodeStore Lookup p99\", \"\", \"\")" + } + ], + "fieldConfig": { + "defaults": { + "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", + "unit": "µs", + "custom": { + "axisLabel": "Duration (μs)", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3, + "drawStyle": "line", + "lineWidth": 2, + "fillOpacity": 5 + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + } + }, + { + "title": "GetObject Request Size Distribution", + "description": "###### What this is:\n*How many objects peers ask for per TMGetObjectByHash message, as a full distribution rather than an average. This characterises the request that caused any latency seen in the breakdown panel: large batches make the work genuinely large, which is a different problem from the same work becoming slower.*\n\n###### How it's computed:\n*Counts of requests falling in each object-count band per 5-minute window, from the getobject_request_objects bucket series, drawn as colour density.*\n\n###### Reading it:\n*A tight band at the bottom is honest traffic: InboundLedger asks for at most 8 hashes per call. Bands above 64 and above 1024 are the medium and large pricing bands, so mass there means the size surcharge is being applied. A hot cell in the top row is the overflow bucket and means requests larger than the top bucket boundary.*\n\n###### Healthy range:\n*Nearly all mass in the lowest bands (8 objects or fewer per request).*\n\n###### Watch for:\n*Mass appearing in the high bands, especially a persistent hot row near the top: a peer is batching thousands of hashes per message, which is what the differential pricing exists to charge for. Confirm with GetObject Charge Distribution and GetObject Rejections. Buckets are explicit (1,2,4,8,16,64,256,1024,4096,12288) and reach the handler's hard cap, so the top row is real traffic at the cap, not a measurement ceiling.*\n\n###### Source:\n[PeerImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/overlay/detail/PeerImp.cpp)\n\n###### Function:\n`PeerImp::recordGetObjectMetrics`", + "type": "heatmap", + "gridPos": { + "h": 8, + "w": 12, + "x": 0, + "y": 41 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + }, + "yAxis": { + "axisLabel": "Objects Per Request", + "unit": "short" + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus" + }, + "expr": "sum(increase(getobject_request_objects_bucket{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\"}[5m])) by (le)", + "legendFormat": "{{le}}", + "format": "heatmap" + } + ], + "fieldConfig": { + "defaults": { + "unit": "short" + }, + "overrides": [] + } + }, + { + "title": "GetObject Lookups by Result", + "description": "###### What this is:\n*NodeStore lookups performed by the handler, split into hits and misses. A miss does a node-store seek while a hit is usually served from cache, so the hit/miss mix is the reason NodeStore Lookup time moves.*\n\n###### How it's computed:\n*Per-second rate of getobject_lookups_total, grouped by the result label. The counter is advanced once per request with the batch total, not once per object, so the rate is objects per second rather than requests per second.*\n\n###### Reading it:\n*Use this to explain the NodeStore Lookup line on the breakdown panel. A miss-heavy mix makes that line rise for a real reason: seeks, not a regression. A hit-heavy mix with rising lookup time points at the storage layer instead.*\n\n###### Healthy range:\n*Hits dominating on a warm synced node; misses low and driven by genuine catch-up requests.*\n\n###### Watch for:\n*A sustained miss rate far above the hit rate: a peer is asking for hashes this node does not hold, which is either a badly out-of-sync peer or probing traffic. Cross-check GetObject Charge Distribution, since misses are billed first and at eight times the hit cost.*\n\n###### Source:\n[PeerImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/overlay/detail/PeerImp.cpp)\n\n###### Function:\n`PeerImp::recordGetObjectMetrics`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 12, + "x": 12, + "y": 41 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(sum by (result, service_instance_id, xrpl_branch, xrpl_node_role) (rate(getobject_lookups_total{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\", result=~\"$result\"}[$__rate_interval])), \"series\", \"$1\", \"result\", \"(.*)\")" + } + ], + "fieldConfig": { + "defaults": { + "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", + "unit": "cps", + "custom": { + "axisLabel": "Lookups / Sec", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3 + } + }, + "overrides": [] + } + }, + { + "title": "GetObject Rejections", + "description": "###### What this is:\n*Requests refused by the message handler before any NodeStore access, split by which gate refused them: oversize means more objects than the handler accepts, malformed_ledgerhash means the ledger hash was not 32 bytes.*\n\n###### How it's computed:\n*Per-second rate of getobject_rejected_total, grouped by the reason label. Both gates run in onMessage before the job is queued, so a rejection consumes no queue slot and no NodeStore lookup.*\n\n###### Reading it:\n*Any non-zero value is traffic that does not conform to the protocol: an honest peer asks for at most 8 hashes and always sends a full-size hash. Because the gates fire before the fetch loop, rejections explain why request volume can be high while lookups stay flat.*\n\n###### Healthy range:\n*Zero. No honest peer produces either rejection.*\n\n###### Watch for:\n*A rising oversize rate: a peer is probing the request-size limit. Confirm the pricing response on GetObject Charge Distribution, and expect the peer to be disconnected once its resource balance crosses the drop threshold. A rising malformed rate points at a broken or hostile client rather than at load.*\n\n###### Source:\n[PeerImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/overlay/detail/PeerImp.cpp)\n\n###### Function:\n`PeerImp::onMessage (TMGetObjectByHash)`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 12, + "x": 0, + "y": 49 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(sum by (reason, service_instance_id, xrpl_branch, xrpl_node_role) (rate(getobject_rejected_total{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\", reason=~\"$reason\"}[$__rate_interval])), \"series\", \"$1\", \"reason\", \"(.*)\")" + } + ], + "fieldConfig": { + "defaults": { + "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", + "unit": "cps", + "custom": { + "axisLabel": "Rejections / Sec", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3 + } + }, + "overrides": [] + } + }, + { + "title": "GetObject Charge Distribution", + "description": "###### What this is:\n*The dynamic resource charge applied per TMGetObjectByHash request, as percentiles. This is the differential-pricing component only, so it shows whether cost actually escalates with request size and miss ratio the way the pricing model intends.*\n\n###### How it's computed:\n*p50, p90 and p99 of getobject_charge over the dashboard rate interval, from its bucket series summed by le. The value recorded is the charge that was applied, computed from billable hits, billable misses and the request-size band.*\n\n###### Reading it:\n*p50 sitting at zero is the healthy shape: requests inside the free allowance cost nothing. Movement in p99 while p50 stays at zero means a small number of expensive requests, which is exactly the traffic the model is meant to price. Compare with GetObject Request Size Distribution: charge should rise in steps as requests cross the size-band edges, not smoothly.*\n\n###### Healthy range:\n*p50 at zero, p99 low. Honest requests of 16 objects or fewer are free by design.*\n\n###### Watch for:\n*p99 climbing steadily: sustained expensive traffic, and the peers producing it should be approaching the resource drop threshold. Buckets are explicit and bracket the resource thresholds (5000 warning, 25000 drop), so p99 crossing 25000 means senders are being disconnected on a single message. The axis is deliberately unscaled rather than abbreviated, so those two numbers are readable exactly rather than as 5 K and 25 K.*\n\n###### Source:\n[PeerImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/overlay/detail/PeerImp.cpp)\n\n###### Function:\n`PeerImp::computeGetObjectByHashFee`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 12, + "x": 12, + "y": 49 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(histogram_quantile(0.5, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(getobject_charge_bucket{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]))), \"series\", \"Charge p50\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(histogram_quantile(0.9, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(getobject_charge_bucket{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]))), \"series\", \"Charge p90\", \"\", \"\")" + }, + { + "datasource": { + "type": "prometheus" + }, + "expr": "label_replace(histogram_quantile(0.99, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(getobject_charge_bucket{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]))), \"series\", \"Charge p99\", \"\", \"\")" + } + ], + "fieldConfig": { + "defaults": { + "displayName": "${__field.labels.series} [${__field.labels.service_instance_id} ${__field.labels.xrpl_branch} ${__field.labels.xrpl_node_role} ${__field.labels.xrpl_work_item}]", + "unit": "none", + "custom": { + "axisLabel": "Charge (Cost Units)", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3, + "drawStyle": "line", + "lineWidth": 2, + "fillOpacity": 5 + }, + "color": { + "mode": "palette-classic" + } + }, + "overrides": [] + } } ], "schemaVersion": 39, @@ -675,6 +926,46 @@ "multi": true, "refresh": 2, "sort": 1 + }, + { + "name": "result", + "label": "Lookup Result", + "description": "Filter GetObject NodeStore lookups by result [hit / miss]", + "type": "query", + "query": "label_values(getobject_lookups_total, result)", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "includeAll": true, + "allValue": ".*", + "current": { + "text": "All", + "value": "$__all" + }, + "multi": true, + "refresh": 2, + "sort": 1 + }, + { + "name": "reason", + "label": "Rejection Reason", + "description": "Filter GetObject rejections by gate [oversize / malformed_ledgerhash]", + "type": "query", + "query": "label_values(getobject_rejected_total, reason)", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "includeAll": true, + "allValue": ".*", + "current": { + "text": "All", + "value": "$__all" + }, + "multi": true, + "refresh": 2, + "sort": 1 } ] }, diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 218cf7ab74..ebeb4eeaab 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -625,9 +625,71 @@ The `OTelCollector` implementation exports metrics via OTLP/HTTP to the same OTe | `peer_finder_active_outbound_peers` | PeerfinderManager.cpp:215 | Active outbound peer connections | | `overlay_peer_disconnects` | OverlayImpl.h:557 | Peer disconnect count | | `job_count` | JobQueue.cpp:26 | Current job queue depth | +| `jobq_{jobtype}_waiting` | JobTypeData.h | Jobs of this type enqueued but not yet running | +| `jobq_{jobtype}_running` | JobTypeData.h | Jobs of this type currently executing | +| `jobq_{jobtype}_deferred` | JobTypeData.h | Jobs of this type held back because the type's concurrency limit was hit | | `{category}_bytes_in/out` | OverlayImpl.h:535 | Overlay traffic bytes per category (57 categories) | | `{category}_messages_in/out` | OverlayImpl.h:535 | Overlay traffic messages per category | +Note that `job_count` is exported as `jobq_job_count`: the JobQueue is +constructed with `collectorManager_->group("jobq")` (Application.cpp:386), +`GroupImp::makeName()` joins prefix and name with a `.` (Groups.cpp:42), and +`OTelCollectorImp::formatName()` then turns the `.` into `_` and lowercases the +whole string (OTelCollector.cpp:860). The same mechanism produces the +`jobq_{jobtype}_*` names above and the pre-existing +`jobq_{jobtype}_milliseconds` timing family. + +#### Per-Job-Type Queue Saturation + +The three `jobq_{jobtype}_{waiting,running,deferred}` families expose the +per-type counters that `JobTypeData` already maintained but never exported. +`{jobtype}` is the lowercased `JobTypes` name, so `JtLedgerReq` ("ledgerRequest") +becomes `jobq_ledgerrequest_waiting` / `_running` / `_deferred`. + +They are emitted for every **non-special** job type — 35 of the 46 declared +types. A "special" type is one whose concurrency limit is 0 +(`JobTypeInfo::special()`, JobTypeInfo.h:71-74); the limit logic never applies +to it, so its `deferred` is always zero. The gauge members are declared at +JobTypeData.h:78-80 and created at :100-102, next to the existing +`dequeue`/`execute` events and under the same `!info.special()` guard (:95). They +are published by `JobQueue::collect()` under the `mutex_` that already guards the +counters (JobQueue.cpp:66-93) — no new locking. + +**`deferred` is the leading indicator.** `JobQueue::addJob()` never rejects +work — when a type is at its limit, `addRefCountedJob()` increments `deferred` +and returns `true` anyway (JobQueue.cpp:131-142), and `finishJob()` drains one +deferred job per completion (JobQueue.cpp:353-362). Backpressure on a capped type +therefore shows up **only as latency**, after the harm is done. `deferred > 0` +says the cap is being hit _now_, before the duration histograms move. + +Limits that matter for ledger sync (JobTypes.h:54-77): + +| Job type | Metric prefix | Limit | Producers | +| -------------- | --------------------- | ----- | ------------------------------------------------------------------------------- | +| `JtPack` | `jobq_makefetchpack_` | 1 | `MakeFetchPack` | +| `JtLedgerReq` | `jobq_ledgerrequest_` | 3 | `RcvGetLedger`, `RcvGetObjByHash` | +| `JtLedgerData` | `jobq_ledgerdata_` | 3 | `ProcessLData`, `GotStaleData`, `GotFetchPack`, `AcqDone`, `InboundLedger` | +| `JtUpdatePf` | `jobq_updatepaths_` | 1 | `PthFindNewReq`, `PthFindOBDB`, `PthFindNewLed`, `OB` — see the note below | +| `JtTxnData` | `jobq_fetchtxndata_` | 5 | `TxAcq`, `ComplAcquire`, `RcvPeerData` | + +> **`JtUpdatePf` has four producers, three of them individually visible.** All +> four run the same `updatePaths()` work but arrive under different names. Three +> come through `LedgerMaster::newPFWork()` (LedgerMaster.cpp:1545), which passes +> its caller's name straight to `addJob`: `PthFindNewReq` (:1512), +> `PthFindOBDB` (:1533), and `PthFindNewLed` (:1984). All three are all-letters, +> so each is its own `handler` series. The fourth is +> `"OB" + std::to_string(seq)` (OrderBookDBImpl.cpp:84), which contains digits +> and therefore folds to `handler="other"` — order-book rebuild traffic is the +> only one of the four that is not directly attributable. Do not read the whole +> type as invisible: three of its four producers are named. + +> **Sampling caveat**: these are gauges read by the `JobQueue::collect()` hook, +> which the beast::insight `PeriodicMetricReader` drives every 1 s +> (Telemetry.cpp:441). A `deferred` spike shorter than the sample interval can be +> missed entirely. Treat a non-zero reading as real saturation, but do not treat +> a zero reading as proof that no saturation occurred — cross-check +> `job_queued_us` for the same type. + #### OTel MetricsRegistry Gauges These gauges are exported via the OTel Metrics SDK `PeriodicMetricReader` (10s interval), NOT through beast::insight. @@ -675,6 +737,126 @@ These gauges are exported via the OTel Metrics SDK `PeriodicMetricReader` (10s i | `pathfind_fast` | PathRequests.h:23 | Fast pathfinding duration (ms) | | `pathfind_full` | PathRequests.h:24 | Full pathfinding duration (ms) | +#### Job Instruments + +These five come from the `PerfLog` job hooks, not from beast::insight, so they +are exported by the `MetricsRegistry` meter. `job_queued_us` and `job_running_us` +have explicit microsecond bucket views registered +(`addMicrosecondHistogramView()`, MetricsRegistry.cpp:253-254) spanning 100 µs to +60 s; without those the SDK default buckets stop at 10 ms and every quantile +saturates. + +| Prometheus Metric | Kind | Labels | Description | +| -------------------- | --------- | --------------------- | ------------------------------------ | +| `job_queued_total` | Counter | `job_type`, `handler` | Jobs enqueued | +| `job_started_total` | Counter | `job_type`, `handler` | Jobs dequeued and started | +| `job_finished_total` | Counter | `job_type`, `handler` | Jobs run to completion | +| `job_queued_us` | Histogram | `job_type`, `handler` | Time spent waiting in the queue (µs) | +| `job_running_us` | Histogram | `job_type`, `handler` | Time spent executing (µs) | + +#### The `handler` Label + +`job_type` names the queue a job ran on, not the code that submitted it. Several +job types have more than one producer, so `job_type` alone cannot attribute a +latency spike. The clearest case: `RcvGetLedger` (PeerImp.cpp:1566) and +`RcvGetObjByHash` (PeerImp.cpp:2603) both submit to `JtLedgerReq`, so both report +as `job_type="ledgerRequest"`. `JtLedgerData` has five producers, `JtUpdatePf` has +four, and `JtAdvance` has four. + +The `handler` label carries the name string passed to `addJob()` — the specific +call site. It resolves all of those at once, not just the GetObject path. + +**The value is sanitized, not raw.** A raw job name would be unbounded, because +two production job names embed a ledger sequence number: + +- `"Pub" + std::to_string(ledger->seq())` (LedgerPersistence.cpp:84) +- `"OB" + std::to_string(ledger->seq() % 1000000000)` (OrderBookDBImpl.cpp:84) + +A raw label would mint a new Prometheus series for every ledger — unbounded +growth at ~1 series every 3-5 s, forever. +`MetricsRegistry::sanitiseHandler()` (declared inline in +`src/xrpld/telemetry/MetricsRegistry.h`) therefore applies one rule: + +- Keep the name when it is **non-empty and every character is an ASCII letter**. +- Otherwise return the constant `"other"`. An empty name, a digit, a hyphen, or + any punctuation all fall here. + +Both dynamic names always contain digits, so both collapse to `"other"`. Because +the rule is a pure function of compile-time string literals, the label domain is +fixed at build time and cannot grow at runtime. That is a stronger guarantee than +an allowlist, which would silently mislabel any job added later; this rule +degrades to `"other"` instead. + +**Five static job names also fall into `"other"`.** Sweeping every `addJob` / +`addRefCountedJob` / `postCoro` / `newPFWork` / `TimeoutCounter::jobName` call +site outside `src/test` finds 48 distinct static name literals. 43 are +all-letters and pass through; five are not, and two more are built at runtime +from a ledger sequence. The domain is therefore **44 values** (43 names plus +`"other"`): + +| Name | Why it is not all-letters | Call site | +| ------------- | ------------------------- | ---------------------- | +| `GetConsL1` | digit | RCLConsensus.cpp:169 | +| `GetConsL2` | digit | RCLValidations.cpp:135 | +| `gRPC-Client` | hyphen | GRPCServer.cpp:156 | +| `RPC-Client` | hyphen | ServerHandler.cpp:332 | +| `WS-Client` | hyphen | ServerHandler.cpp:376 | + +> The consequence worth remembering: `handler="other"` is a **mixed bucket**, not +> a residual. It holds the two per-ledger dynamic names _and_ those five static +> ones, so `GetConsL1` and `GetConsL2` — two different `JtAdvance` producers — +> are not separable, and neither are the three RPC client-session names. Do not +> read a handler breakdown as exhaustive. The GetObject path is unaffected: +> `RcvGetObjByHash` and `RcvGetLedger` are all-letters and pass through as +> distinct series. +> +> The count is "at the time of writing" — it is a property of the source, not of +> the rule. Re-derive it from the call sites after adding a job rather than +> trusting this number. + +#### GetObject Request Metrics + +Five instruments on the `TMGetObjectByHash` query path, recorded via the +`XRPL_METRIC_*` macros at their call sites in `PeerImp.cpp`. Label cardinality is +fixed and tiny: two `result` values, two `reason` values. + +| Prometheus Metric | Kind | Labels | Description | +| --------------------------- | --------- | ----------------------------------------------- | ----------------------------------------------------- | +| `getobject_lookup_us` | Histogram | none | Time inside the NodeStore fetch loop (µs) | +| `getobject_request_objects` | Histogram | none | Objects requested per request | +| `getobject_lookups_total` | Counter | `result` = `hit` \| `miss` | NodeStore hit/miss volume | +| `getobject_rejected_total` | Counter | `reason` = `oversize` \| `malformed_ledgerhash` | Requests refused before any NodeStore access | +| `getobject_charge` | Histogram | none | Dynamic component of the differential resource charge | + +Aggregation choices worth knowing when reading these: + +- `getobject_lookup_us` times the **whole fetch loop once** + (`processGetObjectByHash()`, PeerImp.cpp:2713-2742 — the iteration cap is set + at :2713 and the loop ends at :2742), not each iteration. The loop can run up + to `kHardMaxReplyNodes` = 12288 times (Tuning.h:30); timing each + `fetchNodeObject()` would cost more than the lookups. It needs an + `addMicrosecondHistogramView()` entry for the same reason the job histograms + do — a 12288-lookup loop routinely exceeds 10 ms, so without the view the + metric saturates exactly when it matters. +- `getobject_lookups_total` is incremented **once per request with the batch + totals**, not once per object. A 12288-iteration loop incrementing per object + would be a measurable hot-path cost for no extra information. +- `getobject_request_objects` records `packet.objects_size()` — the _requested_ + count, which is what the charge bands price on, not the count actually found. +- `getobject_charge` records only the **dynamic** part returned by + `computeGetObjectByHashFee()` (PeerImp.cpp:3658-3681), applied at + PeerImp.cpp:2757-2758 just after the loop. The admission-time base charge is a + constant (`kFeeModerateBurdenPeer`, PeerImp.cpp:2634) and is already implied. +- `getobject_rejected_total` counts the two early returns in + `onMessage(TMGetObjectByHash)`: the malformed-ledgerhash check (PeerImp.cpp:2569, + counter at :2573) and the oversize gate (PeerImp.cpp:2585, counter at :2591). + Both fire before the job is enqueued, so a rejected request contributes to no + other GetObject metric. + +> On a healthy local network `getobject_rejected_total` reads zero — no honest +> peer sends an oversized request. Verify its panel with a synthetic oversized +> request; do not assume it works because the query parses. + #### Adding a New Metric @@ -1178,6 +1360,114 @@ Wait for the node to sync with the network. The `getKBUsed*()` methods require SQLite databases to exist. If running with `--standalone` or before the first ledger is stored, these will be zero. +### Slow TMGetObjectByHash service + +Use this when a peer reports slow object fetches, or when `job_queued_us` / +`job_running_us` for `job_type="ledgerRequest"` rises. The goal is to name the +cause, not to confirm the slowness. + +End-to-end handler time splits into three additive parts, and each has its own +signal: + +```mermaid +flowchart LR + A["`**Request arrives** + onMessage + TMGetObjectByHash`"] --> B["`**1. Queue wait** + job_queued_us + handler=RcvGetObjByHash`"] + B --> C["`**2. NodeStore lookup** + getobject_lookup_us`"] + C --> D["`**3. Everything else** + protobuf, serialization, + reply construction`"] + D --> E["`**Reply sent**`"] + + C -.-> F["`job_running_us + handler=RcvGetObjByHash + covers steps 2 + 3`"] + D -.-> F + + style A fill:#1f4e79,color:#ffffff + style B fill:#7b3f00,color:#ffffff + style C fill:#2d5016,color:#ffffff + style D fill:#4a148c,color:#ffffff + style E fill:#1f4e79,color:#ffffff + style F fill:#37474f,color:#ffffff +``` + +**Reading the diagram** + +- Step 1 is time the job sat in `JtLedgerReq` before a worker picked it up. Only + `job_queued_us` measures it. +- Steps 2 and 3 both happen inside the worker, so `job_running_us` covers them + together. `getobject_lookup_us` isolates step 2 alone. +- Step 3 is therefore not measured directly. Derive it: + `job_running_us − getobject_lookup_us`. That subtraction is what makes the set + able to name a cause instead of just reporting a duration. + +**Procedure** — work through these in order. The first row that matches is the +answer. + +> **Scope every query to one node.** All snippets below carry +> `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. + +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]))) + ``` + +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]))) + ``` + +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. | + +Row 2 says "within ~10%", not "equal", deliberately: `job_running_us` also +covers the charge computation (PeerImp.cpp:2757) and the reply `send()` that +follow the loop, so it is always the larger of the two. Treat a small residual as +normal and only a large one as a signal — that is what row 3 is for. + +The last row matters as much as the others: the set can rule this path _out_, +which a slowness-only metric cannot. + +**Caveats** + +- `handler` collapses to `"other"` for any job name that is not all ASCII + letters, so a handler breakdown is not exhaustive — see + [The `handler` Label](#the-handler-label). This does not affect + `RcvGetObjByHash` or `RcvGetLedger`; both pass through as distinct series. +- `jobq_*_deferred` is sampled at 1 s. A zero reading does not prove no + saturation occurred — see the sampling caveat under + [Per-Job-Type Queue Saturation](#per-job-type-queue-saturation). +- The two families compared in this procedure are exported on **different + cadences by separate meter providers**: the `jobq_*` gauges every 1 s + (`Telemetry.cpp` global provider) and `job_queued_us` / `job_running_us` / + `getobject_*` every 10 s (the private `MetricsRegistry` provider). A short + spike can therefore appear in one family a step before the other. When + correlating them, widen the window rather than reading a single scrape, and + do not conclude the two disagree from one interval's difference. +- A request rejected at either gate contributes to no other GetObject metric, so + a rejection spike will _not_ show up as latency. Check the rejection counters + before concluding that traffic is normal. + ### High memory usage - Reduce trace volume with collector-side tail sampling (xrpld head sampling is diff --git a/include/xrpl/core/Job.h b/include/xrpl/core/Job.h index 93b39701be..53e8566a99 100644 --- a/include/xrpl/core/Job.h +++ b/include/xrpl/core/Job.h @@ -109,6 +109,20 @@ public: [[nodiscard]] JobType getType() const; + /** + * Returns the job name supplied to JobQueue::addJob. + * + * Several job types have more than one producer (for example both + * RcvGetLedger and RcvGetObjByHash run as JtLedgerReq), so the name is + * the only thing that tells them apart. It is read by the JobQueue + * PerfLog hooks and exported as the `handler` metric label. + * + * Empty for the default and index-only constructors, which carry no + * name; callers must treat an empty name as "unknown". + */ + [[nodiscard]] std::string const& + getName() const; + /** * Returns the time when the job was queued. */ diff --git a/include/xrpl/core/JobQueue.h b/include/xrpl/core/JobQueue.h index 0c9fc76357..e07ab0362c 100644 --- a/include/xrpl/core/JobQueue.h +++ b/include/xrpl/core/JobQueue.h @@ -334,7 +334,9 @@ private: // any. // // Invariants: - // + // The calling thread owns the JobLock. This function mutates the + // deferred and running counts, which mutex_ guards; collect() reads + // them under the same lock. void finishJob(JobType type); diff --git a/include/xrpl/core/JobTypeData.h b/include/xrpl/core/JobTypeData.h index d53440e1ca..b503cbcbbd 100644 --- a/include/xrpl/core/JobTypeData.h +++ b/include/xrpl/core/JobTypeData.h @@ -3,6 +3,7 @@ #include #include #include +#include #include #include #include @@ -20,6 +21,23 @@ private: beast::insight::Collector::ptr collector_; public: + /** + * Metric-name suffixes appended to `JobTypeInfo::name()`. + * + * The constructor builds the instrument names from these. Public so + * tests can assert on the exported names without repeating the + * literals. The collector is the `"jobq"` group, so + * `GroupImp::makeName()` prefixes `jobq.` and `OTelCollector` + * lowercases and turns `.` into `_`: `ledgerRequest` + + * `kSuffixDeferred` exports as `jobq_ledgerrequest_deferred`. + */ + /** @{ */ + static constexpr char kSuffixWaiting[] = "_waiting"; + static constexpr char kSuffixRunning[] = "_running"; + static constexpr char kSuffixDeferred[] = "_deferred"; + static constexpr char kSuffixQueued[] = "_q"; + /** @} */ + /* The job category which we represent */ JobTypeInfo const& info; @@ -36,6 +54,32 @@ public: beast::insight::Event dequeue; beast::insight::Event execute; + /** + * Saturation gauges, published by `JobQueue::collect()`. + * + * Each mirrors the same-named counter above so per-job-type queue + * pressure is visible in metrics. Without them the only exported queue + * signal is the process-wide `jobq_job_count`, which cannot attribute + * pressure to a job type. + * + * `waitingGauge` is the backlog not yet started, `runningGauge` is the + * in-flight count, and `deferredGauge` is the count held back by this + * type's concurrency limit. `deferredGauge` is the leading indicator: + * `JobQueue::addJob()` never rejects, so a capped type under pressure + * shows up as latency only after the fact, whereas a non-zero deferred + * reading precedes it. + * + * Created only for non-special types (see the constructor). A default + * constructed `beast::insight::Gauge` holds a null impl and every + * mutator is a no-op, so a special type's gauge is safe to assign to + * but publishes nothing. + */ + /** @{ */ + beast::insight::Gauge waitingGauge; + beast::insight::Gauge runningGauge; + beast::insight::Gauge deferredGauge; + /** @} */ + JobTypeData( JobTypeInfo const& info, beast::insight::Collector::ptr collector, @@ -45,10 +89,17 @@ public: { load_.setTargetLatency(info.getAverageLatency(), info.getPeakLatency()); + // Special types have limit_ == 0 and bypass the limit logic + // entirely, so their `deferred` is always 0. Excluding them here + // matches the existing dequeue/execute rule. if (!info.special()) { - dequeue = collector_->makeEvent(info.name() + "_q"); + dequeue = collector_->makeEvent(info.name() + kSuffixQueued); execute = collector_->makeEvent(info.name()); + + waitingGauge = collector_->makeGauge(info.name() + kSuffixWaiting); + runningGauge = collector_->makeGauge(info.name() + kSuffixRunning); + deferredGauge = collector_->makeGauge(info.name() + kSuffixDeferred); } } diff --git a/include/xrpl/core/PerfLog.h b/include/xrpl/core/PerfLog.h index f09665e291..441a6f6c76 100644 --- a/include/xrpl/core/PerfLog.h +++ b/include/xrpl/core/PerfLog.h @@ -92,30 +92,41 @@ public: * Log queued job * * @param type Job type + * @param name Job name as given to JobQueue::addJob. Distinguishes the + * several producers that share one job type. May be empty. */ virtual void - jobQueue(JobType const type) = 0; + jobQueue(JobType const type, std::string const& name) = 0; /** * Log job executing * * @param type Job type + * @param name Job name as given to JobQueue::addJob. Distinguishes the + * several producers that share one job type. May be empty. * @param dur Duration enqueued in microseconds * @param startTime Time that execution began * @param instance JobQueue worker thread instance */ virtual void - jobStart(JobType const type, microseconds dur, steady_time_point startTime, int instance) = 0; + jobStart( + JobType const type, + std::string const& name, + microseconds dur, + steady_time_point startTime, + int instance) = 0; /** * Log job finishing * * @param type Job type + * @param name Job name as given to JobQueue::addJob. Distinguishes the + * several producers that share one job type. May be empty. * @param dur Duration running in microseconds * @param instance Jobqueue worker thread instance */ virtual void - jobFinish(JobType const type, microseconds dur, int instance) = 0; + jobFinish(JobType const type, std::string const& name, microseconds dur, int instance) = 0; /** * Render performance counters in Json diff --git a/include/xrpl/telemetry/GetObjectMetricNames.h b/include/xrpl/telemetry/GetObjectMetricNames.h new file mode 100644 index 0000000000..e2951a43d0 --- /dev/null +++ b/include/xrpl/telemetry/GetObjectMetricNames.h @@ -0,0 +1,160 @@ +#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 names, label keys, label values, and descriptions for the + * `TMGetObjectByHash` request path. + * + * These constants are shared across two modules, which is why they live in a + * header rather than in either translation unit's unnamed namespace: + * + * GetObjectMetricNames.h + * | + * +--> PeerImp.cpp (XRPL_METRIC_* call sites: records the + * | instruments) + * | + * +--> MetricsRegistry.cpp (addMicrosecondHistogramView: registers + * the explicit bucket boundaries for + * kGetObjectLookupUs) + * + * `kGetObjectLookupUs` in particular is referenced from both sites. 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, which top out at 10,000 (10 ms), so every quantile + * would saturate. This mirrors the reason the existing + * `kJobQueuedDurationUs` / `kJobRunningDurationUs` / `kRpcMethodDurationUs` + * constants exist in MetricsRegistry.cpp; those three are referenced only + * within that one file, so they stay file-local. + * + * Placed under `include/xrpl/telemetry/` because the two consumers sit in + * different levelization modules: PeerImp.cpp is `xrpld.overlay` and + * MetricsRegistry.cpp is `xrpld.telemetry`. Both are allowed to depend on + * `xrpl.telemetry` (see `xrpld.overlay > xrpl.telemetry` and + * `xrpld.telemetry > xrpl.telemetry` in the levelization ordering results), so + * `include/xrpl/` is the one level both can reach. Keeping the constants in + * `src/xrpld/telemetry/` would have required overlay to include a private + * xrpld header from another module, flipping a levelization edge. Both sites + * include this file as ``. + * + * Example usage -- recording a histogram: + * @code + * XRPL_METRIC_HISTOGRAM_RECORD( + * app_, kGetObjectRequestObjects, kGetObjectRequestObjectsDesc, requested); + * @endcode + * + * Example usage -- edge case: the same instrument recorded under two + * different label values, which is why the label key and both values are + * constants rather than literals: + * @code + * XRPL_METRIC_COUNTER_ADD_LABELED( + * app_, kGetObjectLookupsTotal, kGetObjectLookupsTotalDesc, hits, + * {{kLabelResult, std::string(kResultHit)}}); + * XRPL_METRIC_COUNTER_ADD_LABELED( + * app_, kGetObjectLookupsTotal, kGetObjectLookupsTotalDesc, misses, + * {{kLabelResult, std::string(kResultMiss)}}); + * @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 (the build defines only OPENTELEMETRY_ABI_VERSION_NO, not + * OPENTELEMETRY_STL_VERSION, so `nostd::string_view` is not an alias for + * `std::string_view`). 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. This also + * matches the existing convention in MetricsRegistry.cpp. + * + * @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 names ========================================================== + +/** + * Requests refused by `onMessage(TMGetObjectByHash)` before any NodeStore + * access, split by the `reason` label. + */ +inline constexpr char kGetObjectRejectedTotal[] = "getobject_rejected_total"; + +/** + * Distribution of the object count requested per message. + */ +inline constexpr char kGetObjectRequestObjects[] = "getobject_request_objects"; + +/** + * Wall time spent in the NodeStore fetch loop, in microseconds. + * + * Referenced twice: here at the record site, and by + * `addMicrosecondHistogramView()` in MetricsRegistry.cpp. Both must use this + * one constant. + */ +inline constexpr char kGetObjectLookupUs[] = "getobject_lookup_us"; + +/** + * NodeStore lookups performed, split by the `result` label. + */ +inline constexpr char kGetObjectLookupsTotal[] = "getobject_lookups_total"; + +/** + * Distribution of the dynamic resource charge applied per request. + */ +inline constexpr char kGetObjectCharge[] = "getobject_charge"; + +// ===== Label keys ============================================================ + +/** + * Label key distinguishing a hit from a miss on `kGetObjectLookupsTotal`. + */ +inline constexpr char kLabelResult[] = "result"; + +/** + * Label key naming which gate refused the request. + */ +inline constexpr char kLabelReason[] = "reason"; + +// ===== Label values ========================================================== + +/** + * `kLabelResult` value: the object was found in the NodeStore. + */ +inline constexpr char kResultHit[] = "hit"; + +/** + * `kLabelResult` value: the object was not found. + */ +inline constexpr char kResultMiss[] = "miss"; + +/** + * `kLabelReason` value: more objects requested than the handler accepts. + */ +inline constexpr char kReasonOversize[] = "oversize"; + +/** + * `kLabelReason` value: the ledger hash was not uint256-sized. + */ +inline constexpr char kReasonMalformedLedgerHash[] = "malformed_ledgerhash"; + +// ===== Instrument descriptions =============================================== + +/** @{ */ +inline constexpr char kGetObjectRejectedTotalDesc[] = + "TMGetObjectByHash requests refused before any NodeStore access, by reason"; + +inline constexpr char kGetObjectRequestObjectsDesc[] = + "Objects requested per TMGetObjectByHash message"; + +inline constexpr char kGetObjectLookupUsDesc[] = + "Time spent in the TMGetObjectByHash NodeStore fetch loop, in microseconds"; + +inline constexpr char kGetObjectLookupsTotalDesc[] = + "TMGetObjectByHash NodeStore lookups, by hit/miss result"; + +inline constexpr char kGetObjectChargeDesc[] = + "Dynamic resource charge applied per TMGetObjectByHash request"; +/** @} */ + +} // namespace xrpl::telemetry diff --git a/src/libxrpl/core/detail/Job.cpp b/src/libxrpl/core/detail/Job.cpp index 89fe42db05..70c11b3bf1 100644 --- a/src/libxrpl/core/detail/Job.cpp +++ b/src/libxrpl/core/detail/Job.cpp @@ -36,6 +36,12 @@ Job::getType() const return type_; } +std::string const& +Job::getName() const +{ + return name_; +} + Job::clock_type::time_point const& Job::queueTime() const { diff --git a/src/libxrpl/core/detail/JobQueue.cpp b/src/libxrpl/core/detail/JobQueue.cpp index 8f95a8a5fa..71051839a9 100644 --- a/src/libxrpl/core/detail/JobQueue.cpp +++ b/src/libxrpl/core/detail/JobQueue.cpp @@ -18,6 +18,7 @@ #include #include #include +#include namespace xrpl { @@ -65,8 +66,45 @@ JobQueue::~JobQueue() void JobQueue::collect() { - std::scoped_lock const lock(mutex_); - jobCount_ = jobSet_.size(); + // Gauge::value_type is unsigned. The counters are only ever expected to + // be non-negative (the surrounding asserts enforce it), but clamp anyway: + // an unclamped negative would wrap to ~1.8e19 and swamp every dashboard + // reading this family. + auto const toGauge = [](int value) { + return static_cast(std::max(0, value)); + }; + + // Snapshot under the lock, publish after releasing it. + // + // Writing gauges while holding `mutex_` would invert a lock order: a + // collector's gauge write can take the collector's own lock, while the + // collector's flush thread already holds that lock when it calls this + // hook and then needs `mutex_`. Publishing outside the lock keeps + // `mutex_` strictly innermost, so no cycle can form. It also keeps the + // queue's hot lock (every addJob and every job start/finish takes it) + // off the per-gauge write path, which on some collectors allocates. + // + // A snapshot can be one flush interval stale; these are sampled + // saturation gauges, so that is the intended accuracy. + std::vector> snapshot; + { + std::scoped_lock const lock(mutex_); + jobCount_ = jobSet_.size(); + + snapshot.reserve(jobData_.size()); + for (auto& [type, data] : jobData_) + snapshot.emplace_back(&data, data.waiting, data.running, data.deferred); + } + + // Gauges exist only for non-special types (JobTypeData's ctor). Assigning + // to a special type's default-constructed Gauge is a safe no-op -- + // Gauge::set() checks its impl pointer -- so this needs no special case. + for (auto const& [data, waiting, running, deferred] : snapshot) + { + data->waitingGauge = toGauge(waiting); + data->runningGauge = toGauge(running); + data->deferredGauge = toGauge(deferred); + } } bool @@ -98,7 +136,9 @@ JobQueue::addRefCountedJob(JobType type, std::string const& name, JobFunction co JobType const type(job.getType()); XRPL_ASSERT(type != JtInvalid, "xrpl::JobQueue::addRefCountedJob : has valid job type"); XRPL_ASSERT(jobSet_.contains(job), "xrpl::JobQueue::addRefCountedJob : job found"); - perfLog_.jobQueue(type); + // `name` is the addJob name; it becomes the `handler` metric label so + // producers sharing a job type stay individually attributable. + perfLog_.jobQueue(type, name); JobTypeData& data(getJobTypeData(type)); @@ -359,7 +399,7 @@ JobQueue::processTask(int instance) // The amount of time that the job was in the queue auto const qTime = ceil(startTime - job.queueTime()); - perfLog_.jobStart(type, qTime, startTime, instance); + perfLog_.jobStart(type, job.getName(), qTime, startTime, instance); job.doJob(); @@ -371,7 +411,9 @@ JobQueue::processTask(int instance) getJobTypeData(type).dequeue.notify(qTime); getJobTypeData(type).execute.notify(xTime); } - perfLog_.jobFinish(type, xTime, instance); + // `job` is still alive here: it is scoped to the enclosing block + // and doJob() only releases the callable, not the name. + perfLog_.jobFinish(type, job.getName(), xTime, instance); } } diff --git a/src/test/basics/PerfLog_test.cpp b/src/test/basics/PerfLog_test.cpp index 41b5f81f5d..792934f0fe 100644 --- a/src/test/basics/PerfLog_test.cpp +++ b/src/test/basics/PerfLog_test.cpp @@ -533,7 +533,7 @@ public: // the jobs data with every addition. for (int i = 0; i < jobs.size(); ++i) { - perfLog->jobQueue(jobs[i].type); + perfLog->jobQueue(jobs[i].type, jobs[i].typeName); json::Value const jqCounters{perfLog->countersJson()[jss::job_queue]}; BEAST_EXPECT(jqCounters.size() == i + 2); @@ -581,7 +581,8 @@ public: // be half as many queued as started... for (int i = 0; i < jobs.size(); ++i) { - perfLog->jobStart(jobs[i].type, microseconds{i + 1}, steady_clock::now(), i * 2); + perfLog->jobStart( + jobs[i].type, jobs[i].typeName, microseconds{i + 1}, steady_clock::now(), i * 2); std::this_thread::sleep_for(microseconds(10)); // Check each jobType counter entry. @@ -623,7 +624,8 @@ public: BEAST_EXPECT(total[jss::running_duration_us] == "0"); } - perfLog->jobStart(jobs[i].type, microseconds{0}, steady_clock::now(), (i * 2) + 1); + perfLog->jobStart( + jobs[i].type, jobs[i].typeName, microseconds{0}, steady_clock::now(), (i * 2) + 1); std::this_thread::sleep_for(microseconds{10}); // Verify that every entry in jobs appears twice in currents. @@ -651,7 +653,7 @@ public: // A number of the computations in this loop care about the // number of jobs that have finished. Make that available. int const finished = ((jobs.size() - i) * 2) - 1; - perfLog->jobFinish(jobs[i].type, microseconds(finished), (i * 2) + 1); + perfLog->jobFinish(jobs[i].type, jobs[i].typeName, microseconds(finished), (i * 2) + 1); std::this_thread::sleep_for(microseconds(10)); json::Value const jqCounters{perfLog->countersJson()[jss::job_queue]}; @@ -697,7 +699,7 @@ public: BEAST_EXPECT(jsonToUInt64(total[jss::running_duration_us]) == runningDur); } - perfLog->jobFinish(jobs[i].type, microseconds(finished + 1), (i * 2)); + perfLog->jobFinish(jobs[i].type, jobs[i].typeName, microseconds(finished + 1), (i * 2)); std::this_thread::sleep_for(microseconds(10)); // Verify that the two jobs we just finished no longer appear in @@ -891,25 +893,25 @@ public: }; // Start an ID that's too large. - perfLog->jobStart(jobType, microseconds{11}, steady_clock::now(), 2); + perfLog->jobStart(jobType, jobTypeName, microseconds{11}, steady_clock::now(), 2); std::this_thread::sleep_for(microseconds{10}); verifyCounters(perfLog->countersJson(), 1, 0, 11, 0); verifyEmptyCurrent(perfLog->currentJson()); // Start a negative ID - perfLog->jobStart(jobType, microseconds{13}, steady_clock::now(), -1); + perfLog->jobStart(jobType, jobTypeName, microseconds{13}, steady_clock::now(), -1); std::this_thread::sleep_for(microseconds{10}); verifyCounters(perfLog->countersJson(), 2, 0, 24, 0); verifyEmptyCurrent(perfLog->currentJson()); // Finish the too large ID - perfLog->jobFinish(jobType, microseconds{17}, 2); + perfLog->jobFinish(jobType, jobTypeName, microseconds{17}, 2); std::this_thread::sleep_for(microseconds{10}); verifyCounters(perfLog->countersJson(), 2, 1, 24, 17); verifyEmptyCurrent(perfLog->currentJson()); // Finish the negative ID - perfLog->jobFinish(jobType, microseconds{19}, -1); + perfLog->jobFinish(jobType, jobTypeName, microseconds{19}, -1); std::this_thread::sleep_for(microseconds{10}); verifyCounters(perfLog->countersJson(), 2, 2, 24, 36); verifyEmptyCurrent(perfLog->currentJson()); diff --git a/src/test/core/JobQueue_test.cpp b/src/test/core/JobQueue_test.cpp index aa6a0d60a8..2f262282dc 100644 --- a/src/test/core/JobQueue_test.cpp +++ b/src/test/core/JobQueue_test.cpp @@ -1,14 +1,307 @@ #include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include #include +#include #include #include +#include +#include +#include +#include #include +#include +#include +#include +#include +#include +#include #include +#include +#include +#include +#include +#include namespace xrpl::test { +namespace { + +/** + * A beast::insight::Collector that remembers the last value set on every + * gauge it created, keyed by gauge name. + * + * Needed because the production collectors are write-only sinks: StatsD + * sends over UDP and NullCollector discards. `JobQueue::collect()` assigns + * to the per-job-type gauges, so the only way to assert on the published + * values in-process is to supply a Collector that keeps them. + * + * RecordingCollector (Collector) + * | makeGauge(name) + * v + * RecordingGaugeImpl (GaugeImpl) --writes--> Values (shared, mutex-guarded) + * ^ ^ + * | | + * JobQueue::collect() assigns gaugeValue(name) reads + * + * Only gauges are recorded; counters, events, meters and hooks get inert + * implementations, because no assertion here needs them. The hook handler is + * kept so the test can invoke the collection pass on demand rather than + * waiting for a collector's own timer -- that makes the reads deterministic. + * + * @note Thread-safe: the value map is guarded by its own mutex, because + * `JobQueue::collect()` may run on a different thread from the assertions. + */ +class RecordingCollector : public beast::insight::Collector +{ +public: + /** + * Shared storage so gauge handles outliving the collector stay valid. + */ + struct Values + { + std::mutex mutex; + std::map gauges; + }; + +private: + /** + * A gauge that writes each assigned value into the shared map. + */ + class RecordingGaugeImpl : public beast::insight::GaugeImpl + { + std::shared_ptr values_; + std::string name_; + + public: + RecordingGaugeImpl(std::shared_ptr values, std::string name) + : values_(std::move(values)), name_(std::move(name)) + { + } + + void + set(value_type value) override + { + std::scoped_lock const lock(values_->mutex); + values_->gauges[name_] = value; + } + + void + increment(difference_type amount) override + { + std::scoped_lock const lock(values_->mutex); + values_->gauges[name_] += static_cast(amount); + } + }; + + /** @{ */ + /** + * Inert implementations for the metric kinds no assertion reads. + */ + class InertCounterImpl : public beast::insight::CounterImpl + { + void + increment(value_type) override + { + } + }; + + class InertEventImpl : public beast::insight::EventImpl + { + void + notify(value_type const&) override + { + } + }; + + class InertMeterImpl : public beast::insight::MeterImpl + { + void + increment(value_type) override + { + } + }; + + /** + * A hook that owns its handler, so releasing the Hook releases the + * handler with it. + * + * The collector holds only a weak reference (see `hooks_`). That + * reproduces the documented beast::insight lifetime rule -- "when the + * last reference goes away, the metric is no longer collected" -- and + * matters here because `JobQueue::~JobQueue()` unhooks by assigning an + * empty Hook. A collector holding the handler strongly would keep + * calling back into a destroyed JobQueue. + */ + class InertHookImpl : public beast::insight::HookImpl + { + public: + explicit InertHookImpl(HandlerType handler) : handler_(std::move(handler)) + { + } + + void + invoke() const + { + if (handler_) + handler_(); + } + + private: + HandlerType handler_; + }; + /** @} */ + + std::shared_ptr values_{std::make_shared()}; + std::vector> hooks_; + +public: + beast::insight::Hook + makeHook(beast::insight::HookImpl::HandlerType const& handler) override + { + auto impl = std::make_shared(handler); + hooks_.push_back(impl); + return beast::insight::Hook(std::move(impl)); + } + + beast::insight::Counter + makeCounter(std::string const&) override + { + return beast::insight::Counter(std::make_shared()); + } + + beast::insight::Event + makeEvent(std::string const&) override + { + return beast::insight::Event(std::make_shared()); + } + + beast::insight::Gauge + makeGauge(std::string const& name) override + { + return beast::insight::Gauge(std::make_shared(values_, name)); + } + + beast::insight::Meter + makeMeter(std::string const&) override + { + return beast::insight::Meter(std::make_shared()); + } + + /** + * Run every still-live hook, i.e. force one collection pass. + * + * Expired hooks are skipped rather than resurrected, so calling this + * after the JobQueue has been destroyed is a no-op instead of a + * use-after-free. + */ + void + runHooks() const + { + for (auto const& weak : hooks_) + { + if (auto const hook = weak.lock()) + hook->invoke(); + } + } + + /** + * The last value published for @p name. + * + * @return The value, or std::nullopt when no gauge of that name has + * ever been written -- which distinguishes "gauge absent" from + * "gauge present and reading zero". + */ + [[nodiscard]] std::optional + gaugeValue(std::string const& name) const + { + std::scoped_lock const lock(values_->mutex); + auto const iter = values_->gauges.find(name); + if (iter == values_->gauges.end()) + return std::nullopt; + return iter->second; + } +}; + +/** + * A perf::PerfLog that ignores everything. + * + * JobQueue requires a PerfLog reference; these tests assert on gauges, not + * on the perf hooks, so every override is empty. + */ +class SilentPerfLog : public perf::PerfLog +{ + void + rpcStart(std::string const&, std::uint64_t) override + { + } + void + rpcFinish(std::string const&, std::uint64_t) override + { + } + void + rpcError(std::string const&, std::uint64_t) override + { + } + void + jobQueue(JobType, std::string const&) override + { + } + void + jobStart( + JobType, + std::string const&, + std::chrono::microseconds, + std::chrono::time_point, + int) override + { + } + void + jobFinish(JobType, std::string const&, std::chrono::microseconds, int) override + { + } + [[nodiscard]] json::Value + countersJson() const override + { + return json::Value(); + } + [[nodiscard]] json::Value + currentJson() const override + { + return json::Value(); + } + void + resizeJobs(int) override + { + } + void + rotate() override + { + } +}; + +// Gauge-name suffixes. Aliased from JobTypeData rather than re-spelled, so a +// rename there fails here instead of silently asserting on a stale name. +/** @{ */ +constexpr auto& kSuffixWaiting = JobTypeData::kSuffixWaiting; +constexpr auto& kSuffixRunning = JobTypeData::kSuffixRunning; +constexpr auto& kSuffixDeferred = JobTypeData::kSuffixDeferred; +/** @} */ + +} // namespace + //------------------------------------------------------------------------------ class JobQueue_test : public beast::unit_test::Suite @@ -130,12 +423,298 @@ class JobQueue_test : public beast::unit_test::Suite } } + //-------------------------------------------------------------------------- + // Per-job-type saturation gauges (waiting / running / deferred) + //-------------------------------------------------------------------------- + + /** + * Owns a JobQueue wired to a RecordingCollector. + * + * A standalone JobQueue rather than `env.app().getJobQueue()`, for two + * reasons: the application's queue uses a write-only collector whose + * gauge values cannot be read back, and it carries background jobs whose + * timing would make exact counts unreproducible. Constructed with the + * given thread count so a concurrency limit can be exceeded on demand. + */ + struct GaugeFixture + { + Logs logs{beast::Severity::Disabled}; + SilentPerfLog perfLog; + std::shared_ptr collector{std::make_shared()}; + JobQueue queue; + + explicit GaugeFixture(int threadCount) + : queue(threadCount, collector, logs.journal("JobQueue"), logs, perfLog) + { + } + + /** + * Publish one collection pass, then read a gauge by job type. + */ + [[nodiscard]] std::optional + read(JobType type, char const* suffix) const + { + collector->runHooks(); + return collector->gaugeValue(JobTypes::name(type) + suffix); + } + }; + + /** + * A gauge exists for a limited job type and not for a special one. + * + * Creation is observed through the RecordingCollector: a name no gauge + * was created for is absent from its value map even after a collection + * pass, whereas a created one is present. That distinguishes "never + * created" from "created and reading 0", which a value check alone + * cannot. + */ + void + testGaugeCreation() + { + testcase("Saturation gauge creation"); + + GaugeFixture fixture(1); + + // JtLedgerReq has limit 3, so it is not special and must be gauged. + BEAST_EXPECT(!JobTypes::instance().get(JtLedgerReq).special()); + BEAST_EXPECT(JobTypes::instance().get(JtLedgerReq).limit() == 3); + BEAST_EXPECT(fixture.read(JtLedgerReq, kSuffixWaiting).has_value()); + BEAST_EXPECT(fixture.read(JtLedgerReq, kSuffixRunning).has_value()); + BEAST_EXPECT(fixture.read(JtLedgerReq, kSuffixDeferred).has_value()); + + // A quiescent queue publishes exactly zero, not "no value". + BEAST_EXPECT(fixture.read(JtLedgerReq, kSuffixWaiting) == 0u); + BEAST_EXPECT(fixture.read(JtLedgerReq, kSuffixRunning) == 0u); + BEAST_EXPECT(fixture.read(JtLedgerReq, kSuffixDeferred) == 0u); + + // JtPeer is special (limit_ == 0) and must have no gauges at all. + BEAST_EXPECT(JobTypes::instance().get(JtPeer).special()); + BEAST_EXPECT(JobTypes::instance().get(JtPeer).limit() == 0); + BEAST_EXPECT(!fixture.read(JtPeer, kSuffixWaiting).has_value()); + BEAST_EXPECT(!fixture.read(JtPeer, kSuffixRunning).has_value()); + BEAST_EXPECT(!fixture.read(JtPeer, kSuffixDeferred).has_value()); + } + + /** + * Driving a capped type past its limit reports exact running and + * deferred counts, and deferred returns to exactly 0 once drained. + * + * JtPack is used because its limit is 1, which makes both figures + * unambiguous: with the single slot occupied by a job that blocks until + * released, every further submission must defer. + */ + void + testDeferredGaugeExactValues() + { + testcase("Saturation gauge deferred counts"); + + int const limit = JobTypes::instance().get(JtPack).limit(); + BEAST_EXPECT(limit == 1); + + // More threads than the type's limit, so `running` is capped by the + // job type rather than by thread availability. + GaugeFixture fixture(4); + + // The first job blocks inside doJob() until released, holding the + // one slot. `entered` proves it really is running before the + // remaining jobs are submitted. + std::mutex mutex; + std::condition_variable cv; + bool release = false; + int entered = 0; + + auto blockingJob = [&]() { + std::unique_lock lock(mutex); + ++entered; + cv.notify_all(); + cv.wait(lock, [&release] { return release; }); + }; + + BEAST_EXPECT(fixture.queue.addJob(JtPack, "GaugeHold", blockingJob)); + { + std::unique_lock lock(mutex); + BEAST_EXPECT( + cv.wait_for(lock, std::chrono::seconds(10), [&entered] { return entered == 1; })); + } + + // Every one of these must defer: the limit is already reached. + int const extra = 4; + for (int i = 0; i < extra; ++i) + BEAST_EXPECT(fixture.queue.addJob(JtPack, "GaugeDefer", blockingJob)); + + // Exact values, not bounds: `running` equals the type's limit and + // `deferred` equals the number of submissions beyond it. Both are + // deterministic here because no JtPack job can complete until + // `release` is set. + BEAST_EXPECT(fixture.read(JtPack, kSuffixRunning) == static_cast(limit)); + BEAST_EXPECT(fixture.read(JtPack, kSuffixDeferred) == static_cast(extra)); + + // `waiting` counts everything submitted and not yet started, which + // is the deferred jobs -- the running one was decremented when + // getNextJob() picked it up. + BEAST_EXPECT(fixture.read(JtPack, kSuffixWaiting) == static_cast(extra)); + + // Cross-check against the public accessors, so a gauge that silently + // published a stale or unrelated number would be caught. + BEAST_EXPECT(fixture.queue.getJobCount(JtPack) == extra); + BEAST_EXPECT(fixture.queue.getJobCountTotal(JtPack) == extra + limit); + + // Release everything and drain. + { + std::scoped_lock const lock(mutex); + release = true; + } + cv.notify_all(); + fixture.queue.stop(); + BEAST_EXPECT(fixture.queue.isStopped()); + + // All five jobs ran, so the backlog is gone: deferred is exactly 0, + // and so are waiting and running. + BEAST_EXPECT(entered == extra + limit); + BEAST_EXPECT(fixture.read(JtPack, kSuffixDeferred) == 0u); + BEAST_EXPECT(fixture.read(JtPack, kSuffixWaiting) == 0u); + BEAST_EXPECT(fixture.read(JtPack, kSuffixRunning) == 0u); + } + + /** + * Negative path: an uncapped job type never reports non-zero deferred. + * + * JtClient's limit is std::numeric_limits::max(), so + * `addRefCountedJob()` can never take the `++data.deferred` branch. The + * gauge must therefore read exactly 0 both while jobs are in flight and + * after the queue drains -- otherwise a dashboard would attribute + * backpressure to a type that cannot experience it. + */ + void + testUncappedTypeNeverDefers() + { + testcase("Saturation gauge uncapped type"); + + int const limit = JobTypes::instance().get(JtClient).limit(); + BEAST_EXPECT(limit == std::numeric_limits::max()); + BEAST_EXPECT(!JobTypes::instance().get(JtClient).special()); + + // One thread, so submissions greatly outnumber the workers that can + // service them. Under a capped type this would defer; here it must + // not, which is what separates "waiting" from "deferred". + GaugeFixture fixture(1); + + std::mutex mutex; + std::condition_variable cv; + bool release = false; + int entered = 0; + + int const jobs = 6; + for (int i = 0; i < jobs; ++i) + { + BEAST_EXPECT(fixture.queue.addJob(JtClient, "GaugeUncapped", [&]() { + std::unique_lock lock(mutex); + ++entered; + cv.notify_all(); + cv.wait(lock, [&release] { return release; }); + })); + } + + // At least one job is in flight and the rest are backlogged, yet + // deferred stays at exactly 0 because the type has no limit. + { + std::unique_lock lock(mutex); + BEAST_EXPECT( + cv.wait_for(lock, std::chrono::seconds(10), [&entered] { return entered >= 1; })); + } + BEAST_EXPECT(fixture.read(JtClient, kSuffixDeferred) == 0u); + + { + std::scoped_lock const lock(mutex); + release = true; + } + cv.notify_all(); + fixture.queue.stop(); + + BEAST_EXPECT(entered == jobs); + BEAST_EXPECT(fixture.read(JtClient, kSuffixDeferred) == 0u); + BEAST_EXPECT(fixture.read(JtClient, kSuffixWaiting) == 0u); + BEAST_EXPECT(fixture.read(JtClient, kSuffixRunning) == 0u); + } + + /** + * Exactly the non-special job types are gauged, three gauges each, and + * every published value is non-negative. + * + * The coverage half pins the cardinality the metric family adds: one + * gauge per non-special type per counter and none for special types, so + * a job type gaining or losing a limit shows up here. + * + * The non-negativity half is the observable consequence of the clamp in + * `collect()`. The clamp itself cannot be triggered from a test: it + * guards `waiting` / `running` / `deferred`, which are private to + * JobQueue and only ever incremented and decremented in matched pairs, + * so forcing one negative would need the internals hacked. What is + * assertable is the property the clamp exists to guarantee -- since + * `Gauge::value_type` is unsigned, an unclamped negative would surface + * as a value near 2^64 rather than as a small number, which is exactly + * what the upper bound below rules out. + */ + void + testGaugeCoverageAndNonNegative() + { + testcase("Saturation gauge coverage"); + + GaugeFixture fixture(1); + fixture.collector->runHooks(); + + // Sanity-check the fixture against the job-type table itself, so the + // expected counts are derived rather than hard-coded. + int nonSpecial = 0; + int special = 0; + int gauges = 0; + bool allSmall = true; + + // No job has been submitted, so every published value must be 0. + // The bound is deliberately generous: it is here to catch an + // unsigned wrap, not to re-assert the exact zero above. + auto const kWrapGuard = static_cast(1) << 32; + + for (auto const& [type, info] : JobTypes::instance()) + { + if (type == JtInvalid) + continue; + + info.special() ? ++special : ++nonSpecial; + + for (char const* suffix : {kSuffixWaiting, kSuffixRunning, kSuffixDeferred}) + { + auto const value = fixture.collector->gaugeValue(info.name() + suffix); + + // Presence must agree with speciality, in both directions. + BEAST_EXPECT(value.has_value() == !info.special()); + if (!value) + continue; + + ++gauges; + if (*value >= kWrapGuard) + allSmall = false; + BEAST_EXPECT(*value == 0u); + } + } + + BEAST_EXPECT(nonSpecial == 35); + BEAST_EXPECT(special == 11); + BEAST_EXPECT(gauges == nonSpecial * 3); + BEAST_EXPECT(gauges == 105); + BEAST_EXPECT(allSmall); + } + public: void run() override { testAddJob(); testPostCoro(); + testGaugeCreation(); + testGaugeCoverageAndNonNegative(); + testDeferredGaugeExactValues(); + testUncappedTypeNeverDefers(); } }; diff --git a/src/test/core/Workers_test.cpp b/src/test/core/Workers_test.cpp index fe3820b84a..102f5df14d 100644 --- a/src/test/core/Workers_test.cpp +++ b/src/test/core/Workers_test.cpp @@ -36,13 +36,14 @@ class PerfLogTest : public PerfLog } void - jobQueue(JobType const type) override + jobQueue(JobType const type, std::string const& name) override { } void jobStart( JobType const type, + std::string const& name, std::chrono::microseconds dur, std::chrono::time_point startTime, int instance) override @@ -50,7 +51,11 @@ class PerfLogTest : public PerfLog } void - jobFinish(JobType const type, std::chrono::microseconds dur, int instance) override + jobFinish( + JobType const type, + std::string const& name, + std::chrono::microseconds dur, + int instance) override { } diff --git a/src/test/overlay/TMGetObjectByHash_test.cpp b/src/test/overlay/TMGetObjectByHash_test.cpp index e579989181..b0e3b70dfa 100644 --- a/src/test/overlay/TMGetObjectByHash_test.cpp +++ b/src/test/overlay/TMGetObjectByHash_test.cpp @@ -20,7 +20,9 @@ #include #include #include +#include #include +#include #include #include @@ -33,6 +35,9 @@ #include #include +#include +#include +#include #include #include @@ -100,6 +105,50 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite return lastSentMessage_; } + /** + * Capture the charge the handler applies, then apply it for real. + * + * `Peer::charge()` is pure virtual and `processGetObjectByHash()` + * calls it unqualified, so this override sees the exact + * `Resource::Charge` the handler built -- the same object passed to + * `computeGetObjectByHashFee()`'s caller. That makes the handler's + * *choice of argument* observable, which reading `fee_` or calling + * the pricing helper with the test's own arguments cannot do. + * + * Recorded before forwarding so the base-class strand hop cannot + * reorder the observation; forwarding keeps the production + * disconnect/accounting behaviour intact. + */ + void + charge(Resource::Charge const& fee, std::string const& context) override + { + lastAppliedCharge_ = fee; + lastChargeContext_ = context; + PeerImp::charge(fee, context); + } + + /** + * The charge captured by the override above, or nullopt if none. + * + * `Resource::Charge` has no default constructor, so the optional + * also distinguishes "not charged at all" from "charged zero" -- + * a distinction the rejection-gate tests depend on. + */ + [[nodiscard]] std::optional const& + getLastAppliedCharge() const + { + return lastAppliedCharge_; + } + + /** + * The context string that accompanied the captured charge. + */ + [[nodiscard]] std::string const& + getLastChargeContext() const + { + return lastChargeContext_; + } + // Synchronous test access to the JobQueue-dispatched processor. // The production path runs this on JtLedgerReq; tests need a // synchronous entry point to inspect the reply via send(). @@ -111,6 +160,25 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite processGetObjectByHash(m); } + // Read the accumulated per-message charge. `currentFeeCharge()` is + // protected on PeerImp; exposed here because it is the one + // deterministic, same-thread witness that a rejection gate fired -- + // `charge()` itself dispatches to the peer's strand. + [[nodiscard]] Resource::Charge + peekFeeCharge() const + { + return currentFeeCharge(); + } + + // The differential-pricing helper, so a test can compare the charge + // applied by the handler against the helper's own result for the + // same inputs. Static and protected on PeerImp. + [[nodiscard]] static Resource::Charge + peekComputeFee(int const requested, int const found) + { + return computeGetObjectByHashFee(requested, found); + } + static void resetId() { @@ -119,12 +187,55 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite private: inline static Peer::id_t id = 0; + + /** + * The last message handed to send(). + * + * @note Not synchronised. When the handler runs on a JobQueue + * worker (the `onMessage()` tests), this is written on that worker + * and read on the test thread, so every such test must call + * `env.app().getJobQueue().rendezvous()` before reading it. The + * rendezvous supplies the happens-before edge: the worker's + * `--processCount_` under `mutex_` in `JobQueue::processTask()` + * releases, and the waiter's predicate acquires the same mutex. + * Tests that drive `runProcessGetObjectByHash()` directly run + * wholly on the test thread and need no rendezvous. + */ std::shared_ptr lastSentMessage_; + + /** + * @see getLastAppliedCharge(). Same threading rules as above. + */ + std::optional lastAppliedCharge_; + + /** + * @see getLastChargeContext(). Same threading rules as above. + */ + std::string lastChargeContext_; }; shared_context context_{makeSslContext("")}; ProtocolVersion protocolVersion_{1, 7}; + /** + * Seed offset for hashes that must NOT be present in the NodeStore. + * + * `createRequest()` stores `sha512Half(i)` for i in [0, numObjects), and + * numObjects can reach kHardMaxReplyNodes. Offsetting well past that + * keeps "unstored" hashes genuinely absent. + */ + static constexpr int kUnstoredHashSeed = 1'000'000; + + /** + * Build a live PeerTest registered with the overlay. + * + * @note `overlay.addActive()` stores only `std::weak_ptr`s + * (`OverlayImpl::peers_`, `ids_` and `list_` are all weak), so it does + * *not* keep the peer alive. The returned `shared_ptr` is the sole + * owner; keep it in scope for the whole test. Safety for the + * JobQueue-dispatched path comes from the job lambda locking its own + * `weak_ptr` plus the `rendezvous()` each such test performs. + */ std::shared_ptr createPeer(jtx::Env& env) { @@ -187,6 +298,27 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite return request; } + /** + * Parse the reply captured by PeerTest::send(). + * + * @return The decoded message, or std::nullopt when nothing was sent. + */ + std::optional + parseReply(std::shared_ptr const& peer) + { + auto const sentMessage = peer->getLastSentMessage(); + if (!sentMessage) + return std::nullopt; + + auto const& buffer = sentMessage->getBuffer(compression::Compressed::Off); + BEAST_EXPECT(buffer.size() > 6); + + // Skip the 6-byte message header (4 size + 2 type). + protocol::TMGetObjectByHash reply; + BEAST_EXPECT(reply.ParseFromArray(buffer.data() + 6, buffer.size() - 6) == true); + return reply; + } + /** * Test that reply is limited to hardMaxReplyNodes when more objects * are requested than the limit allows. @@ -209,28 +341,675 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite peer->runProcessGetObjectByHash(request); // Verify that a reply was sent - auto sentMessage = peer->getLastSentMessage(); - BEAST_EXPECT(sentMessage != nullptr); - - // Parse the reply message - auto const& buffer = sentMessage->getBuffer(compression::Compressed::Off); - - BEAST_EXPECT(buffer.size() > 6); - // Skip the message header (6 bytes: 4 for size, 2 for type) - protocol::TMGetObjectByHash reply; - BEAST_EXPECT(reply.ParseFromArray(buffer.data() + 6, buffer.size() - 6) == true); + auto reply = parseReply(peer); + BEAST_EXPECT(reply.has_value()); + if (!reply) + return; // Verify the reply is limited to expectedReplySize - BEAST_EXPECT(reply.objects_size() == expectedReplySize); + BEAST_EXPECT(reply->objects_size() == expectedReplySize); + } + + //-------------------------------------------------------------------------- + // Request-gate rejection paths + //-------------------------------------------------------------------------- + + /** + * Build a query request with @p numObjects hashes and nothing stored. + * + * Distinct from `createRequest()`, which writes every hash to the + * NodeStore. The rejection gates return before any NodeStore access, so + * storing 12289 objects to test them would cost real time and prove + * nothing. Hashes are derived from the index but need not resolve. + * + * @param numObjects Objects to place in the request. + * @param type Message type; must not be otFETCH_PACK or + * otTRANSACTIONS, both of which are intercepted by + * earlier branches of onMessage(). + */ + static std::shared_ptr + createUnstoredRequest( + int const numObjects, + protocol::TMGetObjectByHash::ObjectType const type = + protocol::TMGetObjectByHash_ObjectType_otLEDGER) + { + auto request = std::make_shared(); + request->set_type(type); + request->set_query(true); + + for (int i = 0; i < numObjects; ++i) + { + // Offset the seed so these hashes cannot collide with the ones + // createRequest() stores, keeping "unstored" unambiguous. + uint256 const hash(xrpl::sha512Half(i + kUnstoredHashSeed)); + auto* object = request->add_objects(); + object->set_hash(hash.data(), hash.size()); + } + return request; + } + + /** + * An oversized request is refused with no reply and an exact fee. + * + * This is the gate that `getobject_rejected_total{reason="oversize"}` + * counts. The counter itself is not readable in-process (see the note + * on run()), so the assertions are on the two observable effects of the + * same early return: no message was sent, and `fee_` holds exactly + * `kFeeInvalidData`. + */ + void + testOversizeRejection() + { + testcase("Oversize Rejection"); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + // Successful-setup assertion: a fresh peer starts at the trivial + // fee, so the post-condition below can only come from this call. + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeTrivialPeer.cost()); + BEAST_EXPECT(peer->getLastSentMessage() == nullptr); + + int const oversize = static_cast(Tuning::kHardMaxReplyNodes) + 1; + peer->onMessage(createUnstoredRequest(oversize)); + + // State: nothing was replied to, because the gate returns before + // the job is queued. + BEAST_EXPECT(peer->getLastSentMessage() == nullptr); + + // Cause: the charge is exactly the invalid-data fee, not merely + // "some larger fee". The label pins which gate fired -- the + // malformed-ledgerhash gate charges a different constant. + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeInvalidData.cost()); + BEAST_EXPECT(peer->peekFeeCharge().cost() == 400); + BEAST_EXPECT(peer->peekFeeCharge().label() == Resource::kFeeInvalidData.label()); + + // Negative path for the differential charge: the gate returns before + // the handler runs, so computeGetObjectByHashFee() is never reached + // and charge() is never called. Nothing was applied at all -- which + // the optional distinguishes from a zero-cost charge. + BEAST_EXPECT(!peer->getLastAppliedCharge().has_value()); + } + + /** + * Exactly at the limit the request is accepted, so the gate is a strict + * `>` and not `>=`. + * + * Negative control for testOversizeRejection: without it, a gate that + * rejected everything would pass that test. + */ + void + testAtLimitNotRejected() + { + testcase("At Limit Not Rejected"); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + int const atLimit = static_cast(Tuning::kHardMaxReplyNodes); + peer->onMessage(createUnstoredRequest(atLimit)); + + // Accepted: the request was queued, so the fee is the + // moderate-burden admission charge, not the invalid-data charge. + // + // `fee_.update()` for the admission charge runs on this thread, but + // the enqueued worker also writes the peer's reply. Drain the queue + // before reading anything so the observation cannot race the worker. + env.app().getJobQueue().rendezvous(); + + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeModerateBurdenPeer.cost()); + BEAST_EXPECT(peer->peekFeeCharge().cost() != Resource::kFeeInvalidData.cost()); + BEAST_EXPECT(peer->peekFeeCharge().cost() == 250); + + // The request was in bounds, so the worker ran and replied. Nothing + // was stored, so every lookup missed and the reply is empty. + auto reply = parseReply(peer); + BEAST_EXPECT(reply.has_value()); + if (reply) + BEAST_EXPECT(reply->objects_size() == 0); + + // Positive counterpart to the oversize test: because the handler did + // run, a differential charge was applied, and it is exactly the + // all-miss price for the full request size. + auto const& applied = peer->getLastAppliedCharge(); + BEAST_EXPECT(applied.has_value()); + if (applied) + { + BEAST_EXPECT(applied->cost() == PeerTest::peekComputeFee(atLimit, 0).cost()); + BEAST_EXPECT(applied->cost() == 99176); + } + } + + /** + * A wrong-sized ledgerhash is refused with no reply and an exact fee. + * + * This is the gate `getobject_rejected_total{reason="malformed_ledgerhash"}` + * counts. `stringIsUInt256Sized` requires exactly `uint256::size()` + * bytes, so both a short and a long hash must be refused; a test using + * only one would miss an off-by-one in either direction. + * + * @param hashSize Byte length of the malformed ledgerhash. + */ + void + testMalformedLedgerHashRejection(std::size_t const hashSize) + { + testcase("Malformed LedgerHash Rejection: " + std::to_string(hashSize) + " bytes"); + + BEAST_EXPECT(hashSize != uint256::size()); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeTrivialPeer.cost()); + + // Small in-bounds object count, so this can only be the ledgerhash + // gate: the oversize gate is checked afterwards and cannot fire. + auto request = createUnstoredRequest(1); + request->set_ledgerhash(std::string(hashSize, 'x')); + peer->onMessage(request); + + BEAST_EXPECT(peer->getLastSentMessage() == nullptr); + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeMalformedRequest.cost()); + BEAST_EXPECT(peer->peekFeeCharge().cost() == 200); + BEAST_EXPECT(peer->peekFeeCharge().label() == Resource::kFeeMalformedRequest.label()); + + // Negative path: the gate returns before the handler, so no + // differential charge was ever applied. + BEAST_EXPECT(!peer->getLastAppliedCharge().has_value()); + } + + /** + * A correctly sized ledgerhash passes the gate. + * + * Negative control for testMalformedLedgerHashRejection. + */ + void + testWellFormedLedgerHashAccepted() + { + testcase("Well-Formed LedgerHash Accepted"); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + auto request = createUnstoredRequest(1); + uint256 const ledgerHash(xrpl::sha512Half(0)); + BEAST_EXPECT(ledgerHash.size() == uint256::size()); + request->set_ledgerhash(ledgerHash.data(), ledgerHash.size()); + peer->onMessage(request); + + // Drain the enqueued worker before observing, as in + // testAtLimitNotRejected. + env.app().getJobQueue().rendezvous(); + + // Not the malformed charge: the request was admitted. + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeModerateBurdenPeer.cost()); + BEAST_EXPECT(peer->peekFeeCharge().cost() != Resource::kFeeMalformedRequest.cost()); + BEAST_EXPECT(peer->peekFeeCharge().cost() == 250); + + // A reply was produced, and it echoes the request's ledgerhash. + auto reply = parseReply(peer); + BEAST_EXPECT(reply.has_value()); + if (reply) + { + BEAST_EXPECT(reply->has_ledgerhash()); + BEAST_EXPECT(reply->ledgerhash() == request->ledgerhash()); + } + } + + //-------------------------------------------------------------------------- + // Hit / miss split and charge + //-------------------------------------------------------------------------- + + /** + * Build a request that interleaves stored and unstored hashes. + * + * One of each is taken in turn until a side runs out, then whichever + * side remains is drained. Interleaving matters: a handler that stopped + * at the first miss would return fewer objects than expected, which a + * stored-then-unstored layout could hide. + * + * Asserts on its own setup, so a miscount here is reported at this call + * rather than as a confusing reply-size failure later. + * + * @param env Environment whose NodeStore receives the writes. + * @param numStored Hashes written to the NodeStore, i.e. hits. + * @param numUnstored Hashes left absent, i.e. misses. + * @param storedHashes Out-param populated with the stored hashes. + * @return The assembled request. + */ + std::shared_ptr + buildInterleavedRequest( + Env& env, + int const numStored, + int const numUnstored, + std::set& storedHashes) + { + auto& nodeStore = env.app().getNodeStore(); + + auto request = std::make_shared(); + request->set_type(protocol::TMGetObjectByHash_ObjectType_otLEDGER); + request->set_query(true); + + int stored = 0; + int unstored = 0; + for (int i = 0; i < numStored + numUnstored; ++i) + { + // Alternate while both remain; then drain whichever is left. + bool const takeStored = + (stored < numStored) && (unstored >= numUnstored || (i % 2) == 0); + + uint256 const hash( + xrpl::sha512Half(takeStored ? stored : unstored + kUnstoredHashSeed)); + + if (takeStored) + { + Blob data(100, static_cast(stored % 256)); + nodeStore.store( + NodeObjectType::Ledger, std::move(data), hash, nodeStore.earliestLedgerSeq()); + BEAST_EXPECT(storedHashes.insert(hash).second); + ++stored; + } + else + { + ++unstored; + } + + auto* object = request->add_objects(); + object->set_hash(hash.data(), hash.size()); + } + + // Setup assertions: the mix is exactly what was asked for. + BEAST_EXPECT(stored == numStored); + BEAST_EXPECT(unstored == numUnstored); + BEAST_EXPECT(storedHashes.size() == static_cast(numStored)); + BEAST_EXPECT(request->objects_size() == numStored + numUnstored); + + return request; + } + + /** + * Every replied object is a distinct hash drawn from @p storedHashes. + * + * Without the distinctness check a handler that returned the same hit + * twice would still satisfy a reply-size assertion. + * + * @param reply The decoded reply. + * @param storedHashes The hashes that were written to the NodeStore. + * @param numStored Expected number of distinct returned hashes. + */ + void + verifyReplyObjects( + protocol::TMGetObjectByHash const& reply, + std::set const& storedHashes, + int const numStored) + { + std::set returned; + for (int i = 0; i < reply.objects_size(); ++i) + { + auto const& obj = reply.objects(i); + BEAST_EXPECT(obj.hash().size() == uint256::size()); + BEAST_EXPECT(returned.insert(uint256::fromRaw(obj.hash())).second); + BEAST_EXPECT(storedHashes.contains(uint256::fromRaw(obj.hash()))); + } + BEAST_EXPECT(returned.size() == static_cast(numStored)); + } + + /** + * A mixed request returns exactly the stored objects and nothing else. + * + * This is the split `getobject_lookups_total{result=hit|miss}` records: + * the handler derives the miss count as `requested - found`, so an + * exact reply size is exactly the hit count the metric would report. + * + * @param numStored Hashes written to the NodeStore before the call. + * @param numUnstored Hashes that will miss. + */ + void + testHitMissSplit(int const numStored, int const numUnstored) + { + testcase( + "Hit/Miss Split: " + std::to_string(numStored) + " stored, " + + std::to_string(numUnstored) + " unstored"); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + std::set storedHashes; + auto request = buildInterleavedRequest(env, numStored, numUnstored, storedHashes); + + int const requested = numStored + numUnstored; + peer->runProcessGetObjectByHash(request); + + auto reply = parseReply(peer); + BEAST_EXPECT(reply.has_value()); + if (!reply) + return; + + // The exact hit count. Every stored hash is returned and no + // unstored one is, so hits == numStored and the derived miss count + // is exactly numUnstored. + BEAST_EXPECT(reply->objects_size() == numStored); + BEAST_EXPECT(requested - reply->objects_size() == numUnstored); + + verifyReplyObjects(*reply, storedHashes, numStored); + + // Cause: the value recorded as getobject_charge is exactly the + // charge the handler applied, captured by PeerTest::charge(). + auto const& applied = peer->getLastAppliedCharge(); + BEAST_EXPECT(applied.has_value()); + if (!applied) + return; + BEAST_EXPECT(applied->cost() == PeerTest::peekComputeFee(requested, numStored).cost()); + BEAST_EXPECT(applied->label() == "GetObject differential"); + + // These request sizes are all within kFreeObjectsPerRequest, so the + // charge is exactly zero regardless of the split. Asserted rather + // than assumed: it is why this test does not also pin a non-trivial + // fee -- testComputeFeeExactValues covers the billable bands. + BEAST_EXPECT(requested <= static_cast(Tuning::kFreeObjectsPerRequest)); + BEAST_EXPECT(applied->cost() == 0); + + // `fee_` is untouched on this path: the handler charges through + // charge(), never through fee_.update(). + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeTrivialPeer.cost()); + } + + /** + * One pricing case: inputs, the derived expectation, and the literal. + * + * Both expectations are kept. `derived` is written from the Tuning + * constants so a deliberate re-pricing needs one edit; `literal` is the + * number as of this branch so a re-pricing cannot pass unnoticed by + * being self-consistently wrong. + */ + struct FeeCase + { + /** + * Objects the peer asked for. + */ + int requested; + /** + * Objects that resolved in the NodeStore. + */ + int found; + /** + * Expectation computed from the Tuning constants. + */ + int derived; + /** + * The same value as a hard number. + */ + int literal; + /** + * Reported when the case fails. + */ + char const* why; + }; + + /** + * Assert computeGetObjectByHashFee() equals both expectations of a case. + * + * @param fc The case to check. + */ + void + checkFeeCase(FeeCase const& fc) + { + auto const cost = PeerTest::peekComputeFee(fc.requested, fc.found).cost(); + BEAST_EXPECTS(cost == fc.derived, fc.why); + BEAST_EXPECTS(cost == fc.literal, fc.why); + } + + /** + * The Tuning constants the fee expectations are built from. + * + * Verified against their literal values by testComputeFeeExactValues() + * so a silent re-pricing shows up as a failure there rather than as a + * self-consistent but wrong expectation in every case below. + */ + struct FeeConstants + { + int free{static_cast(Tuning::kFreeObjectsPerRequest)}; + int hit{static_cast(Tuning::kCostPerLookupHit)}; + int miss{static_cast(Tuning::kCostPerLookupMiss)}; + int bandSmall{static_cast(Tuning::kCostBandSmall)}; + int bandMedium{static_cast(Tuning::kCostBandMedium)}; + int bandLarge{static_cast(Tuning::kCostBandLarge)}; + int smallMax{static_cast(Tuning::kBandSmallMax)}; + int mediumMax{static_cast(Tuning::kBandMediumMax)}; + }; + + /** + * Every pricing case, in one table. + * + * @param k The Tuning constants to derive expectations from. + */ + static std::vector + makeFeeCases(FeeConstants const& k) + { + return { + // Wholly free: at or below the free allowance nothing is + // billable, so only the small size band applies -- which is 0. + {k.free, k.free, k.bandSmall, 0, "at the free allowance"}, + {0, 0, k.bandSmall, 0, "empty request"}, + {1, 1, k.bandSmall, 0, "one object, one hit"}, + + // All hits, one object past the allowance: one billable hit. + {k.free + 1, k.free + 1, k.hit + k.bandSmall, 1, "one billable hit"}, + + // All misses, one past the allowance: misses are billed first, + // so the single billable object is priced as a miss, not a hit. + {k.free + 1, 0, k.miss + k.bandSmall, 8, "one billable miss"}, + + // Mixed at the small-band edge: 64 requested, 32 found. + // Billable is 64-16 = 48; misses are 32 and all billable, + // leaving 16 billable hits. + {k.smallMax, + 32, + (16 * k.hit) + (32 * k.miss) + k.bandSmall, + 272, + "small-band edge, mixed"}, + + // One past the small band moves to the medium surcharge. + {k.smallMax + 1, + k.smallMax + 1, + ((k.smallMax + 1 - k.free) * k.hit) + k.bandMedium, + 149, + "first medium-band size"}, + + // The medium band's last size, then one past it, which moves to + // the large surcharge. + {k.mediumMax, + k.mediumMax, + ((k.mediumMax - k.free) * k.hit) + k.bandMedium, + 1108, + "last medium-band size"}, + {k.mediumMax + 1, + k.mediumMax + 1, + ((k.mediumMax + 1 - k.free) * k.hit) + k.bandLarge, + 2009, + "first large-band size"}, + + // Clamp: found > requested cannot make the miss count negative, + // so the fee is the same as the all-hit case (1). + {k.free + 1, k.free + 10, k.hit + k.bandSmall, 1, "found exceeds requested"}, + }; + } + + /** + * computeGetObjectByHashFee() returns exactly the documented value. + * + * The metric records the helper's result verbatim, so pinning the helper + * pins what `getobject_charge` reports. + */ + void + testComputeFeeExactValues() + { + testcase("Compute Fee Exact Values"); + + FeeConstants const k; + + // Verify the constants themselves, so a silent re-pricing shows up + // here rather than as a self-consistent but wrong expectation. + BEAST_EXPECT(k.free == 16); + BEAST_EXPECT(k.hit == 1); + BEAST_EXPECT(k.miss == 8); + BEAST_EXPECT(k.bandSmall == 0); + BEAST_EXPECT(k.bandMedium == 100); + BEAST_EXPECT(k.bandLarge == 1000); + BEAST_EXPECT(k.smallMax == 64); + BEAST_EXPECT(k.mediumMax == 1024); + + auto const cases = makeFeeCases(k); + BEAST_EXPECT(cases.size() == 10); + for (auto const& fc : cases) + checkFeeCase(fc); + + // A miss costs strictly more than a hit for the same request size. + // Relational, so it cannot be expressed as a table row. + BEAST_EXPECT( + PeerTest::peekComputeFee(k.free + 1, 0).cost() > + PeerTest::peekComputeFee(k.free + 1, k.free + 1).cost()); + + // The label is fixed, so a charge can be attributed to this helper. + BEAST_EXPECT(PeerTest::peekComputeFee(k.free + 1, 0).label() == "GetObject differential"); + } + + /** + * The charge the handler *applies* is priced on `requested`, not on the + * capped iteration count and not on `found`. + * + * Load-bearing because `getobject_charge` records the applied value: if + * `processGetObjectByHash()` priced on `iterLimit` -- i.e. + * `min(requested, kHardMaxReplyNodes)` -- the metric would under-report + * abusive batches by exactly the overshoot. + * + * The assertion is on `PeerTest::charge()`, which overrides the virtual + * the handler calls, so it observes the very `Resource::Charge` object + * the handler constructed. Two other candidate witnesses were rejected: + * - `fee_` / `peekFeeCharge()`: this path never touches `fee_`, it + * goes through `charge()`. + * - `usage_.balance()`: `Entry::add()` returns + * `localBalance.add(...) + remoteBalance` and `DecayingSample::add()` + * returns `value_ / Window` with `Window == kDecayWindowSeconds == + * 32`, so the balance is the applied cost divided by 32 with integer + * truncation. 99184 / 32 and 99176 / 32 are both 3099, so the + * balance cannot distinguish the mutation this test exists to catch. + * It also decays with wall-clock time (`BasicSecondsClock`), making + * any exact expectation racy. + */ + void + testChargeUsesRequestedCount() + { + testcase("Charge Uses Requested Count"); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + int const requested = static_cast(Tuning::kHardMaxReplyNodes) + 1; + int const capped = static_cast(Tuning::kHardMaxReplyNodes); + + // Successful-setup assertion: nothing has been charged yet, so the + // post-condition below can only come from the handler call. + BEAST_EXPECT(!peer->getLastAppliedCharge().has_value()); + + // No hashes are stored, so every lookup misses and `found` is 0. + // Called directly, so the handler and the charge both run on this + // thread: `charge()` dispatches to strand_, and boost's strand + // `dispatch` runs the function inline when the caller is not already + // in the strand and the strand is idle. The capture in the override + // happens before that hop regardless, so the observation is + // deterministic either way. + peer->runProcessGetObjectByHash(createUnstoredRequest(requested)); + + auto reply = parseReply(peer); + BEAST_EXPECT(reply.has_value()); + if (!reply) + return; + BEAST_EXPECT(reply->objects_size() == 0); + + // State: a charge was applied at all. + auto const& applied = peer->getLastAppliedCharge(); + BEAST_EXPECT(applied.has_value()); + if (!applied) + return; + + // Cause: it is exactly the requested-count price. This is the + // assertion the test is named for. Under either plausible + // mis-pricing it reads a different number and therefore fails: + // priced on `iterLimit` (12288) -> 99176 + // priced on `found` (0) -> 0, since billable clamps to 0 + // and the band drops to Small + BEAST_EXPECT(applied->cost() == 99184); + BEAST_EXPECT(applied->cost() == PeerTest::peekComputeFee(requested, 0).cost()); + BEAST_EXPECT(applied->cost() != PeerTest::peekComputeFee(capped, 0).cost()); + + // Attribution: the charge came from the differential helper, not + // from one of the flat admission or rejection constants. + BEAST_EXPECT(applied->label() == "GetObject differential"); + BEAST_EXPECT(peer->getLastChargeContext() == "processed get object by hash request"); + + // `fee_` is untouched on this path, which is why the override above + // exists rather than a peekFeeCharge() assertion. + BEAST_EXPECT(peer->peekFeeCharge().cost() == Resource::kFeeTrivialPeer.cost()); + + // Pricing on the requested count is strictly more expensive than + // pricing on the capped count, which is what makes the choice + // observable at all. + BEAST_EXPECT( + PeerTest::peekComputeFee(requested, 0).cost() > + PeerTest::peekComputeFee(capped, 0).cost()); + + // Exact values for both, so a change to either input is caught. + BEAST_EXPECT(PeerTest::peekComputeFee(requested, 0).cost() == 99184); + BEAST_EXPECT(PeerTest::peekComputeFee(capped, 0).cost() == 99176); } void run() override { + // NOTE ON METRIC COVERAGE. The five getobject_* instruments are + // recorded through the XRPL_METRIC_* macros, which push into the + // OpenTelemetry SDK. That API is write-only by design -- there is no + // read-back accessor and no in-memory metric reader in this build -- + // and a default jtx::Env leaves telemetry disabled, so the macros do + // not execute at all here. These tests therefore assert the + // observable behaviour of each instrumented code path, which pins + // the values the instruments are fed: + // getobject_request_objects <- the request's objects_size() + // getobject_lookups_total <- reply size (hits) and the derived + // miss count, per testHitMissSplit + // getobject_charge <- the applied Resource::Charge, + // captured by PeerTest::charge() + // getobject_rejected_total <- the two gates' exact fee_ values + // plus "no charge was applied" + // Only getobject_lookup_us has no in-process witness, being a wall + // clock reading. The counter and histogram values themselves remain + // unverified by unit test and are checked live against Prometheus + // per the design's live-validation step. int const limit = static_cast(Tuning::kHardMaxReplyNodes); testReplyLimit(limit + 1, limit); testReplyLimit(limit, limit); testReplyLimit(limit - 1, limit - 1); + + testOversizeRejection(); + testAtLimitNotRejected(); + testMalformedLedgerHashRejection(uint256::size() - 1); + testMalformedLedgerHashRejection(uint256::size() + 1); + testMalformedLedgerHashRejection(0); + testWellFormedLedgerHashAccepted(); + + testHitMissSplit(5, 3); + testHitMissSplit(0, 4); + testHitMissSplit(4, 0); + + testComputeFeeExactValues(); + testChargeUsesRequestedCount(); } }; diff --git a/src/tests/libxrpl/telemetry/MetricsRegistry.cpp b/src/tests/libxrpl/telemetry/MetricsRegistry.cpp index a1000d4cae..7d4206ab00 100644 --- a/src/tests/libxrpl/telemetry/MetricsRegistry.cpp +++ b/src/tests/libxrpl/telemetry/MetricsRegistry.cpp @@ -1,25 +1,296 @@ /** - * GTest unit tests for MetricsRegistry (no-op / telemetry-disabled path). + * GTest unit tests for MetricsRegistry. * - * Tests cover: - * - Construction with telemetry disabled (no-op behavior). - * - start()/stop() lifecycle when disabled. - * - Synchronous instrument recording methods do not crash when disabled. - * - Double stop() is safe. - * - Destructor handles cleanup without crash. + * Two independent groups, split by what they can link: * - * NOTE: These tests only exercise the no-op path (telemetry disabled). - * When XRPL_ENABLE_TELEMETRY is defined, MetricsRegistry.cpp pulls in - * xrpld symbols that cannot be linked into this standalone test binary, - * so the tests are compiled out. + * 1. sanitiseHandler() — the `handler` label sanitiser. Runs in **both** + * builds. sanitiseHandler() is a public static constexpr defined inline + * in the header, so it needs no part of MetricsRegistry.cpp on the link + * line. These tests therefore sit outside the guard below; putting them + * inside it would silently compile them out of the telemetry-enabled + * build, which is the build that actually exports the label. + * + * 2. The no-op / telemetry-disabled path — construction, start()/stop() + * lifecycle, and the synchronous record*() methods. Guarded, because + * when XRPL_ENABLE_TELEMETRY is defined MetricsRegistry.cpp is not + * compiled into this binary (see src/tests/libxrpl/CMakeLists.txt) and + * its out-of-line symbols are unresolvable here. */ +#include + +#include + +#include +#include +#include +#include + +namespace { + +using xrpl::telemetry::MetricsRegistry; + +/** + * Every job name reaching the JobQueue in non-test code that + * sanitiseHandler() must return unchanged, i.e. every one consisting solely + * of ASCII letters. + * + * How to re-derive this set (it is read off the source, not off docs): + * + * 1. Enumerate the four surfaces that put a name into the JobQueue, + * excluding `src/test/` and `src/tests/`: + * - `JobQueue::addJob` + * - `JobQueue::postCoro` (its `name` becomes `Coro::name_`, which + * `Coro::post()` hands to `addRefCountedJob`) + * - `LedgerMaster::newPFWork`, a thin `addJob` wrapper + * - each `TimeoutCounter` subclass's `.jobName =` designated + * initialiser, consumed by `TimeoutCounter::queueJob()`'s `addJob` + * `addRefCountedJob` is private and has only those callers, so the four + * surfaces close the set. + * 2. Resolve each `name` argument to the literal(s) it can hold. Most are + * literals written in place, but four call sites pass a variable and + * must be traced back: + * - `PeerImp.cpp` passes a local `std::string const name = + * isTrusted ? "ChkTrust" : "ChkUntrust";`, so one call site + * contributes *two* names. Neither literal appears at an `addJob` + * call site, which is why a grep of `addJob` alone misses them. + * - `LedgerMaster::newPFWork` forwards its own `char const* name` + * parameter; its three callers supply the three `PthFind*` literals. + * - `TimeoutCounter` forwards `queueJobParameter_.jobName`, set by a + * `.jobName =` designated initialiser in each of its five + * subclasses. + * - `Coro::post()` forwards `name_`, set from `postCoro`'s argument. + * 3. Keep the names that satisfy sanitiseHandler()'s rule — non-empty and + * all ASCII letters. Everything else belongs in kFoldToOtherHandlers. + * + * Note what step 3 excludes. Two call sites compose the name at runtime from + * a literal prefix and a ledger sequence: `"Pub" + std::to_string(seq)` and + * `"OB" + std::to_string(seq % 1000000000)`. The bare prefixes `"Pub"` and + * `"OB"` are all letters, but they are never what reaches the JobQueue — the + * *composed* form is, and it always carries digits. So they are absent here + * and their composed forms appear in kFoldToOtherHandlers instead. + * + * `JobQueue::makeLoadEvent` is deliberately out of scope: its `name` feeds + * `LoadEvent`/`LoadMonitor`, neither of which reaches MetricsRegistry, so + * names like `"cmd:" + method` never become a `handler` label value. + * + * Asserting on the real list is the point of the test: it proves the + * cardinality bound holds for the names actually in the binary, so a job + * added later whose name breaks the rule shows up as a failure here rather + * than as an unexplained `other` bucket on a dashboard. + */ +constexpr std::array kPassThroughHandlers = { + std::string_view{"AcceptLedger"}, // RCLConsensus.cpp + std::string_view{"AcqDone"}, // InboundLedger.cpp + std::string_view{"AdvanceLedger"}, // LedgerMaster.cpp + std::string_view{"ChkTrust"}, // PeerImp.cpp (local, ternary) + std::string_view{"ChkUntrust"}, // PeerImp.cpp (local, ternary) + std::string_view{"ComplAcquire"}, // TransactionAcquire.cpp + std::string_view{"DoTxs"}, // PeerImp.cpp + std::string_view{"GotFetchPack"}, // LedgerMaster.cpp + std::string_view{"GotStaleData"}, // InboundLedgers.cpp + std::string_view{"HandleHaveTxs"}, // PeerImp.cpp + std::string_view{"HistTxStream"}, // NetworkOPs.cpp + std::string_view{"InboundLedger"}, // InboundLedger.cpp (.jobName) + std::string_view{"LedReplDelta"}, // LedgerDeltaAcquire.cpp (.jobName) + std::string_view{"LedReplTask"}, // LedgerReplayTask.cpp (.jobName) + std::string_view{"MakeFetchPack"}, // PeerImp.cpp + std::string_view{"NObjStore"}, // NodeStoreScheduler.cpp + std::string_view{"NetCluster"}, // NetworkOPs.cpp + std::string_view{"NetHeart"}, // NetworkOPs.cpp + std::string_view{"OnLedBuilt"}, // LedgerDeltaAcquire.cpp + std::string_view{"ProcessLData"}, // InboundLedgers.cpp + std::string_view{"PthFindNewLed"}, // LedgerMaster.cpp (newPFWork) + std::string_view{"PthFindNewReq"}, // LedgerMaster.cpp (newPFWork) + std::string_view{"PthFindOBDB"}, // LedgerMaster.cpp (newPFWork) + std::string_view{"PubCons"}, // NetworkOPs.cpp + std::string_view{"PubFee"}, // NetworkOPs.cpp + std::string_view{"RPCSubSendThr"}, // RPCSub.cpp + std::string_view{"RcvCheckTx"}, // PeerImp.cpp + std::string_view{"RcvGetLedger"}, // PeerImp.cpp + std::string_view{"RcvGetObjByHash"}, // PeerImp.cpp + std::string_view{"RcvManifests"}, // PeerImp.cpp + std::string_view{"RcvPeerData"}, // PeerImp.cpp + std::string_view{"RcvProofPReq"}, // PeerImp.cpp + std::string_view{"RcvReplDReq"}, // PeerImp.cpp + std::string_view{"SkipListAcq"}, // SkipListAcquire.cpp (.jobName) + std::string_view{"SubmitTxn"}, // NetworkOPs.cpp + std::string_view{"TryFill"}, // LedgerMaster.cpp + std::string_view{"TxAcq"}, // TransactionAcquire.cpp (.jobName) + std::string_view{"TxBatchAsync"}, // NetworkOPs.cpp + std::string_view{"TxBatchSync"}, // NetworkOPs.cpp + std::string_view{"TxsToTxn"}, // ConsensusTransSetSF.cpp + std::string_view{"WAL"}, // SociDB.cpp + std::string_view{"checkPropose"}, // PeerImp.cpp (lowercase start) + std::string_view{"sweep"}, // Application.cpp (all lowercase) +}; + +/** + * Names that must fold to kHandlerOther. + * + * The first two are the composed forms of the only two dynamically built job + * names in the tree: `"Pub" + std::to_string(ledger->seq())` + * (LedgerPersistence.cpp) and + * `"OB" + std::to_string(ledger->seq() % 1000000000)` (OrderBookDBImpl.cpp). + * They are the reason the sanitiser exists — used raw they would mint a + * Prometheus series per ledger — so realistic sequence values are used + * rather than short placeholders. The sequence is unbounded at the `"Pub"` + * site and masked to nine digits at the `"OB"` site, but a digit appears + * either way (even `seq == 0` gives `"Pub0"`), so no reachable input at + * either site can produce an all-letter name. + * + * The next five are static literals that already fail the rule today, so + * the fallback is exercised by real code and not only by synthetic input. + * + * The remainder are the edge cases: empty, and one entry per disallowed + * character class (space, digit, underscore, hyphen, non-ASCII byte). The + * non-ASCII entry is UTF-8 'e-acute'; on a signed-char platform its lead + * byte is negative, which the explicit ASCII range check rejects where a + * locale-sensitive std::isalpha might not. + */ +constexpr std::array kFoldToOtherHandlers = { + std::string_view{"Pub97531234"}, // dynamic: "Pub" + ledger seq + std::string_view{"OB123456789"}, // dynamic: "OB" + ledger seq % 1e9 + std::string_view{"GetConsL1"}, // static, digit (RCLConsensus.cpp) + std::string_view{"GetConsL2"}, // static, digit (RCLValidations.cpp) + std::string_view{"gRPC-Client"}, // static, hyphen (GRPCServer.cpp) + std::string_view{"RPC-Client"}, // static, hyphen (ServerHandler.cpp) + std::string_view{"WS-Client"}, // static, hyphen (ServerHandler.cpp) + std::string_view{""}, // empty + std::string_view{"Rcv Ledger"}, // space + std::string_view{"Handler7"}, // digit + std::string_view{"Rcv_Ledger"}, // underscore + std::string_view{"Rcv-Ledger"}, // hyphen + std::string_view{"caf\xC3\xA9"}, // non-ASCII byte (UTF-8 e-acute) +}; + +/** + * True when sanitiseHandler() returns each pass-through name unchanged. + * + * consteval so a regression is a compile error rather than a test failure: + * the sanitiser is constexpr precisely so this bound can be checked without + * running anything. + */ +consteval bool +allPassThroughUnchanged() +{ + for (auto const name : kPassThroughHandlers) + { + if (MetricsRegistry::sanitiseHandler(name) != name) + return false; + } + return true; +} + +/** + * True when sanitiseHandler() maps every listed name to kHandlerOther. + */ +consteval bool +allFoldToOther() +{ + for (auto const name : kFoldToOtherHandlers) + { + if (MetricsRegistry::sanitiseHandler(name) != MetricsRegistry::kHandlerOther) + return false; + } + return true; +} + +// Compile-time guarantees. Duplicated at runtime below so a failure names +// the offending input instead of only pointing at the assertion. +static_assert(allPassThroughUnchanged()); +static_assert(allFoldToOther()); + +// The verified size of the pass-through set as of this branch: 43 all-letter +// job-name literals. Pinned so that adding or removing a job name without +// revisiting the label-cardinality budget fails the build here. +static_assert(kPassThroughHandlers.size() == 43); + +/** + * Total distinct `handler` label values reachable from the inputs above: + * one per pass-through name plus the single shared kHandlerOther bucket. + * This is the number the Prometheus cardinality budget is sized against. + */ +constexpr std::size_t kExpectedHandlerDomain = kPassThroughHandlers.size() + 1; +static_assert(kExpectedHandlerDomain == 44); + +} // namespace + +TEST(MetricsRegistrySanitiseHandler, static_job_names_pass_through_unchanged) +{ + // Every all-letter job name in the tree survives sanitisation, so the + // `handler` label keeps its attribution value for real producers. + for (auto const name : kPassThroughHandlers) + { + EXPECT_EQ(MetricsRegistry::sanitiseHandler(name), name) + << "job name should pass through unchanged: " << name; + // Cause, not just state: it passed because it is not the fallback. + EXPECT_NE(MetricsRegistry::sanitiseHandler(name), MetricsRegistry::kHandlerOther) + << "job name wrongly folded to the fallback: " << name; + } +} + +TEST(MetricsRegistrySanitiseHandler, dynamic_and_non_letter_names_fold_to_other) +{ + // Negative path: everything that is not an all-letter name collapses + // into exactly one bucket, which is what bounds the label domain. + for (auto const name : kFoldToOtherHandlers) + { + EXPECT_EQ(MetricsRegistry::sanitiseHandler(name), MetricsRegistry::kHandlerOther) + << "name should fold to the fallback: " << name; + } +} + +TEST(MetricsRegistrySanitiseHandler, empty_name_folds_to_other) +{ + // Called out separately because it is the one case the all-letter scan + // cannot catch: std::ranges::all_of() is vacuously true on an empty + // range, so the sanitiser needs its own emptiness check. + EXPECT_EQ(MetricsRegistry::sanitiseHandler(std::string_view{}), MetricsRegistry::kHandlerOther); + EXPECT_EQ(MetricsRegistry::sanitiseHandler(""), MetricsRegistry::kHandlerOther); +} + +TEST(MetricsRegistrySanitiseHandler, fallback_value_is_the_shared_constant) +{ + // The fallback must be the constant the dashboards and the reference doc + // are written against, not merely some non-empty string. + EXPECT_EQ(MetricsRegistry::kHandlerOther, std::string_view{"other"}); + EXPECT_EQ(MetricsRegistry::kHandlerOther.size(), 5u); + + // "other" is itself all letters, so sanitising it is idempotent -- a + // handler genuinely named "other" is indistinguishable from the bucket. + EXPECT_EQ( + MetricsRegistry::sanitiseHandler(MetricsRegistry::kHandlerOther), + MetricsRegistry::kHandlerOther); +} + +TEST(MetricsRegistrySanitiseHandler, output_domain_is_exactly_44_values) +{ + // The cardinality bound itself: over every input above -- 43 real job + // names, 2 dynamic names, 5 non-conforming static names and 6 edge + // cases -- the sanitiser can emit only 44 distinct label values (43 + // names plus the single "other" bucket). + std::set domain; + for (auto const name : kPassThroughHandlers) + domain.insert(MetricsRegistry::sanitiseHandler(name)); + for (auto const name : kFoldToOtherHandlers) + domain.insert(MetricsRegistry::sanitiseHandler(name)); + + EXPECT_EQ(domain.size(), kExpectedHandlerDomain); + EXPECT_EQ(domain.size(), 44u); + + // State plus cause: the domain is the pass-through names and nothing + // else besides the one fallback bucket. + EXPECT_TRUE(domain.contains(MetricsRegistry::kHandlerOther)); + EXPECT_EQ(domain.size() - 1, kPassThroughHandlers.size()); + for (auto const name : kPassThroughHandlers) + EXPECT_TRUE(domain.contains(name)) << "missing from domain: " << name; +} + // When telemetry is globally enabled, MetricsRegistry.cpp requires xrpld // link dependencies we cannot satisfy in a standalone GTest binary. #ifndef XRPL_ENABLE_TELEMETRY -#include - #include #include #include @@ -27,8 +298,6 @@ #include -#include - #include #include #include @@ -339,9 +608,9 @@ TEST_F(MetricsRegistryTest, disabled_recording_methods) registry.recordRpcStarted("server_info"); registry.recordRpcFinished("server_info", 1000); registry.recordRpcErrored("ledger", 500); - registry.recordJobQueued("ledgerData"); - registry.recordJobStarted("ledgerData", 200); - registry.recordJobFinished("ledgerData", 3000); + registry.recordJobQueued("ledgerData", "ProcessLData"); + registry.recordJobStarted("ledgerData", "ProcessLData", 200); + registry.recordJobFinished("ledgerData", "ProcessLData", 3000); registry.stop(); } diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index a8f5db0508..aebb7c281b 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -1,3 +1,7 @@ +// 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. + #include #include @@ -24,6 +28,7 @@ #include #include #include +#include #include #include @@ -68,6 +73,7 @@ #include #include #include +#include #include #include #include @@ -2568,6 +2574,12 @@ PeerImp::onMessage(std::shared_ptr const& m) { JLOG(pJournal_.debug()) << "GetObj: malformed ledgerhash from peer " << id_; fee_.update(Resource::kFeeMalformedRequest, "get object ledger hash"); + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + telemetry::kGetObjectRejectedTotal, + telemetry::kGetObjectRejectedTotalDesc, + {{telemetry::kLabelReason, + std::string(telemetry::kReasonMalformedLedgerHash)}}); return; } } @@ -2580,6 +2592,11 @@ PeerImp::onMessage(std::shared_ptr const& m) << "GetObj: oversized request from peer " << id_ << " (" << packet.objects_size() << " > " << Tuning::kHardMaxReplyNodes << ")"; fee_.update(Resource::kFeeInvalidData, "oversized get object request"); + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + telemetry::kGetObjectRejectedTotal, + telemetry::kGetObjectRejectedTotalDesc, + {{telemetry::kLabelReason, std::string(telemetry::kReasonOversize)}}); return; } @@ -2699,6 +2716,11 @@ PeerImp::processGetObjectByHash(std::shared_ptr con int const requested = packet.objects_size(); int const iterLimit = std::min(requested, Tuning::kHardMaxReplyNodes); + // Time the whole loop once, not each iteration: the loop can run up to + // kHardMaxReplyNodes times, so per-iteration clock reads would cost more + // than the lookups they measure. + auto const lookupStart = std::chrono::steady_clock::now(); + for (int i = 0; i < iterLimit; ++i) { auto const& obj = packet.objects(i); @@ -2723,20 +2745,74 @@ PeerImp::processGetObjectByHash(std::shared_ptr con newObj.set_ledgerseq(obj.ledgerseq()); } + auto const lookupElapsed = std::chrono::duration_cast( + std::chrono::steady_clock::now() - lookupStart); + // Apply work-proportional charge. `charge()` posts the disconnect // step (if any) back to strand_, so it is safe to call from this // JobQueue worker thread. - charge( - // We pass `requested` directly here, instead of actual lookups done. Which could be - // std::min(packet.objects_size(), static_cast(Tuning::kHardMaxReplyNodes)); - // Because we want to charge as per the request size, to discourage large requests. - computeGetObjectByHashFee(requested, reply.objects_size()), - "processed get object by hash request"); + // + // We pass `requested` directly here, instead of actual lookups done. Which could be + // std::min(packet.objects_size(), static_cast(Tuning::kHardMaxReplyNodes)); + // Because we want to charge as per the request size, to discourage large requests. + // + // Computed into a local so the recorded metric is exactly the charge + // that is applied -- calling the helper twice could diverge. + Resource::Charge const fee = computeGetObjectByHashFee(requested, reply.objects_size()); + charge(fee, "processed get object by hash request"); + + recordGetObjectMetrics(requested, reply.objects_size(), lookupElapsed, fee); JLOG(pJournal_.trace()) << "GetObj: " << reply.objects_size() << " of " << requested; send(std::make_shared(reply, protocol::mtGET_OBJECTS)); } +void +PeerImp::recordGetObjectMetrics( + int const requested, + int const found, + std::chrono::microseconds const lookupElapsed, + Resource::Charge const& fee) +{ + using namespace telemetry; + + XRPL_METRIC_HISTOGRAM_RECORD( + app_, kGetObjectRequestObjects, kGetObjectRequestObjectsDesc, requested); + + XRPL_METRIC_HISTOGRAM_RECORD( + app_, kGetObjectLookupUs, kGetObjectLookupUsDesc, lookupElapsed.count()); + + XRPL_METRIC_HISTOGRAM_RECORD(app_, kGetObjectCharge, kGetObjectChargeDesc, fee.cost()); + + // Batch totals, added once per request rather than once per object: + // per-object increments on a loop bounded by kHardMaxReplyNodes would be + // a measurable cost for no extra information. + // + // `found` is the reply size, which the fetch loop only grows on a + // successful lookup within `iterLimit <= requested`, so `found <= + // requested` always holds. std::max still clamps both values, so a future + // caller passing found > requested cannot make the miss count wrap + // negative -- the counter takes an unsigned amount, where a wrap would + // read as ~1.8e19 rather than as an error. + // + // Written as two calls rather than a loop over a {hit, miss} pair: the + // macros expand to empty statements in a telemetry-off build, which would + // leave a loop's induction variable unused and fail the -Werror build. + XRPL_METRIC_COUNTER_ADD_LABELED( + app_, + kGetObjectLookupsTotal, + kGetObjectLookupsTotalDesc, + static_cast(std::max(0, found)), + {{kLabelResult, std::string(kResultHit)}}); + + XRPL_METRIC_COUNTER_ADD_LABELED( + app_, + kGetObjectLookupsTotal, + kGetObjectLookupsTotalDesc, + static_cast(std::max(0, requested - found)), + {{kLabelResult, std::string(kResultMiss)}}); +} + void PeerImp::onMessage(std::shared_ptr const& m) { diff --git a/src/xrpld/overlay/detail/PeerImp.h b/src/xrpld/overlay/detail/PeerImp.h index ea6eccd656..2e004f0f3f 100644 --- a/src/xrpld/overlay/detail/PeerImp.h +++ b/src/xrpld/overlay/detail/PeerImp.h @@ -681,6 +681,34 @@ private: void processLedgerRequest(std::shared_ptr const& m); + /** + * Record the OTel metrics for one completed `TMGetObjectByHash` request. + * + * Extracted from `processGetObjectByHash()` purely to keep that method + * within the 80-line limit; it holds no logic of its own beyond deriving + * the hit/miss split from `requested` and `found`. Called once per + * request, after the fetch loop and the `charge()` call. + * + * Records `getobject_request_objects`, `getobject_lookup_us`, + * `getobject_charge`, and both label values of + * `getobject_lookups_total`. Compiles to nothing when telemetry is + * disabled, because the `XRPL_METRIC_*` macros do. + * + * @param requested Objects the peer asked for (`objects_size()`). + * @param found Objects returned, i.e. the reply's object count. + * Expected to be `<= requested`; clamped either way + * so the derived miss count cannot go negative. + * @param lookupElapsed Wall time of the whole fetch loop. + * @param fee The dynamic charge that was applied, so the + * recorded value is exactly the one charged. + */ + void + recordGetObjectMetrics( + int const requested, + int const found, + std::chrono::microseconds const lookupElapsed, + Resource::Charge const& fee); + protected: // Kept `protected` so test subclasses (see // TMGetObjectByHash_test) can drive the diff --git a/src/xrpld/perflog/detail/PerfLogImp.cpp b/src/xrpld/perflog/detail/PerfLogImp.cpp index f840ec2bf3..f43464dd1d 100644 --- a/src/xrpld/perflog/detail/PerfLogImp.cpp +++ b/src/xrpld/perflog/detail/PerfLogImp.cpp @@ -414,7 +414,7 @@ PerfLogImp::rpcEnd(std::string const& method, std::uint64_t const requestId, boo } void -PerfLogImp::jobQueue(JobType const type) +PerfLogImp::jobQueue(JobType const type, std::string const& name) { auto counter = counters_.jq.find(type); if (counter == counters_.jq.end()) @@ -429,12 +429,13 @@ PerfLogImp::jobQueue(JobType const type) // Task 9.5: Record job enqueue in OTel metrics pipeline. if (auto* mr = app_.getMetricsRegistry()) - mr->recordJobQueued(JobTypes::name(type)); + mr->recordJobQueued(JobTypes::name(type), name); } void PerfLogImp::jobStart( JobType const type, + std::string const& name, microseconds dur, steady_time_point startTime, int instance) @@ -459,11 +460,11 @@ PerfLogImp::jobStart( // Task 9.5: Record job start in OTel metrics pipeline. if (auto* mr = app_.getMetricsRegistry()) - mr->recordJobStarted(JobTypes::name(type), dur.count()); + mr->recordJobStarted(JobTypes::name(type), name, dur.count()); } void -PerfLogImp::jobFinish(JobType const type, microseconds dur, int instance) +PerfLogImp::jobFinish(JobType const type, std::string const& name, microseconds dur, int instance) { auto counter = counters_.jq.find(type); if (counter == counters_.jq.end()) @@ -485,7 +486,7 @@ PerfLogImp::jobFinish(JobType const type, microseconds dur, int instance) // Task 9.5: Record job finish in OTel metrics pipeline. if (auto* mr = app_.getMetricsRegistry()) - mr->recordJobFinished(JobTypes::name(type), dur.count()); + mr->recordJobFinished(JobTypes::name(type), name, dur.count()); } void diff --git a/src/xrpld/perflog/detail/PerfLogImp.h b/src/xrpld/perflog/detail/PerfLogImp.h index 14477512ff..9c8f38bb74 100644 --- a/src/xrpld/perflog/detail/PerfLogImp.h +++ b/src/xrpld/perflog/detail/PerfLogImp.h @@ -153,12 +153,16 @@ public: } void - jobQueue(JobType const type) override; + jobQueue(JobType const type, std::string const& name) override; void - jobStart(JobType const type, microseconds dur, steady_time_point startTime, int instance) - override; + jobStart( + JobType const type, + std::string const& name, + microseconds dur, + steady_time_point startTime, + int instance) override; void - jobFinish(JobType const type, microseconds dur, int instance) override; + jobFinish(JobType const type, std::string const& name, microseconds dur, int instance) override; json::Value countersJson() const override diff --git a/src/xrpld/telemetry/MetricMacros.h b/src/xrpld/telemetry/MetricMacros.h index 940f916de5..6bea92d8e3 100644 --- a/src/xrpld/telemetry/MetricMacros.h +++ b/src/xrpld/telemetry/MetricMacros.h @@ -46,10 +46,19 @@ * if (queueIsFull) * XRPL_METRIC_COUNTER_INC_LABELED(app, "txq_dropped_total", * "Transactions refused admission to the queue", - * ({{"reason", std::string("queue_full")}})); + * {{"reason", std::string("queue_full")}}); * } * @endcode * + * Pass the label set as a bare brace-enclosed list, as above. Do not wrap + * it in an extra pair of parentheses: the list is forwarded verbatim into + * the OTel `Add()`/`Record()` call, which takes an initializer_list, and + * the extra parentheses do not compile. + * + * Wrap each label *value* in `std::string`. `AttributeValue` is a variant + * in which a bare `const char*` selects the boolean alternative, so an + * unwrapped literal is recorded as `true`. + * * Example usage -- UpDownCounter (edge case: value that can decrease): * @code * void ServerHandler::onRpcStart() diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index 7e5d67910c..1c0c83221e 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -44,6 +44,7 @@ #include #include #include +#include #include #include @@ -64,6 +65,7 @@ #include #include +#include #include #include #include @@ -89,43 +91,55 @@ constexpr char kJobQueuedDurationUs[] = "job_queued_us"; constexpr char kJobRunningDurationUs[] = "job_running_us"; constexpr char kRpcMethodDurationUs[] = "rpc_method_us"; +// Attribute (label) keys for the job instruments. Each is referenced from +// several record sites, and a counter and its histogram must carry exactly +// the same key spelling or the two series cannot be joined in a query. +constexpr char kJobTypeLabel[] = "job_type"; +constexpr char kHandlerLabel[] = "handler"; + /** - * Register an explicit-bucket histogram view for a microsecond-valued - * instrument. + * Bucket boundaries for microsecond-valued duration instruments. * - * The SDK's default histogram buckets top out at 10,000 (10 ms when the - * values are microseconds), so any duration above 10 ms saturates and - * every quantile reads as 10 ms. Job wait/run times and RPC latencies - * routinely exceed that, so we install boundaries spanning 100 µs to - * 60 s to capture the real distribution. + * 100 µs, 500 µs, 1 ms, 5 ms, 10 ms, 25 ms, 50 ms, 100 ms, 250 ms, 500 ms, + * 1 s, 2.5 s, 5 s, 10 s, 30 s, 60 s. Covers sub-millisecond jobs through + * multi-second stalls without saturating. + */ +constexpr std::array kMicrosecondBoundaries{ + 100.0, + 500.0, + 1'000.0, + 5'000.0, + 10'000.0, + 25'000.0, + 50'000.0, + 100'000.0, + 250'000.0, + 500'000.0, + 1'000'000.0, + 2'500'000.0, + 5'000'000.0, + 10'000'000.0, + 30'000'000.0, + 60'000'000.0}; + +/** + * Register an explicit-bucket histogram view. * - * @param views The registry to add the view to. - * @param name Instrument name to match (e.g. "job_running_us"). + * The SDK's default boundaries top out at 10,000, so any instrument whose + * values exceed that saturates and every quantile reads as the ceiling. + * + * @param views The registry to add the view to. + * @param name Instrument name to match (e.g. "job_running_us"). + * @param boundaries Bucket upper bounds, ascending. */ void -addMicrosecondHistogramView(metric_sdk::ViewRegistry& views, std::string const& name) +addHistogramView( + metric_sdk::ViewRegistry& views, + std::string const& name, + std::vector boundaries) { - // Boundaries in microseconds: 100µs, 500µs, 1ms, 5ms, 10ms, 25ms, 50ms, - // 100ms, 250ms, 500ms, 1s, 2.5s, 5s, 10s, 30s, 60s. Covers sub-millisecond - // jobs through multi-second stalls without saturating. auto config = std::make_shared(); - config->boundaries_ = { - 100.0, - 500.0, - 1'000.0, - 5'000.0, - 10'000.0, - 25'000.0, - 50'000.0, - 100'000.0, - 250'000.0, - 500'000.0, - 1'000'000.0, - 2'500'000.0, - 5'000'000.0, - 10'000'000.0, - 30'000'000.0, - 60'000'000.0}; + config->boundaries_ = std::move(boundaries); auto selector = metric_sdk::InstrumentSelectorFactory::Create( metric_sdk::InstrumentType::kHistogram, name, ""); @@ -136,6 +150,21 @@ addMicrosecondHistogramView(metric_sdk::ViewRegistry& views, std::string const& views.AddView(std::move(selector), std::move(meterSelector), std::move(view)); } +/** + * Register the microsecond-ladder view for a duration instrument. + * + * Job wait/run times and RPC latencies routinely exceed the SDK default + * ceiling, so they all share `kMicrosecondBoundaries`. + * + * @param views The registry to add the view to. + * @param name Instrument name to match. + */ +void +addMicrosecondHistogramView(metric_sdk::ViewRegistry& views, std::string const& name) +{ + addHistogramView(views, name, {kMicrosecondBoundaries.begin(), kMicrosecondBoundaries.end()}); +} + } // namespace #endif // XRPL_ENABLE_TELEMETRY @@ -216,6 +245,30 @@ MetricsRegistry::initExporterAndProvider(std::string const& endpoint, std::strin addMicrosecondHistogramView(*views, kJobQueuedDurationUs); addMicrosecondHistogramView(*views, kJobRunningDurationUs); addMicrosecondHistogramView(*views, kRpcMethodDurationUs); + // Recorded at its PeerImp.cpp call site, not created here, so the name + // comes from the shared constant both sites use. + addMicrosecondHistogramView(*views, kGetObjectLookupUs); + + // 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. + // + // Object counts run 1..kHardMaxReplyNodes (12288). The honest sync path + // asks for at most 8, so the low buckets are fine-grained and the upper + // ones follow the charge size bands (64, 1024) up to the hard cap. + addHistogramView( + *views, + kGetObjectRequestObjects, + {1.0, 2.0, 4.0, 8.0, 16.0, 64.0, 256.0, 1'024.0, 4'096.0, 12'288.0}); + + // Charge values span 0 (free tier) to ~99k for a full-size all-miss + // request. Boundaries bracket the resource thresholds that decide a + // peer's fate -- kWarningThreshold (5000) and kDropThreshold (25000) -- + // so a dashboard can show how close charges run to each. + addHistogramView( + *views, + kGetObjectCharge, + {0.0, 100.0, 500.0, 1'000.0, 5'000.0, 10'000.0, 25'000.0, 50'000.0, 100'000.0}); // Create MeterProvider with resource, then attach the metric reader. provider_ = metric_sdk::MeterProviderFactory::Create(std::move(views), resourceAttrs); @@ -394,55 +447,71 @@ MetricsRegistry::recordRpcErrored(std::string_view method, std::int64_t duration // ----------------------------------------------------------------- void -MetricsRegistry::recordJobQueued(std::string_view jobType) +MetricsRegistry::recordJobQueued(std::string_view jobType, std::string_view jobName) { #ifdef XRPL_ENABLE_TELEMETRY if (!enabled_ || !jobQueuedCounter_) return; - jobQueuedCounter_->Add(1, {{"job_type", std::string(jobType)}}); + jobQueuedCounter_->Add( + 1, + {{kJobTypeLabel, std::string(jobType)}, + {kHandlerLabel, std::string(sanitiseHandler(jobName))}}); #else (void)jobType; + (void)jobName; (void)enabled_; #endif } void -MetricsRegistry::recordJobStarted(std::string_view jobType, std::int64_t queuedDurUs) +MetricsRegistry::recordJobStarted( + std::string_view jobType, + std::string_view jobName, + std::int64_t queuedDurUs) { #ifdef XRPL_ENABLE_TELEMETRY if (!enabled_ || !jobStartedCounter_) return; - jobStartedCounter_->Add(1, {{"job_type", std::string(jobType)}}); + // Build the attribute pair once: both the counter and the histogram + // must carry the identical label set or they cannot be joined. + std::string const handler(sanitiseHandler(jobName)); + jobStartedCounter_->Add(1, {{kJobTypeLabel, std::string(jobType)}, {kHandlerLabel, handler}}); if (jobQueuedDurationHistogram_) { jobQueuedDurationHistogram_->Record( static_cast(queuedDurUs), - {{"job_type", std::string(jobType)}}, + {{kJobTypeLabel, std::string(jobType)}, {kHandlerLabel, handler}}, opentelemetry::context::Context{}); } #else (void)jobType; + (void)jobName; (void)queuedDurUs; (void)enabled_; #endif } void -MetricsRegistry::recordJobFinished(std::string_view jobType, std::int64_t runningDurUs) +MetricsRegistry::recordJobFinished( + std::string_view jobType, + std::string_view jobName, + std::int64_t runningDurUs) { #ifdef XRPL_ENABLE_TELEMETRY if (!enabled_ || !jobFinishedCounter_) return; - jobFinishedCounter_->Add(1, {{"job_type", std::string(jobType)}}); + std::string const handler(sanitiseHandler(jobName)); + jobFinishedCounter_->Add(1, {{kJobTypeLabel, std::string(jobType)}, {kHandlerLabel, handler}}); if (jobRunningDurationHistogram_) { jobRunningDurationHistogram_->Record( static_cast(runningDurUs), - {{"job_type", std::string(jobType)}}, + {{kJobTypeLabel, std::string(jobType)}, {kHandlerLabel, handler}}, opentelemetry::context::Context{}); } #else (void)jobType; + (void)jobName; (void)runningDurUs; (void)enabled_; #endif diff --git a/src/xrpld/telemetry/MetricsRegistry.h b/src/xrpld/telemetry/MetricsRegistry.h index 402b7d539b..17d33a7d2f 100644 --- a/src/xrpld/telemetry/MetricsRegistry.h +++ b/src/xrpld/telemetry/MetricsRegistry.h @@ -28,11 +28,11 @@ * | +-- rpc_method_finished_total * | +-- rpc_method_errored_total * | +-- rpc_method_us (Histogram) - * | +-- job_queued_total - * | +-- job_started_total - * | +-- job_finished_total - * | +-- job_queued_us (Histogram) - * | +-- job_running_us (Histogram) + * | +-- job_queued_total{job_type,handler} + * | +-- job_started_total{job_type,handler} + * | +-- job_finished_total{job_type,handler} + * | +-- job_queued_us{job_type,handler} (Histogram) + * | +-- job_running_us{job_type,handler} (Histogram) * | +-- ledgers_closed_total * | +-- validations_sent_total * | +-- validations_checked_total @@ -109,9 +109,10 @@ * // or: mr->recordRpcErrored("server_info", durationUs); * } * - * // In PerfLogImp::jobQueue(): + * // In PerfLogImp::jobQueue(). The second argument is the addJob name; + * // it is sanitised internally into the bounded `handler` label. * if (auto* mr = app_.getMetricsRegistry()) - * mr->recordJobQueued("ledgerData"); + * mr->recordJobQueued("ledgerData", "ProcessLData"); * * // Shutdown: * metricsRegistry_->stop(); @@ -134,9 +135,11 @@ #include +#include #include #include #include +#include #include #include @@ -315,28 +318,115 @@ public: void recordRpcErrored(std::string_view method, std::int64_t durationUs); + /** + * The `handler` label value used for any job name that fails the + * sanitiser's all-ASCII-letters rule. + * + * Public because both sanitiseHandler() and its unit tests must agree + * on the exact fallback token; a test asserting against its own copy + * of the string would not catch a change made here. + * + * Declared as std::string_view rather than the `constexpr char k[]` + * form used for instrument names in MetricsRegistry.cpp: this value is + * *returned* by sanitiseHandler(), whose return type is + * std::string_view, and is compared against std::string_view in tests. + * Matching the type avoids array-to-pointer decay and a needless + * strlen at each use. + */ + static constexpr std::string_view kHandlerOther{"other"}; + + /** + * Reduce a job name to a bounded-cardinality `handler` label value. + * + * A job type can have several producers — both `RcvGetLedger` and + * `RcvGetObjByHash` run as `JtLedgerReq` — so `job_type` alone cannot + * attribute a latency spike to one of them. The job name can, but it + * cannot be used raw: two names embed a ledger sequence number + * (`"Pub" + std::to_string(seq)` in LedgerPersistence.cpp and + * `"OB" + std::to_string(...)` in OrderBookDBImpl.cpp), which would + * mint a fresh Prometheus series for every ledger. + * + * The rule is therefore: keep the name only when it is non-empty and + * every character is an ASCII letter; otherwise return `"other"`. + * Both dynamic names always contain digits, so they always fold to + * `"other"`, while every all-letter name is a compile-time literal. + * The label domain is thus a function of the literals present in the + * source — 43 names plus `"other"` at the time of writing — and + * cannot grow at runtime. A name added later that does not satisfy + * the rule degrades to `"other"` rather than becoming unbounded, + * which is a stronger guarantee than an allowlist that would have to + * be maintained by hand. + * + * Defined inline so unit tests can call it without linking the rest + * of the registry: in a telemetry-enabled build MetricsRegistry.cpp + * is not compiled into the test binary, so an out-of-line definition + * would be unreachable from tests. Being inline also makes it usable + * regardless of XRPL_ENABLE_TELEMETRY. + * + * @param name The job name as passed to JobQueue::addJob. + * @return @p name when it is non-empty and all ASCII letters, else + * kHandlerOther. + * + * @note Pure and reentrant: holds no state, performs no I/O, and is + * safe to call concurrently from any thread. + * @note The letter test is an explicit ASCII range check rather than + * std::isalpha, which classifies by the current C locale. A + * locale-dependent test could admit non-ASCII bytes and so + * weaken the cardinality bound this function exists to provide. + * @note When the name is kept, the returned view aliases @p name, so + * it must not outlive the caller's buffer. The kHandlerOther case + * returns a view of a static constant and is always valid. + * + * Example: + * @code + * sanitiseHandler("RcvGetObjByHash"); // "RcvGetObjByHash" + * sanitiseHandler("Pub94512331"); // kHandlerOther (digits) + * sanitiseHandler(""); // kHandlerOther (empty) + * @endcode + */ + [[nodiscard]] static constexpr std::string_view + sanitiseHandler(std::string_view name) noexcept + { + auto const isAsciiLetter = [](char const c) { + return (c >= 'a' && c <= 'z') || (c >= 'A' && c <= 'Z'); + }; + + if (name.empty() || !std::ranges::all_of(name, isAsciiLetter)) + return kHandlerOther; + + return name; + } + /** * Record a job enqueued event. * @param jobType The job type name (e.g. "ledgerData"). + * @param jobName The addJob name, reduced to a bounded `handler` + * label by sanitiseHandler(). Distinguishes producers + * that share a job type. */ void - recordJobQueued(std::string_view jobType); + recordJobQueued(std::string_view jobType, std::string_view jobName); /** * Record a job start event. * @param jobType The job type name. + * @param jobName The addJob name; see recordJobQueued(). * @param queuedDurUs Time the job spent waiting in the queue (us). */ void - recordJobStarted(std::string_view jobType, std::int64_t queuedDurUs); + recordJobStarted(std::string_view jobType, std::string_view jobName, std::int64_t queuedDurUs); /** * Record a job finish event. * @param jobType The job type name. + * @param jobName The addJob name; see recordJobQueued(). * @param runningDurUs Execution time in microseconds. */ void - recordJobFinished(std::string_view jobType, std::int64_t runningDurUs); + recordJobFinished( + std::string_view jobType, + std::string_view jobName, + std::int64_t runningDurUs); // ----------------------------------------------------------------- // External dashboard parity counters (Tasks 7.9-7.14) @@ -503,25 +593,27 @@ private: rpcDurationHistogram_; // --- Synchronous instruments (Job Queue) --- + // All five carry handler="" in addition to + // job_type, so producers that share a job type stay distinguishable. /** - * Counter: job_queued_total{job_type=""} + * Counter: job_queued_total{job_type="",handler=""} */ opentelemetry::nostd::unique_ptr> jobQueuedCounter_; /** - * Counter: job_started_total{job_type=""} + * Counter: job_started_total{job_type="",handler=""} */ opentelemetry::nostd::unique_ptr> jobStartedCounter_; /** - * Counter: job_finished_total{job_type=""} + * Counter: job_finished_total{job_type="",handler=""} */ opentelemetry::nostd::unique_ptr> jobFinishedCounter_; /** - * Histogram: job_queued_duration_us{job_type=""} + * Histogram: job_queued_duration_us{job_type="",handler=""} */ opentelemetry::nostd::unique_ptr> jobQueuedDurationHistogram_; /** - * Histogram: job_running_duration_us{job_type=""} + * Histogram: job_running_duration_us{job_type="",handler=""} */ opentelemetry::nostd::unique_ptr> jobRunningDurationHistogram_;