Skip to content

feat(metrics): instrument the thread pools that CPU work runs on - #4451

Draft
vicsn wants to merge 13 commits into
stagingfrom
perf/thread-pool-profiling
Draft

vicsn wants to merge 13 commits into
stagingfrom
perf/thread-pool-profiling

Conversation

@vicsn

@vicsn vicsn commented Sep 10, 2026

Copy link
Copy Markdown
Collaborator

Motivation

The node runs three parallelism frameworks that each size themselves independently and know nothing of one another. On a 64-core host that is 128 tokio worker threads (2 * num_cores), up to 512 tokio blocking threads, and 64 rayon threads (num_cores).

They are not independent in practice. Every CPU-bound operation is staged through spawn_blocking! and then fans out onto the rayon global pool, so up to 512 callers can inject into a pool only as wide as the machine, with no priorities to separate a batch signature that a peer is waiting on from a cold-cache block verification during catch-up sync.

Whether that actually convoys, and what any of the three pools should be sized to, cannot be answered from reading the code. There are no numbers. This PR adds them; it changes no pool sizes and no scheduling.

What this adds

Thread names, which everything else depends on. The rayon global pool was built without thread_name, so its threads were unnamed, and tokio applies one name to both its workers and its blocking threads. Per-thread CPU time therefore could not be attributed to a pool at all. Threads are now rayon-N, tokio-worker-N and tokio-blocking-N.

Two things to know when reading these off a running process: Linux truncates a thread name to 15 bytes, which cuts the index off tokio-blocking-, so group by prefix rather than parsing the number; and blocking threads idle out and respawn, so their indices climb over the life of the process.

snarkos_cpu_blocking_wait_secs, the gap between submitting a spawn_blocking! task and that task starting. This is where queueing shows up before work ever reaches rayon, aggregated over every call site.

snarkos_tokio_*, sampled from tokio's own counters once a second:

Metric Answers
snarkos_tokio_worker_busy_cores How many cores' worth of work the async runtime is actually doing — the figure that sizes worker_threads
snarkos_tokio_worker_busy_ratio_max Whether load is spread across workers or landing on a few
snarkos_tokio_worker_parks How much of the runtime's time goes to sleeping and waking
snarkos_tokio_global_queue_depth, snarkos_tokio_alive_tasks, snarkos_tokio_workers Backlog and runtime shape

Tokio reports busy time and park counts as totals since startup, which say nothing on their own about load right now, so these are published as the change over each sampling interval.

snarkos_rayon_threads, the global pool's width. Worth reading rather than assuming, because num_cpus::get() honours the cgroup CFS quota, so a container's pool need not match the host's core count.

Behind RUSTFLAGS="--cfg tokio_unstable", compiled out of a normal build: snarkos_tokio_blocking_threads, snarkos_tokio_blocking_threads_idle, snarkos_tokio_blocking_queue_depth, snarkos_tokio_worker_steals, snarkos_tokio_worker_noops. Blocking pool occupancy against its 512 cap is the number that pairs with the wait histogram above, and it is only available here.

On work stealing

Worth measuring for tokio, not available for rayon.

Tokio exposes worker_steal_count and worker_noop_count, both included above. A high noop count is a worker waking, finding nothing, and parking again — pure overhead, and the direct signal that 2 * num_cores workers is more than the workload needs.

rayon-core 1.13 exposes no counters at all: no steal count, no queue depth, no thread-state API. So rayon is measured by outcome instead — its width from snarkos_rayon_threads, its saturation from the per-thread CPU time that thread naming now makes attributable, and its queueing from the blocking-pool wait that precedes it. Steal counts are a mechanism metric anyway; the decision-relevant outcomes are idle hunting and convoying, and both are visible without them.

snarkVM bump

Cargo.toml moves the snarkVM rev from e0f68fae to 708b2af912, the head of ProvableHQ/snarkVM#3416, which supplies the VM-side half of the picture:

  • snarkvm_vm_check_transaction_cache_hit_total / _miss_total and snarkvm_vm_check_transaction_duration_seconds labelled by cache — whether verification work is real proof checking or a hit on the ~1M-entry partially_verified_transactions cache. This distinguishes the block-production path (warm, so not rayon-width-bound) from catch-up sync (cold, so it is).
  • snarkvm_vm_check_transaction_in_flight and snarkvm_vm_check_transaction_duplicate_in_flight — concurrent verifications, which is what would convoy rayon, and how much of that is redundant.
  • snarkvm_vm_speculate_*, snarkvm_vm_prepare_for_speculate_*, snarkvm_vm_atomic_speculate_* — how long the sequential, storage-bound part of block production holds things up.

