Vai al contenuto

Observability

UMNode exposes what it's doing two ways: timing in the logs (how long block import and each RPC call take) and a Prometheus /metrics endpoint for scraping.

Timing in the logs

  • Block import. Each catch-up step logs one summary line at Info. Realtime logs Imported blocks with the range, count, the top block's hash, and elapsed / write durations; it streams batches and overlaps fetching with writing, so elapsed is the chunk's wall-clock and write the disk portion:
INFO Imported blocks from=25,232,801 to=25,232,906 count=106 hash=0x1629… elapsed=435ms write=23ms

Backfill logs Backfilled blocks per chunk. Because it pulls the whole chunk before committing it, the network and disk phases are sequential and reported separately — fetch, write, and the elapsed total — so you can see whether time goes to peers or to the store:

INFO Backfilled blocks from=18,000,000 to=18,004,095 count=4096 fetch=2.3s write=180ms elapsed=2.5s

The per-block Imported block line is logged at Debug, so a deep catch-up or backfill doesn't flood Info with thousands of lines; raise --log-level debug to see it. - Block fetching. Backfill logs a Backfill fetching blocks line at Info before each chunk — its span, the number of batches it splits into, and the effective concurrency (how many batches fetch in parallel) — so the network step and its parallelism are visible at the default log level. The shared fetcher logs the rest at Debug: a Fetching blocks line when it starts a range (the span, the number of batches, and the fetch concurrency) and a Fetched batch line as each batch arrives (batch N of M, its sub-range, block count, and how long the batch took). Also at Debug, it traces the per-peer walk — Fetched from peer names the peer that served a request, the start block (from) and how many blocks it returned (blocks — usually a size-capped prefix of the batch, not a single item), how many candidates were tried, and that peer's response time in took, while All peers failed for request flags a request that exhausted every candidate — so you can see which peer a fetch came from, how much it served, how slow it was, and whether a failing attempt covered the whole set. - RPC calls. Every JSON-RPC call logs an RPC call line at Debug with the method and its duration. Enable it with --log-level debug. - Wire messages. Each message received from a peer — transaction and block gossip, and the headers/bodies/receipts responses to our own fetches — is logged at Trace. This is a high-volume firehose (a busy peer announces pooled transactions many times a second), so it sits below Debug; raise --log-level trace only when debugging the wire protocol itself.

Quieting the p2p subsystem

The p2p subsystem — the devp2p server and discovery, plus our peer connect / handshake / disconnect logs — is chatty at debug. By default its debug lines are suppressed so a plain --log-level debug shows the node's own activity (block import, fetch progress, RPC) without peer/discovery churn. Its info and above (Peer ready, Peer disconnected, warnings) always show.

  • --log-p2p includes the p2p subsystem's debug lines at --log-level debug.
  • --log-level trace shows everything regardless of the flag — the per-message wire firehose included.

So --log-level debug is the node without p2p noise; --log-level debug --log-p2p adds peer/discovery debug; --log-level trace is the full firehose.

Prometheus /metrics

Metrics are enabled by default on 0.0.0.0:18126. Turn them off with --metrics-enabled=false, or rebind with --metrics-addr host:port:

curl -s localhost:18126/metrics | grep umnode_

It runs as a regular background worker, so it shuts down cleanly with the node (in-flight scrapes drain before the store is closed).

Profiling (pprof)

--pprof-addr 127.0.0.1:6060 serves Go's standard net/http/pprof endpoints under /debug/pprof/ — off by default, and meant for localhost only. It is the tool for the "where does the time go" questions the log lines cannot answer:

# 60 s CPU profile of a catch-up run, then the usual pprof views
curl -s -o cpu.pprof 'http://127.0.0.1:6060/debug/pprof/profile?seconds=60'
go tool pprof -top -cum bin/umnode cpu.pprof
curl -s -o heap.pprof http://127.0.0.1:6060/debug/pprof/heap
curl -s 'http://127.0.0.1:6060/debug/pprof/goroutine?debug=1' > goroutines.txt

Like the metrics server it is a background worker that drains on shutdown. The findings of the first profiling pass over catch-up execution are in Where execution time goes.

Metrics exposed

Metric Type Meaning
umnode_chain_last_imported_block gauge Highest block number in the store (0 if empty).
umnode_chain_imported_blocks_total counter Total blocks written to the store, across all import paths (realtime + backfill).
umnode_chain_blocks gauge Stored blocks, labelled by tier (total / sealed / open / tail).
umnode_chain_transactions gauge Total transactions across all stored blocks.
umnode_store_db_bytes gauge Block-store on-disk size, labelled by area (sealed / open / tail / index).
umnode_p2p_ready_peers gauge Number of currently-ready peers.
umnode_rpcpeers_ready gauge With --rpc-peers: number of configured RPC peers currently serving requests.
umnode_rpc_request_duration_seconds histogram JSON-RPC handler duration, labelled by method.
umnode_archive_uploaded_files_total / umnode_archive_uploaded_bytes_total counter Sealed segment files and bytes backed up to the segment archive (--backup).
umnode_archive_attached_segments_total / umnode_archive_downloaded_bytes_total counter Sealed block segments attached from an archive (--archive-source) and the bytes downloaded for them.
go_memstats_*, process_* gauge Standard Go runtime (heap, GC, goroutines) and process (RSS, FDs, CPU — Linux) collectors.

The same figures are available in one shot from the debug_status RPC method. The umnode_chain_blocks / _transactions / umnode_store_db_bytes gauges are read live on each scrape (the byte figures walk the store directories once per scrape), so they always reflect the node's current state.

The two gauges are read live on each scrape (no background sampling), so they always reflect the node's state at scrape time. The imported_blocks_total counter is the throughput companion to the last_imported_block gauge: the gauge is the head's position, the counter is how many blocks were committed — and it counts every write, whether from realtime catch-up, reorg replacement, or backfill, regardless of where in the chain it landed. The histogram uses fine sub-millisecond buckets (100µs … 5s, densest in the 1–5ms range), suited to a read-only node serving from local storage.

Method-label cardinality

The histogram is labelled by method, but only for registered methods. Calls to unknown methods are recorded under a single method="unknown" label, so a client sending arbitrary method names can't explode label cardinality.

Useful queries

Per-method latency percentiles (p50 / p95 / p999) over a 5-minute window:

histogram_quantile(0.50, sum by (le, method) (rate(umnode_rpc_request_duration_seconds_bucket[5m])))
histogram_quantile(0.95, sum by (le, method) (rate(umnode_rpc_request_duration_seconds_bucket[5m])))
histogram_quantile(0.999, sum by (le, method) (rate(umnode_rpc_request_duration_seconds_bucket[5m])))

Per-method request rate (RPS):

sum by (method) (rate(umnode_rpc_request_duration_seconds_count[1m]))

Block import rate (blocks/sec), summed over realtime and backfill:

rate(umnode_chain_imported_blocks_total[1m])

min / max

A Prometheus histogram yields quantiles and counts, not exact min/max. In practice histogram_quantile(0.999, …) is the number to watch for the tail; histogram_quantile(0, …) approximates the floor (both are bounded by the bucket edges). If exact lifetime min/max ever becomes a hard requirement we can add dedicated gauges — they were left out to keep the metric surface lean and idiomatic.