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 blockswith the range, count, the top block's hash, andelapsed/writedurations; it streams batches and overlaps fetching with writing, soelapsedis the chunk's wall-clock andwritethe disk portion:
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:
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-p2pincludes the p2p subsystem's debug lines at--log-level debug.--log-level traceshows 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:
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):
Block import rate (blocks/sec), summed over realtime and backfill:
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.