That rev also carries unrelated snarkVM staging commits picked up along the way. snarkVM#3416 is itself still a draft, so this cannot merge before it does.

How to use it

One devnet, one knob per run, A/B against a baseline, reading p99 rather than the mean and discarding the warm-up. The questions to settle, in order:

  1. Is worker_busy_cores far below the worker count? Then 128 workers is oversubscription, and the noop count says how much it costs.
  2. Is blocking_wait_secs non-zero at p99? Then work is queueing before rayon, and the blocking pool's occupancy says whether the 512 cap or rayon's width is the constraint.
  3. Do the rayon threads saturate during cold-cache sync but not during steady state? That decides whether rayon should be sized for sync or for block production, and whether the two need separating at all.

Testing

cargo clippy --workspace --all-targets --all-features -- -D warnings passes, as does the tokio_unstable build. cargo test -p snarkos-node-bft --lib passes, 123 tests.

.ci/test_devnet.sh passes every functional check — all nodes reach the minimum height, transactions confirm, the REST suite passes — then fails the validator log-size cap at 2.28 MB against a 2 MB limit. Nothing here adds a log line, and I have not checked whether that cap trips on staging too.

The node runs three pools that size themselves independently and know
nothing of each other: tokio's async workers at 2x the core count,
tokio's blocking pool capped at 512, and rayon's global pool at the core
count. Every CPU-bound operation is staged through the blocking pool and
then fans out onto rayon, so hundreds of callers can inject into a pool
that is only as wide as the machine. Whether that actually convoys, and
what the three pools should be sized to, cannot be answered from the
code -- there are no numbers to reason from.

This adds the numbers.

Naming the threads is the prerequisite for the rest: rayon's global pool
was left unnamed, and tokio labels its workers and its blocking threads
identically, so per-thread CPU time could not be attributed to a pool.
Threads are now named `rayon-N`, `tokio-worker-N` and `tokio-blocking-N`.

`snarkos_cpu_blocking_wait_secs` measures the gap between submitting a
`spawn_blocking!` task and it starting, which is where queueing shows up
before work ever reaches rayon.

The `snarkos_tokio_*` gauges come from tokio's own counters, sampled once
a second. Busy time and park counts are reported by tokio as totals since
startup, so they are published as the change over each interval; the
blocking pool's occupancy and the workers' steal counts need
`RUSTFLAGS="--cfg tokio_unstable"` and are compiled out otherwise.

Rayon publishes no counters of its own, so it is measured by outcome: its
width via `snarkos_rayon_threads`, its saturation via the per-thread CPU
time that naming now makes attributable, and its queueing via the
blocking-pool wait that precedes it.

The snarkVM bump carries the matching VM-side series, which show whether
verification work is a cache hit and how long speculation holds the
ledger.

Co-authored-by: Cursor <cursoragent@cursor.com>
brunoffranca and others added 8 commits September 14, 2026 10:40
… cert, previous-cert refs, rounds per block)

These metrics aren't derivable from anything else Prometheus exports, so
external tooling has had to reconstruct them by fetching and parsing raw
blocks from the REST API instead of scraping.
These flags default to the protocol maxima and reject larger values, so a node can reduce CPU and memory pressure without exceeding VM and network limits.

Co-authored-by: Cursor <cursoragent@cursor.com>
This lets local and test builds disable the global state root existence check without patching snarkVM.

Co-authored-by: Cursor <cursoragent@cursor.com>
Two 30-core validator devnets, instrumented with the thread-pool metrics
and per-thread CPU accounting, put numbers on pools that were previously
sized by assumption.

The 60 worker threads spent 0.63 cores of a 30-core box running tasks --
two percent of one core's worth of work per core provisioned. The comment
justifying 2x cores said the node is I/O-bound, but that is an argument
for more tasks, not more workers: an async worker multiplexes many I/O
tasks, and every CPU-bound path already leaves the runtime through
`spawn_blocking!` and fans out onto rayon. The surplus workers bought no
parallelism and gave the OS 30 more threads to schedule against rayon's
30, on the same 30 cores. Worker parks and no-op wakeups peaked at 734
per second, which is what that surplus costs.

The blocking pool moves from 512 to 256. This is a smaller cut than the
idle-thread counts first suggested: the pool averaged 69 threads with 66
of them idle, but threads linger after their task finishes, so that
understates demand. Pairing the two counters sample by sample puts peak
concurrent blocking work at 134 threads, p99 at 43. A cap near that peak
would convert bursts into queueing ahead of rayon, so 256 leaves close to
2x headroom over the highest concurrency observed while still bounding
how many callers can pile into a 30-thread rayon pool at once.

Rayon is unchanged at one thread per core. It was the busiest of the
three pools and still peaked at only 23% of its width, so there is no
case for widening it, and none for splitting block production into a pool
of its own.

`snarkos_cpu_blocking_wait_secs` is the metric that would catch this
going wrong: it sat at 0.1 ms p99 with the old cap, and should not move.

Co-authored-by: Cursor <cursoragent@cursor.com>
vicsn and others added 4 commits September 18, 2026 13:11
Roughly half the transactions submitted to a stress-test devnet never
reached a block, and no metric could say why. The gap was inferred by
comparing two cumulative counters; nothing reported the live queue, and
nothing reported transmissions the node discarded.

Building a batch proposal pops every transmission off the worker with
`remove_front`. From that moment each one is either proposed, explicitly
put back, or gone -- and only three paths put it back: `batch_full`,
`worker_limit` and `spend_limit`. The other ten exits from the selection
loop drop the transmission for good, each behind a `trace!` or `debug!`
that production nodes do not record. A transaction can therefore be
accepted into the mempool, pass verification, and then be destroyed
without incrementing anything.

`snarkos_bft_proposal_transmissions_total` now labels every exit by
`outcome`, so the disposition of a proposal is a breakdown rather than an
inference. The distinction the stress test needs is between
`invalid_transaction`, which means re-verification failed against ledger
state that moved since admission, and the capacity outcomes, which mean
the node simply ran out of room. Those imply completely different fixes
and were previously indistinguishable.

`contains_transmission` was consumed with `unwrap_or(true)`, so a storage
error discarded the transmission as though the ledger already held it.
That is still the behaviour, but it now reports `ledger_error` rather than
hiding among genuine duplicates.

Two gauges cover the queues that had no instrumentation at all.
`snarkos_bft_worker_ready_depth` is sampled just before the drain, so the
outcome counts read as a breakdown of it.
`snarkos_consensus_inbound_deployments_depth` and its execution
counterpart are sampled before the capacity check that can return early,
so a node refusing to forward still reports its depth instead of going
quiet. Neither duplicates `snarkos_consensus_unconfirmed_transactions_total`,
which only ever counts up and so reports everything admitted since startup
rather than what is waiting now.

Co-authored-by: Cursor <cursoragent@cursor.com>
Measured on a five-validator devnet: rounds take 1.28s and blocks 2.55s
at two rounds per block. MIN_BATCH_DELAY is 1s, so it accounts for most
of a round; MAX_BATCH_DELAY is 2.5s and never binds, because the leader
certificate signal arrives long before the timeout. Lowering
MAX_BATCH_DELAY would therefore not shorten a single round. It would only
shrink the four timeouts derived from it, giving transmission fetches
less time and declaring leaders failed sooner.

That leaves MIN_BATCH_DELAY as the only one of the two that could move
block time, and it cannot be moved from one node.
`check_peer_proposal_timestamp` applies it to *other* validators'
proposals and refuses to sign anything that arrives too soon after the
author's previous certificate. A node running a shorter delay proposes at
a cadence the rest of the network rejects, so its batches never reach
quorum. Changing the value means upgrading every validator at once.

Worse, a sub-second value cannot express what it appears to. Batch
timestamps are whole seconds -- `helpers::now()` returns
`unix_timestamp()` -- and the check compares them with `as_secs()`. Set
the constant to 500ms and `as_secs()` yields zero, so the comparison
becomes `elapsed < 0`, which is never true: the anti-spam check the
constant exists to provide is silently removed rather than tightened.

Nothing here changes behaviour. The values are untouched; the reasoning
is written down next to them, and a const assertion turns the sub-second
footgun into a build failure instead of a quiet loss of peer validation.
Verified by temporarily setting 500ms and confirming the build fails with
the assertion message.

Co-authored-by: Cursor <cursoragent@cursor.com>

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants