From f437439734d0af126edcb042b322d571e50184cc Mon Sep 17 00:00:00 2001 From: chrispalaskas Date: Thu, 6 Aug 2026 14:37:34 -0400 Subject: [PATCH 1/3] feat(node): phase-level timing logs for Midnight tx processing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Instruments the ledger host API so every Midnight transaction reports where its time goes, on the dedicated `midnight::tx_timing` log target (`-l midnight::tx_timing=debug`). One `key=value` line per ledger host call — validate_tx (mempool), pre_dispatch, apply_tx, apply_system_tx, post_block_update — carrying a delta per phase: deserialization, state load, strict-cache lookup, well_formed() proof verification, transaction context, guaranteed-execution dry run, cost model, LedgerState::apply, UTXO bookkeeping and persistence. Spans are emitted on error paths too, so a rejected transaction still shows how much time it burned first. This replaces the cumulative-elapsed traces in apply_transaction and post_block_update, which could not be differenced into per-phase costs. A BlockImport wrapper on the import queue adds one `op=block_import` line per block, bracketing the whole import (WASM execution, weight accounting, state root, database commit) and reporting the ledger's share as `ledger_pct`. `ledger_ms` includes pre_dispatch: the Bare extrinsic path runs ValidateUnsigned::pre_dispatch at dispatch time, which is where a syncing node actually pays for proof verification. Nothing is formatted or allocated while the target is disabled; the process-wide counters cost a few relaxed atomic adds per transaction. See docs/tx-processing-profiling.md. Assisted-by: Claude:claude-opus-5 Signed-off-by: chrispalaskas --- .../node/added/tx-processing-phase-timing.md | 35 ++ docs/tx-processing-profiling.md | 171 +++++ ledger/src/versions/common/api/ledger.rs | 4 + ledger/src/versions/common/mod.rs | 228 +++---- node/src/block_import_timing.rs | 124 ++++ node/src/lib.rs | 1 + node/src/service.rs | 9 +- primitives/ledger/src/lib.rs | 2 + primitives/ledger/src/tx_timing.rs | 585 ++++++++++++++++++ 9 files changed, 1025 insertions(+), 134 deletions(-) create mode 100644 changes/node/added/tx-processing-phase-timing.md create mode 100644 docs/tx-processing-profiling.md create mode 100644 node/src/block_import_timing.rs create mode 100644 primitives/ledger/src/tx_timing.rs diff --git a/changes/node/added/tx-processing-phase-timing.md b/changes/node/added/tx-processing-phase-timing.md new file mode 100644 index 000000000..0ce078b9c --- /dev/null +++ b/changes/node/added/tx-processing-phase-timing.md @@ -0,0 +1,35 @@ +#observability #performance +# Add phase-level timing logs for Midnight transaction processing + +Instruments the ledger host API so that every Midnight transaction reports where +its time goes, on the dedicated `midnight::tx_timing` log target +(`-l midnight::tx_timing=debug`). + +One `key=value` line per ledger host call — `validate_tx` (mempool), +`pre_dispatch`, `apply_tx`, `apply_system_tx`, `post_block_update` — carrying a +delta per phase: deserialization, ledger state load, strict-cache lookup, +`well_formed()` proof verification, transaction context, guaranteed-execution dry +run, cost model, `LedgerState::apply`, UTXO bookkeeping, and persistence. Spans +are emitted on error paths too, so a rejected transaction still shows how much +time it burned before rejection. This replaces the cumulative-elapsed `⏱️` traces +in `apply_transaction` and `post_block_update`, which could not be differenced +into per-phase costs. + +A `BlockImport` wrapper on the import queue adds one `op=block_import` line per +block, bracketing the whole import (WASM execution, weight accounting, state +root, database commit) and reporting the ledger's share of it as `ledger_pct` — +so "how much of the node's time is Midnight transaction processing" can be +answered per block. `ledger_ms` sums the block-execution ops, `pre_dispatch` +included: the `Bare` extrinsic path runs `ValidateUnsigned::pre_dispatch` at +dispatch time, which is where a syncing node actually pays for proof +verification. Because the wrapper sits on the import path, syncing a fixed chain +with the target enabled is a repeatable profile of block execution. + +Nothing is formatted or allocated while the target is disabled. Process-wide +counters (`tx_timing::Totals`) are maintained regardless, at the cost of a few +relaxed atomic adds per transaction. + +See `docs/tx-processing-profiling.md` for the field reference, the authoring-node +caveats, and aggregation one-liners. + +PR: diff --git a/docs/tx-processing-profiling.md b/docs/tx-processing-profiling.md new file mode 100644 index 000000000..8b906408d --- /dev/null +++ b/docs/tx-processing-profiling.md @@ -0,0 +1,171 @@ +# Profiling Midnight transaction processing + +The node emits phase-level timing for every Midnight transaction it touches, on +its own log target so it can be switched on without the rest of the ledger's +debug output: + +```bash +midnight-node ... -l midnight::tx_timing=debug +``` + +Nothing is formatted or allocated while the target is disabled, and the +block-import wrapper short-circuits entirely, so leaving the code in place costs +effectively nothing. + +Two kinds of line come out: one per ledger host call (`op=apply_tx`, +`op=validate_tx`, …) and one per imported block (`op=block_import`). Both are +flat `key=value`, which is what makes them worth having over ad-hoc `⏱️` traces — +they aggregate with `awk` instead of by eye. + +## What gets measured + +The pre-block path for one transaction crosses the ledger host API three times. +Each crossing is a separate span, and a transaction that is rejected midway +still logs (with `outcome=err`), showing how much time was burned before the +rejection. + +| Span | Host function | When | +| --- | --- | --- | +| `validate_tx` | `validate_transaction` | Mempool admission and revalidation (`validate_unsigned`) | +| `pre_dispatch` | `validate_guaranteed_execution` | Dispatch-time check, run as part of block execution — authoring *and* import/sync | +| `apply_tx` | `apply_transaction` | Executing the tx as part of a block — authoring *and* import/sync | +| `apply_system_tx` | `apply_system_transaction` | System transactions | +| `post_block_update` | `post_block_update`, `apply_post_block_update` | End-of-block ledger transition | + +Phases within a span (`_us`, in call order): + +| Phase | Meaning | +| --- | --- | +| `deserialize_us` | Tagged deserialization of the tx blob | +| `load_state_us` | Ledger state load (arena, possibly a parity-db read) | +| `state_hash_us` | Hashing state for the strict validation cache key | +| `proof_cache_hit_us` / `proof_cache_lookup_us` | Strict-cache lookup for an existing `VerifiedTransaction` | +| `proof_verify_us` | `well_formed()` — **ZK proof verification**, normally the dominant cost on a cache miss | +| `tx_context_us` | Building the `TransactionContext` | +| `guaranteed_dry_run_us` | Dry run of the guaranteed segment | +| `tx_cost_us` | Cost-model evaluation and block-fullness prevalidation | +| `ledger_apply_us` | `LedgerState::apply` — the state transition, including Impact execution of contract calls | +| `arena_alloc_us`, `unshielded_utxos_us`, `serialize_state_root_us`, `tx_operations_us` | Bookkeeping around the apply | +| `cache_key_us`, `soft_cache_lookup_us`, `proof_verify_setup_us`, `proof_cache_insert_us`, `tx_cost_and_details_us` | Smaller steps, listed so that the phases sum to `total_us` | +| `persist_us` | Writing the new state into the arena / to disk | + +Useful fields: `tx` (hash), `size` (bytes), `tx_type`, `proof=hit|miss` (whether +proof verification was skipped), `soft_cache=hit|miss`, `ops`, `utxos_created`, +`utxos_spent`, `outcome=ok|err`. + +Example (line wrapped here, one line in the log): + +``` +op=apply_tx outcome=ok total_us=48213 size=54321 tx=3f9a… proof=miss tx_type=standard + deserialize_us=1204 load_state_us=93 state_hash_us=41 proof_cache_lookup_us=8 + proof_verify_setup_us=210 proof_verify_us=41880 proof_cache_insert_us=57 + tx_context_us=12 tx_cost_us=180 ledger_apply_us=3204 arena_alloc_us=90 + unshielded_utxos_us=210 serialize_state_root_us=390 tx_operations_us=12 persist_us=622 +``` + +Read that as: 87% of this transaction was ZK proof verification, because it +reached `apply_transaction` with a cold strict cache. + +**Which span pays for proof verification depends on the path.** The `Bare` +extrinsic path runs `ValidateUnsigned::pre_dispatch` as the transaction is +dispatched, so on a **syncing/importing** node the `well_formed()` cost normally +lands in `pre_dispatch` (`proof=miss`) and the following `apply_tx` is a +`proof=hit`. On an **authoring** node the mempool has usually already verified +the transaction, so `validate_tx` pays it and the rest hit the cache. Summing +`proof_verify_us` across spans — rather than looking at `apply_tx` alone — is +what gives the real cost per transaction. + +## Where the block's time goes + +`op=block_import` closes the loop on "how much of the node's time is Midnight +transaction processing". It brackets the whole import — WASM execution, weight +accounting, state root, database commit — and attributes the ledger's share of +it: + +``` +op=block_import outcome=ok number=1234 hash=0x… extrinsics=12 total_ms=421.310 + ledger_ms=380.102 ledger_pct=90.2 mn_txs=8 system_txs=1 + apply_tx_ms=150.300 pre_dispatch_ms=225.800 post_block_update_ms=4.002 + deserialize_ms=9.100 deserialize_pct=2.2 ... proof_verify_ms=210.400 proof_verify_pct=50.0 + ledger_apply_ms=140.200 ledger_apply_pct=33.3 persist_ms=12.900 persist_pct=3.1 + validate_tx_ms=0.000 validate_tx_count=0 +``` + +`ledger_pct` is the answer: everything else in `total_ms` is Substrate +machinery. `ledger_ms` is the sum of the block-execution ops — `apply_tx`, +`pre_dispatch`, `apply_system_tx`, `post_block_update` — each of which is also +broken out. `validate_tx_ms` (mempool) is *not* included. + +Two caveats: + +- The counters behind these numbers are process-wide, and only the wall-clock + window is per-block. On an **authoring** node, ledger work from a concurrent + proposal or from mempool validation running on another thread lands in the same + window and inflates `ledger_ms`. A non-authoring node that is importing or + syncing does all of its ledger work on the import path, so its numbers are + clean; `validate_tx_ms` being non-zero is the signal that something else was + running alongside. +- The wrapper sits on the import queue, so blocks this node *authors* never reach + it — they are imported by the authorship task with state already computed. For + the authoring side, use the per-transaction spans plus Substrate's own + `🎁 Prepared block for proposing at #N` timing as the denominator. + +## Sync as a repeatable benchmark + +Block import is the same machinery as block production minus the proposer, so +syncing a fixed chain with these logs on is a repeatable profile: point a fresh +node at a snapshot, sync N blocks, aggregate the lines. Same input, same work, +directly comparable across code changes. + +```bash +midnight-node ... -l midnight::tx_timing=debug 2>&1 | tee sync.log +``` + +## Aggregating + +Mean and share per phase across all applied transactions: + +```bash +grep 'op=apply_tx' sync.log \ + | tr ' ' '\n' | grep '_us=' \ + | awk -F'[=]' '{sum[$1]+=$2; n[$1]++} END {for (k in sum) printf "%-28s %10.1f us avg %12.0f us total\n", k, sum[k]/n[k], sum[k]}' \ + | sort -k4 -nr +``` + +Proof-verification share of block import, per block: + +```bash +grep 'op=block_import' sync.log \ + | sed -E 's/.*number=([0-9]+).*total_ms=([0-9.]+).*ledger_pct=([0-9.]+).*proof_verify_pct=([0-9.]+).*/\1 \2 \3 \4/' \ + | awk '{printf "block %-8s total %8.1fms ledger %5.1f%% proofs %5.1f%%\n", $1, $2, $3, $4}' +``` + +Total proof verification, wherever it was paid, versus everything else: + +```bash +awk '/op=(apply_tx|pre_dispatch|validate_tx) /{ + for (i=1;i<=NF;i++) { split($i,kv,"="); k[kv[1]]=kv[2] } + total[k["op"]] += k["total_us"]; proofs += k["proof_verify_us"]; delete k + } + END { for (op in total) printf "%-14s %12.0f us\n", op, total[op]; + printf "%-14s %12.0f us\n", "proof_verify", proofs }' sync.log +``` + +Cache-miss rate per span — if the same transaction misses in more than one span, +proof verification is being paid more than once: + +```bash +for op in validate_tx pre_dispatch apply_tx; do + printf '%-13s hit=%s miss=%s\n' "$op" \ + "$(grep -c "op=$op .*proof=hit" sync.log)" \ + "$(grep -c "op=$op .*proof=miss" sync.log)" +done +``` + +## Relationship to the Prometheus metrics + +`ledger_txs_processing_time`, `ledger_txs_validating_time` and the +`ledger_tx_validation_cache_*` counters still report the same per-op totals and +are the right thing for dashboards and long-running networks. The timing logs +are for the question those cannot answer — *which phase inside the op* — and for +one-off profiling runs where you want per-transaction detail. diff --git a/ledger/src/versions/common/api/ledger.rs b/ledger/src/versions/common/api/ledger.rs index be9b687e8..95b0af692 100644 --- a/ledger/src/versions/common/api/ledger.rs +++ b/ledger/src/versions/common/api/ledger.rs @@ -26,6 +26,7 @@ use ledger_storage_local::{ }; use helpers_local::{StorableSyntheticCost, compute_overall_fullness}; +use midnight_primitives_ledger::tx_timing::{self, Phase as TimedPhase}; use midnight_serialize_local::{self as serialize, Tagged}; use mn_ledger_local::{ semantics::{TransactionContext, TransactionResult}, @@ -168,11 +169,14 @@ impl Ledger { &sp.state.parameters.limits.block_limits, "apply_verified_transaction", )?; + tx_timing::mark("tx_cost"); let (next_state, result) = sp.state.apply(verified_tx, ctx); + tx_timing::mark_agg(TimedPhase::LedgerApply); let new_sp = default_storage::() .arena .alloc(Ledger { state: next_state, block_fullness: next_block_fullness.into() }); + tx_timing::mark("arena_alloc"); match result { TransactionResult::Success(_) => Ok((new_sp, AppliedStage::AllApplied)), diff --git a/ledger/src/versions/common/mod.rs b/ledger/src/versions/common/mod.rs index beafa2c82..dbaf911a2 100644 --- a/ledger/src/versions/common/mod.rs +++ b/ledger/src/versions/common/mod.rs @@ -67,6 +67,7 @@ use { }, midnight_primitives_ledger::{ LedgerMetricsExt, LedgerStorageDb, LedgerStorageExt, TBlockCorrection, TBlockCorrectionExt, + tx_timing::{self, Op as TimedOp, Phase as TimedPhase}, }, mn_ledger_local::{ dust::InitialNonce, @@ -246,51 +247,29 @@ where state_key: &[u8], block_context: BlockContext, ) -> Result, LedgerApiError> { - let start_tx_processing_time = Instant::now(); - log::trace!( - target: LOG_TARGET, - "⏱️ Initializing API (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + let _timing = tx_timing::span(TimedOp::PostBlockUpdate); + // Both host functions share one op; this says which of the two ran. + tx_timing::note("variant", "fallible"); + let api = api::new(); - log::trace!( - target: LOG_TARGET, - "⏱️ API ready (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); let ledger = Self::get_ledger(&api, state_key)?; + tx_timing::mark_agg(TimedPhase::LoadState); - log::trace!( - target: LOG_TARGET, - "⏱️ Post block update start (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); let mut ledger = Ledger::post_block_update(ledger, block_context).inspect_err(|e| { log::error!( target: LOG_TARGET, "Post Block Update error: {e:?}" ); })?; - log::trace!( - target: LOG_TARGET, - "⏱️ Post block update done (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::mark_agg(TimedPhase::LedgerApply); let state_root = api.tagged_serialize(&ledger.as_typed_key())?; + tx_timing::mark("serialize_state_root"); // Only update state after no errors - log::trace!( - target: LOG_TARGET, - "⏱️ Persisting ledger (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); ledger.persist(); - log::trace!( - target: LOG_TARGET, - "⏱️ Ledger persisted (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::mark_agg(TimedPhase::Persist); + tx_timing::ok(); Ok(state_root) } @@ -304,11 +283,19 @@ where state_key: &[u8], block_context: BlockContext, ) -> Result, LedgerApiError> { + let _timing = tx_timing::span(TimedOp::PostBlockUpdate); + tx_timing::note("variant", "infallible"); + let api = api::new(); let ledger = Self::get_ledger(&api, state_key)?; + tx_timing::mark_agg(TimedPhase::LoadState); let mut ledger = Ledger::apply_post_block_update(ledger, block_context); + tx_timing::mark_agg(TimedPhase::LedgerApply); let state_root = api.tagged_serialize(&ledger.as_typed_key())?; + tx_timing::mark("serialize_state_root"); ledger.persist(); + tx_timing::mark_agg(TimedPhase::Persist); + tx_timing::ok(); Ok(state_root) } @@ -331,19 +318,15 @@ where let start_tx_processing_time = Instant::now(); let tx_size = tx_serialized.len(); - log::trace!( - target: LOG_TARGET, - "⏱️ Starting tx processing (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + // Phase timing on the `midnight::tx_timing` target; see `tx_timing`'s docs. + let _timing = tx_timing::span(TimedOp::ApplyTx); + tx_timing::note("size", tx_size); + let api = api::new(); - log::trace!( - target: LOG_TARGET, - "⏱️ Deserializing tx (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); let tx = api.tagged_deserialize::>(tx_serialized)?; let tx_hash = tx.hash(); + tx_timing::mark_agg(TimedPhase::Deserialize); + tx_timing::note_with("tx", || hex::encode(tx_hash)); log::info!( target: LOG_TARGET, "📥 Applying transaction {}", @@ -351,11 +334,7 @@ where ); let ledger = Self::get_ledger(&api, state_key)?; utxo_ordering_override::set_network_id(&ledger.state.network_id); - log::trace!( - target: LOG_TARGET, - "⏱️ Ledger loaded (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::mark_agg(TimedPhase::LoadState); let initial_utxos_size = ledger.state.utxo.utxos.size(); // Use cached VerifiedTransaction if available @@ -369,33 +348,14 @@ where &cache_key, tblock_correction, )?; - log::trace!( - target: LOG_TARGET, - "⏱️ Building tx context (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); // Apply the verified transaction let tx_ctx = ledger.get_transaction_context(block_context.clone())?; - log::trace!( - target: LOG_TARGET, - "⏱️ Tx context ready (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::mark("tx_context"); let (mut new_ledger, applied_stage) = Ledger::apply_verified_transaction(ledger, &api, &tx, &verified_tx, &tx_ctx)?; - log::trace!( - target: LOG_TARGET, - "⏱️ Ledger applied (stage={applied_stage:?}, elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); let all_applied = matches!(applied_stage, TransactionAppliedStage::AllApplied); - log::trace!( - target: LOG_TARGET, - "⏱️ Building unshielded UTXOs (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); let mut utxos = tx.unshielded_utxos(); let failed_segments = @@ -406,20 +366,13 @@ where } else { None }; - log::trace!( - target: LOG_TARGET, - "⏱️ Unshielded UTXOs ready (failed_segments={}, elapsed_ms={})", + tx_timing::note( + "failed_segments", failed_segments.as_ref().map(|segments: &Vec| segments.len()).unwrap_or(0), - start_tx_processing_time.elapsed().as_millis() ); let operations = tx.calls_and_deploys(should_skip_failed_segments.then_some(failed_segments).flatten()); - log::trace!( - target: LOG_TARGET, - "⏱️ Ops built (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); // Capture segment counts before flattening — the HashMap→BTreeMap fix // only changes ordering between segments, not within a single segment. @@ -435,13 +388,9 @@ where ordering.apply(&mut utxo_outputs, output_segments, &mut utxo_inputs, input_segments); } - log::trace!( - target: LOG_TARGET, - "⏱️ UTXO integrity ok (created={}, spent={}, elapsed_ms={})", - utxo_outputs.len(), - utxo_inputs.len(), - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::note("utxos_created", utxo_outputs.len()); + tx_timing::note("utxos_spent", utxo_inputs.len()); + tx_timing::mark("unshielded_utxos"); let mut event = TransactionAppliedStateRoot { state_root: api.tagged_serialize(&new_ledger.as_typed_key())?, @@ -454,84 +403,48 @@ where unshielded_utxos_created: utxo_outputs, unshielded_utxos_spent: utxo_inputs, }; - log::trace!( - target: LOG_TARGET, - "⏱️ Event built (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::mark("serialize_state_root"); + let mut op_count = 0usize; for op in operations { + op_count += 1; match op { TransactionOperation::Call { address, .. } => { event.call_addresses.push(api.tagged_serialize(&address)?); - log::trace!( - target: LOG_TARGET, - "⏱️ Tx op: Call (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); }, TransactionOperation::Deploy { address } => { event.deploy_addresses.push(api.tagged_serialize(&address)?); - log::trace!( - target: LOG_TARGET, - "⏱️ Tx op: Deploy (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); }, TransactionOperation::Maintain { address } => { event.maintain_addresses.push(api.tagged_serialize(&address)?); - log::trace!( - target: LOG_TARGET, - "⏱️ Tx op: Maintain (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); }, TransactionOperation::ClaimRewards { value } => { event.claim_rewards.push(value); - log::trace!( - target: LOG_TARGET, - "⏱️ Tx op: ClaimRewards (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); }, TransactionOperation::ClaimBridgeTransfer { value } => { event.claim_rewards.push(value); - log::trace!( - target: LOG_TARGET, - "⏱️ Tx op: ClaimBridgeTransfer (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); }, } } + tx_timing::note("ops", op_count); + tx_timing::mark("tx_operations"); // Only update state after no errors - log::trace!( - target: LOG_TARGET, - "⏱️ Persisting ledger (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); new_ledger.persist(); - log::trace!( - target: LOG_TARGET, - "⏱️ Ledger persisted (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::mark_agg(TimedPhase::Persist); + + let tx_type = Self::get_tx_type(&tx); + tx_timing::note("tx_type", tx_type); // Write Prometheus metrics let maybe_metrics = externalities.extension::(); if let Some(metrics) = maybe_metrics { - let tx_type = Self::get_tx_type(&tx); let elapsed_time = start_tx_processing_time.elapsed().as_secs_f64(); metrics.observe_txs_processing_time(elapsed_time, tx_type); metrics.observe_txs_size(tx_size as f64, tx_type); } - log::trace!( - target: LOG_TARGET, - "✅ Tx applied (elapsed_ms={})", - start_tx_processing_time.elapsed().as_millis() - ); + tx_timing::ok(); Ok(event) } @@ -546,27 +459,36 @@ where let start_system_tx_processing_time = Instant::now(); let tx_size = tx_serialized.len(); + let _timing = tx_timing::span(TimedOp::ApplySystemTx); + tx_timing::note("size", tx_size); + let api = api::new(); let tx = api.tagged_deserialize::(tx_serialized)?; let tx_type = Self::get_system_tx_type(&tx)?; + tx_timing::mark_agg(TimedPhase::Deserialize); + tx_timing::note("tx_type", tx_type); log::info!( target: LOG_TARGET, "⚙️ Processing SystemTx {tx:?}" ); let tx_hash = tx.transaction_hash().0.0; let ledger = Self::get_ledger(&api, state_key)?; + tx_timing::mark_agg(TimedPhase::LoadState); let mut ledger = Ledger::apply_system_tx(ledger, &tx, Timestamp::from_secs(block_context.tblock))?; + tx_timing::mark_agg(TimedPhase::LedgerApply); let event = SystemTransactionAppliedStateRoot { state_root: api.tagged_serialize(&ledger.as_typed_key())?, tx_hash, tx_type: tx_type.to_string(), }; + tx_timing::mark("serialize_state_root"); // Only update state after no errors ledger.persist(); + tx_timing::mark_agg(TimedPhase::Persist); // Write Prometheus metrics let maybe_metrics = externalities.extension::(); @@ -576,6 +498,7 @@ where metrics.observe_system_txs_processing_time(elapsed_time, tx_type); metrics.observe_txs_size(tx_size as f64, tx_type); } + tx_timing::ok(); Ok(event) } @@ -593,22 +516,32 @@ where // Gather metrics for Prometheus let start_tx_validation_time = Instant::now(); + let _timing = tx_timing::span(TimedOp::ValidateTx); + tx_timing::note("size", tx_serialized.len()); + let api = api::new(); let tx = api.tagged_deserialize::>(tx_serialized)?; + tx_timing::mark_agg(TimedPhase::Deserialize); + tx_timing::note_with("tx", || hex::encode(tx.hash())); let ledger = Self::get_ledger(&api, state_key)?; + tx_timing::mark_agg(TimedPhase::LoadState); let wrapped_cache_key = Self::tx_validation_cache_key(runtime_version, tx_serialized); + tx_timing::mark("cache_key"); // No `tblock` correction on the mempool path: `validate_unsigned` already skews the // block context it passes here by `slot_duration * (1 + MaxSkippedSlots)`. let was_cached = Self::do_validate_transaction(&ledger, &tx, &block_context, &wrapped_cache_key)?; + tx_timing::note("soft_cache", if was_cached { "hit" } else { "miss" }); let tx_details = if get_tx_details { let tx_gas_cost = Self::get_transaction_cost(state_key, tx_serialized, &block_context, max_weight)?; - Some(Self::get_transaction_details(&tx, &ledger, tx_gas_cost)?) + let details = Some(Self::get_transaction_details(&tx, &ledger, tx_gas_cost)?); + tx_timing::mark("tx_cost_and_details"); + details } else { None }; @@ -631,6 +564,7 @@ where .set_tx_validation_cache_size("strict", STRICT_TX_VALIDATION_CACHE.entry_count()); metrics.set_tx_validation_cache_size("soft", SOFT_TX_VALIDATION_CACHE.entry_count()); } + tx_timing::ok(); Ok((wrapped_cache_key.0, tx_details)) } @@ -653,11 +587,18 @@ where where VerifiedTransaction: Send + Sync + 'static, { + let _timing = tx_timing::span(TimedOp::PreDispatch); + tx_timing::note("size", tx_serialized.len()); + let api = api::new(); let tx = api.tagged_deserialize::>(tx_serialized)?; + tx_timing::mark_agg(TimedPhase::Deserialize); + tx_timing::note_with("tx", || hex::encode(tx.hash())); let ledger = Self::get_ledger(&api, state_key)?; + tx_timing::mark_agg(TimedPhase::LoadState); let cache_key = Self::tx_validation_cache_key(runtime_version, tx_serialized); + tx_timing::mark("cache_key"); let tblock_ext = externalities.extension::(); let tblock_correction = tblock_ext.map(|e| &e.0); @@ -683,6 +624,7 @@ where .set_tx_validation_cache_size("strict", STRICT_TX_VALIDATION_CACHE.entry_count()); metrics.set_tx_validation_cache_size("soft", SOFT_TX_VALIDATION_CACHE.entry_count()); } + tx_timing::ok(); Ok(()) } @@ -969,26 +911,35 @@ where tx_hash: tx_hash.0, block_context_tblock: block_context.tblock, }; + tx_timing::mark("state_hash"); // Check strict cache if let Some(cached) = STRICT_TX_VALIDATION_CACHE.get(&strict_key) { if let Some(vt) = cached.downcast_ref::>() { + // Proof verification skipped entirely — the dominant cost of a tx, + // so which side of this branch a tx took dictates its total. + tx_timing::note("proof", "hit"); + tx_timing::mark_agg(TimedPhase::ProofCacheHit); return Ok(vt.clone()); } // Downcast failed - fall through to recompute log::warn!(target: LOG_TARGET, "VerifiedTransaction cache downcast failed"); } + tx_timing::note("proof", "miss"); + tx_timing::mark("proof_cache_lookup"); // Cache miss: compute VerifiedTransaction let ctx = ledger.get_transaction_context(block_context.clone())?; let tblock = well_formed_tblock(ledger, block_context, tblock_correction); + tx_timing::mark("proof_verify_setup"); let verified_tx = tx.0.well_formed( &ctx.ref_state, mn_ledger_local::verify::WellFormedStrictness::default(), tblock, ) + .inspect_err(|_| tx_timing::mark_agg(TimedPhase::ProofVerification)) .map_err(|e| { log::warn!( target: LOG_TARGET, @@ -996,9 +947,11 @@ where ); LedgerApiError::Transaction(types::TransactionError::Malformed(e.into())) })?; + tx_timing::mark_agg(TimedPhase::ProofVerification); // Cache in strict cache (soft cache is managed by do_validate_transaction) STRICT_TX_VALIDATION_CACHE.insert(strict_key, Arc::new(verified_tx.clone())); + tx_timing::mark("proof_cache_insert"); Ok(verified_tx) } @@ -1022,6 +975,7 @@ where // Check soft cache first (quick tx_hash-only lookup for mempool revalidation) if let Some(cached) = SOFT_TX_VALIDATION_CACHE.get(&soft_key) { + tx_timing::mark("soft_cache_lookup"); return cached.map(|_| true); } @@ -1042,12 +996,16 @@ where // Dry-run the guaranteed segment against the current state. let ctx = ledger.get_transaction_context(block_context.clone())?; + tx_timing::mark("tx_context"); - match super::guaranteed_validation::validate_guaranteed_execution( + let dry_run = super::guaranteed_validation::validate_guaranteed_execution( &ledger.state, verified_tx, &ctx, - ) { + ); + tx_timing::mark_agg(TimedPhase::GuaranteedDryRun); + + match dry_run { Ok(()) => { log::info!( target: LOG_TARGET, @@ -1104,12 +1062,16 @@ where Self::get_verified_transaction(ledger, tx, block_context, tx_hash, tblock_correction)?; let ctx = ledger.get_transaction_context(block_context.clone())?; + tx_timing::mark("tx_context"); - match super::guaranteed_validation::validate_guaranteed_execution( + let dry_run = super::guaranteed_validation::validate_guaranteed_execution( &ledger.state, verified_tx, &ctx, - ) { + ); + tx_timing::mark_agg(TimedPhase::GuaranteedDryRun); + + match dry_run { Ok(()) => Ok(was_cached), Err(reason) => { log::warn!( diff --git a/node/src/block_import_timing.rs b/node/src/block_import_timing.rs new file mode 100644 index 000000000..eaa368c8b --- /dev/null +++ b/node/src/block_import_timing.rs @@ -0,0 +1,124 @@ +// This file is part of midnight-node. +// Copyright (C) Midnight Foundation +// SPDX-License-Identifier: Apache-2.0 +// Licensed under the Apache License, Version 2.0 (the "License"); +// You may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// http://www.apache.org/licenses/LICENSE-2.0 +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +//! A `BlockImport` wrapper that reports how much of each block's import time was +//! spent in the Midnight ledger. +//! +//! `midnight_primitives_ledger::tx_timing` says where the time inside one +//! transaction goes; this says how much of a *block* that adds up to. Wrapping +//! the import queue's block import gives a wall-clock denominator that includes +//! everything Substrate does around the ledger — WASM execution, weight +//! accounting, state root computation, database commit — so the residual +//! (`total_ms` minus the ledger lines) is the non-Midnight machinery. +//! +//! Because this sits on the import path it measures the same code that block +//! *sync* exercises: syncing a chain with these logs enabled is a repeatable +//! profile of block execution. +//! +//! Enable with `-l midnight::tx_timing=debug`. + +use midnight_primitives_ledger::tx_timing::{LOG_TARGET, Op, Phase, Totals}; +use sc_consensus::{ + BlockCheckParams, BlockImport, BlockImportParams, ImportResult, import_queue::BoxBlockImport, +}; +use sp_runtime::traits::{Block as BlockT, Header as HeaderT}; +use std::time::Instant; + +/// Wraps a block import, logging a per-block timing summary. +pub struct TimingBlockImport { + inner: BoxBlockImport, +} + +impl TimingBlockImport { + /// Wraps `inner`. Cheap when the timing log target is disabled: the wrapper + /// then does nothing beyond delegating. + pub fn new(inner: BoxBlockImport) -> Self { + Self { inner } + } +} + +#[async_trait::async_trait] +impl BlockImport for TimingBlockImport { + type Error = sp_consensus::error::Error; + + async fn check_block(&self, block: BlockCheckParams) -> Result { + self.inner.check_block(block).await + } + + async fn import_block(&self, block: BlockImportParams) -> Result { + if !log::log_enabled!(target: LOG_TARGET, log::Level::Debug) { + return self.inner.import_block(block).await; + } + + let number = *block.header.number(); + let hash = block.post_hash(); + let extrinsics = block.body.as_ref().map(|body| body.len()).unwrap_or(0); + + let totals_before = Totals::snapshot(); + let started = Instant::now(); + let result = self.inner.import_block(block).await; + let total = started.elapsed(); + let delta = Totals::snapshot().since(&totals_before); + + // `pre_dispatch` is part of block execution, not just authoring: the Bare + // extrinsic path runs `ValidateUnsigned::pre_dispatch` as the transaction is + // dispatched, so on a syncing node that is where `well_formed()` proof + // verification is actually paid (`apply_tx` then hits the strict cache). + // `validate_tx` is the mempool-only op and is reported separately — the + // counters are process-wide, so on an authoring node it can pick up work + // from another thread inside this window. + let ledger_nanos = delta.op(Op::ApplyTx).nanos + + delta.op(Op::ApplySystemTx).nanos + + delta.op(Op::PreDispatch).nanos + + delta.op(Op::PostBlockUpdate).nanos; + let total_nanos = total.as_nanos() as u64; + let pct = |nanos: u64| -> f64 { + if total_nanos == 0 { 0.0 } else { nanos as f64 * 100.0 / total_nanos as f64 } + }; + + let mut line = format!( + "op=block_import outcome={} number={number} hash={hash} extrinsics={extrinsics} \ + total_ms={:.3} ledger_ms={:.3} ledger_pct={:.1} mn_txs={} system_txs={} \ + apply_tx_ms={:.3} pre_dispatch_ms={:.3} post_block_update_ms={:.3}", + if result.is_ok() { "ok" } else { "err" }, + total.as_secs_f64() * 1_000.0, + ledger_nanos as f64 / 1_000_000.0, + pct(ledger_nanos), + delta.op(Op::ApplyTx).count, + delta.op(Op::ApplySystemTx).count, + delta.op(Op::ApplyTx).millis(), + delta.op(Op::PreDispatch).millis(), + delta.op(Op::PostBlockUpdate).millis(), + ); + for phase in Phase::ALL { + let counter = delta.phase(phase); + line.push_str(&format!( + " {}_ms={:.3} {}_pct={:.1}", + phase.as_str(), + counter.millis(), + phase.as_str(), + pct(counter.nanos), + )); + } + // Mempool validation is not part of block import; surfaced so that a + // window where it dominates the CPU is visible rather than confusing. + line.push_str(&format!( + " validate_tx_ms={:.3} validate_tx_count={}", + delta.op(Op::ValidateTx).millis(), + delta.op(Op::ValidateTx).count, + )); + log::debug!(target: LOG_TARGET, "{line}"); + + result + } +} diff --git a/node/src/lib.rs b/node/src/lib.rs index dbf613cc5..7e6aa1715 100644 --- a/node/src/lib.rs +++ b/node/src/lib.rs @@ -18,6 +18,7 @@ mod aura_to_babe_migration_keystore; pub mod backend; #[cfg(feature = "runtime-benchmarks")] pub mod benchmarking; +pub mod block_import_timing; pub mod cfg; pub mod chain_spec; pub mod cli; diff --git a/node/src/service.rs b/node/src/service.rs index 6b359d62d..54df457f7 100644 --- a/node/src/service.rs +++ b/node/src/service.rs @@ -15,6 +15,7 @@ use crate::aura_to_babe_migration_keystore::AuraToBabeMigrationKeystore; use crate::backend::{create_database_source, open_paritydb}; +use crate::block_import_timing::TimingBlockImport; use crate::cfg::midnight_cfg::StorageSeparation; use crate::main_chain_follower::create_cached_main_chain_follower_data_sources; use crate::{ @@ -34,6 +35,7 @@ use midnight_primitives_mainchain_follower::MidnightDataSourceMetrics; use parity_scale_codec::{Decode, Encode}; use partner_chains_db_sync_data_sources::register_metrics_warn_errors; use sc_client_api::{Backend, BlockImportOperation, ExecutorProvider}; +use sc_consensus::import_queue::BoxBlockImport; use sc_consensus_aura::{SlotProportion, StartAuraParams}; use sc_consensus_grandpa::SharedVoterState; use sc_consensus_slots::BackoffAuthoringOnFinalizedHeadLagging; @@ -481,9 +483,14 @@ pub fn new_partial( ), ); + // Wrapped so that every imported block reports the ledger's share of its + // import time on the `midnight::tx_timing` target (no-op unless enabled). + let timed_block_import = + TimingBlockImport::new(Box::new(grandpa_block_import.clone()) as BoxBlockImport); + let import_queue = sc_consensus::import_queue::BasicQueue::new( verifier, - Box::new(grandpa_block_import.clone()), + Box::new(timed_block_import), Some(Box::new(grandpa_block_import.clone())), &task_manager.spawn_essential_handle(), config.prometheus_registry(), diff --git a/primitives/ledger/src/lib.rs b/primitives/ledger/src/lib.rs index 8aa37ce7f..7be058d96 100644 --- a/primitives/ledger/src/lib.rs +++ b/primitives/ledger/src/lib.rs @@ -11,6 +11,8 @@ // See the License for the specific language governing permissions and // limitations under the License. +pub mod tx_timing; + use prometheus_endpoint::{ self as prometheus, CounterVec, GaugeVec, HistogramOpts, HistogramVec, Opts, PrometheusError, Registry, U64, diff --git a/primitives/ledger/src/tx_timing.rs b/primitives/ledger/src/tx_timing.rs new file mode 100644 index 000000000..18def75d2 --- /dev/null +++ b/primitives/ledger/src/tx_timing.rs @@ -0,0 +1,585 @@ +// This file is part of midnight-node. +// Copyright (C) Midnight Foundation +// SPDX-License-Identifier: Apache-2.0 +// Licensed under the Apache License, Version 2.0 (the "License"); +// You may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// http://www.apache.org/licenses/LICENSE-2.0 +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +//! Phase-level timing for Midnight transaction processing. +//! +//! Answers two questions that the existing Prometheus histograms cannot: +//! +//! 1. *Within* one transaction, where does the time go — deserialization, ledger +//! state load, ZK proof verification (`well_formed`), the guaranteed-execution +//! dry run, the ledger apply itself, or persistence? +//! 2. *Within* one block, what share of wall-clock time is Midnight transaction +//! processing versus the surrounding Substrate machinery? +//! +//! # Design +//! +//! A span is opened by [`span`] at each ledger host-function entry point and +//! lives on a thread-local stack, so code deep in the call tree (the apply, the +//! `well_formed` call site) can attribute time to it with a bare [`mark`] / +//! [`mark_agg`] call instead of threading a timer through every signature. Host +//! calls run synchronously on the calling thread, so the thread-local stack is +//! always the current call's own. +//! +//! Two independent sinks: +//! +//! - **Per-span log line** — one `key=value` line per host call on the +//! `midnight::tx_timing` target at `debug`, carrying every phase delta. Built +//! only when that target is enabled, so it costs nothing when off. +//! - **Global counters** — process-wide totals per operation and per aggregated +//! [`Phase`], always maintained (a handful of relaxed atomic adds). The node's +//! block-import wrapper diffs [`Totals::snapshot`] across one block to report +//! the ledger's share of block execution time. +//! +//! # Usage +//! +//! ```ignore +//! let _span = tx_timing::span(Op::ApplyTx); +//! tx_timing::note("tx", hex::encode(tx_hash)); +//! let tx = deserialize(bytes)?; // `?` still logs, with outcome=err +//! tx_timing::mark_agg(Phase::Deserialize); +//! ... +//! tx_timing::ok(); // marks the span successful +//! ``` +//! +//! Enable with `-l midnight::tx_timing=debug`. + +use std::{ + cell::RefCell, + fmt::Display, + sync::atomic::{AtomicU64, Ordering}, + time::{Duration, Instant}, +}; + +/// Log target for all timing output. Kept separate from `midnight::ledger_v2` so +/// that timing can be enabled without the rest of the ledger's debug chatter. +pub const LOG_TARGET: &str = "midnight::tx_timing"; + +/// A ledger host-function entry point — the unit one [`span`] measures end to end. +#[derive(Clone, Copy, PartialEq, Eq, Debug)] +pub enum Op { + /// `apply_transaction`: executing a Midnight tx as part of a block. + ApplyTx, + /// `apply_system_transaction`: executing a system tx as part of a block. + ApplySystemTx, + /// `validate_transaction`: mempool admission / revalidation. + ValidateTx, + /// `validate_guaranteed_execution`: `pre_dispatch`, i.e. the last check + /// before a tx is allowed into a block. + PreDispatch, + /// `post_block_update` / `apply_post_block_update`: the end-of-block ledger + /// transition (DUST generation and friends). + PostBlockUpdate, +} + +const OP_COUNT: usize = 5; + +impl Op { + /// Stable identifier used in log lines and metric-ish output. + pub const fn as_str(self) -> &'static str { + match self { + Op::ApplyTx => "apply_tx", + Op::ApplySystemTx => "apply_system_tx", + Op::ValidateTx => "validate_tx", + Op::PreDispatch => "pre_dispatch", + Op::PostBlockUpdate => "post_block_update", + } + } + + const fn index(self) -> usize { + match self { + Op::ApplyTx => 0, + Op::ApplySystemTx => 1, + Op::ValidateTx => 2, + Op::PreDispatch => 3, + Op::PostBlockUpdate => 4, + } + } +} + +/// Phases that are aggregated process-wide, in addition to appearing in the +/// per-span line. These are the ones worth attributing across a whole block; +/// everything else is recorded with [`mark`] and stays span-local. +#[derive(Clone, Copy, PartialEq, Eq, Debug)] +pub enum Phase { + /// Tagged-deserialization of the transaction blob. + Deserialize, + /// Loading the ledger state (arena lookup, possibly a parity-db read). + LoadState, + /// `well_formed()` — ZK proof verification and structural checks. Recorded + /// only on a cache miss; a hit records [`Phase::ProofCacheHit`] instead. + ProofVerification, + /// A `VerifiedTransaction` served from the strict cache, skipping + /// `well_formed()` entirely. + ProofCacheHit, + /// Dry run of the guaranteed segment against current state. + GuaranteedDryRun, + /// `LedgerState::apply` — the state transition itself, including on-chain + /// (Impact) execution of contract calls. + LedgerApply, + /// Writing the new ledger state into the arena / to disk. + Persist, +} + +const PHASE_COUNT: usize = 7; + +impl Phase { + /// Stable identifier; becomes the `_us` key in the per-span line. + pub const fn as_str(self) -> &'static str { + match self { + Phase::Deserialize => "deserialize", + Phase::LoadState => "load_state", + Phase::ProofVerification => "proof_verify", + Phase::ProofCacheHit => "proof_cache_hit", + Phase::GuaranteedDryRun => "guaranteed_dry_run", + Phase::LedgerApply => "ledger_apply", + Phase::Persist => "persist", + } + } + + const fn index(self) -> usize { + match self { + Phase::Deserialize => 0, + Phase::LoadState => 1, + Phase::ProofVerification => 2, + Phase::ProofCacheHit => 3, + Phase::GuaranteedDryRun => 4, + Phase::LedgerApply => 5, + Phase::Persist => 6, + } + } + + /// All phases, in `index()` order — for iterating a [`Totals`]. + pub const ALL: [Phase; PHASE_COUNT] = [ + Phase::Deserialize, + Phase::LoadState, + Phase::ProofVerification, + Phase::ProofCacheHit, + Phase::GuaranteedDryRun, + Phase::LedgerApply, + Phase::Persist, + ]; +} + +static OP_NANOS: [AtomicU64; OP_COUNT] = [const { AtomicU64::new(0) }; OP_COUNT]; +static OP_COUNTS: [AtomicU64; OP_COUNT] = [const { AtomicU64::new(0) }; OP_COUNT]; +static PHASE_NANOS: [AtomicU64; PHASE_COUNT] = [const { AtomicU64::new(0) }; PHASE_COUNT]; +static PHASE_COUNTS: [AtomicU64; PHASE_COUNT] = [const { AtomicU64::new(0) }; PHASE_COUNT]; + +/// An occurrence count and the total time it accounted for. +#[derive(Clone, Copy, Default, Debug, PartialEq, Eq)] +pub struct Counter { + pub count: u64, + pub nanos: u64, +} + +impl Counter { + /// Elapsed time in milliseconds, for display. + pub fn millis(&self) -> f64 { + self.nanos as f64 / 1_000_000.0 + } + + fn saturating_sub(self, earlier: Self) -> Self { + Counter { + count: self.count.saturating_sub(earlier.count), + nanos: self.nanos.saturating_sub(earlier.nanos), + } + } +} + +/// Process-wide timing counters, as of one point in time. +/// +/// Diff two snapshots with [`Totals::since`] to attribute time to a window (a +/// block import, say). Note that counters are process-wide: on an authoring node +/// a snapshot window around block import can also pick up work done by a +/// concurrent proposal or mempool validation on another thread. [`Op::ApplyTx`], +/// [`Op::ApplySystemTx`], [`Op::PreDispatch`] and [`Op::PostBlockUpdate`] all run +/// as part of block execution; [`Op::ValidateTx`] is the mempool-only one and is +/// worth reporting separately for exactly that reason. +#[derive(Clone, Copy, Default, Debug, PartialEq, Eq)] +pub struct Totals { + ops: [Counter; OP_COUNT], + phases: [Counter; PHASE_COUNT], +} + +impl Totals { + /// Read the current global counters. + pub fn snapshot() -> Self { + let mut totals = Totals::default(); + for i in 0..OP_COUNT { + totals.ops[i] = Counter { + count: OP_COUNTS[i].load(Ordering::Relaxed), + nanos: OP_NANOS[i].load(Ordering::Relaxed), + }; + } + for i in 0..PHASE_COUNT { + totals.phases[i] = Counter { + count: PHASE_COUNTS[i].load(Ordering::Relaxed), + nanos: PHASE_NANOS[i].load(Ordering::Relaxed), + }; + } + totals + } + + /// Counters accumulated between `earlier` and `self`. + pub fn since(&self, earlier: &Totals) -> Totals { + let mut delta = Totals::default(); + for i in 0..OP_COUNT { + delta.ops[i] = self.ops[i].saturating_sub(earlier.ops[i]); + } + for i in 0..PHASE_COUNT { + delta.phases[i] = self.phases[i].saturating_sub(earlier.phases[i]); + } + delta + } + + /// Counter for one operation. + pub fn op(&self, op: Op) -> Counter { + self.ops[op.index()] + } + + /// Counter for one aggregated phase. + pub fn phase(&self, phase: Phase) -> Counter { + self.phases[phase.index()] + } +} + +/// A single in-flight measurement. Created by [`span`]; emitted on drop. +struct Span { + op: Op, + start: Instant, + /// End of the most recent phase — the origin for the next [`mark`]. + last: Instant, + /// `(name, micros)` per phase. Only populated when logging is enabled. + phases: Vec<(&'static str, u128)>, + /// Extra context (`tx=`, `size=`, …). Only populated when logging is enabled. + fields: Vec<(&'static str, String)>, + /// Set by [`ok`]; anything else means we unwound through a `?`. + outcome: &'static str, + detailed: bool, +} + +thread_local! { + /// Stack of open spans on this thread. A stack rather than a single slot so + /// that a host call which opens a nested span (or re-enters the ledger API) + /// attributes marks to the innermost one. + static SPANS: RefCell> = const { RefCell::new(Vec::new()) }; +} + +/// Whether per-span log lines should be built. When false, spans still maintain +/// the global counters but skip all formatting and allocation. +fn detailed_enabled() -> bool { + log::log_enabled!(target: LOG_TARGET, log::Level::Debug) +} + +/// Opens a timing span for `op`. The returned guard emits the log line and +/// updates the global counters when dropped, including on an error unwind — so a +/// transaction rejected halfway through still reports where its time went. +#[must_use = "the span is measured until the guard is dropped"] +pub fn span(op: Op) -> SpanGuard { + let now = Instant::now(); + let detailed = detailed_enabled(); + // `try_with` throughout: instrumentation must never be the thing that panics, + // including on a thread whose TLS is already being torn down. + let _ = SPANS.try_with(|spans| { + if let Ok(mut spans) = spans.try_borrow_mut() { + spans.push(Span { + op, + start: now, + last: now, + phases: Vec::new(), + fields: Vec::new(), + outcome: "err", + detailed, + }) + } + }); + SpanGuard { _private: () } +} + +/// Guard returned by [`span`]. Dropping it closes the span. +pub struct SpanGuard { + _private: (), +} + +impl Drop for SpanGuard { + fn drop(&mut self) { + let popped = SPANS + .try_with(|spans| spans.try_borrow_mut().ok().and_then(|mut spans| spans.pop())) + .ok() + .flatten(); + let Some(span) = popped else { + return; + }; + let total = span.start.elapsed(); + + let idx = span.op.index(); + OP_NANOS[idx].fetch_add(total.as_nanos() as u64, Ordering::Relaxed); + OP_COUNTS[idx].fetch_add(1, Ordering::Relaxed); + + if !span.detailed { + return; + } + + let mut line = format!( + "op={} outcome={} total_us={}", + span.op.as_str(), + span.outcome, + total.as_micros() + ); + for (key, value) in &span.fields { + line.push_str(&format!(" {key}={value}")); + } + for (name, micros) in &span.phases { + line.push_str(&format!(" {name}_us={micros}")); + } + log::debug!(target: LOG_TARGET, "{line}"); + } +} + +/// Runs `f` against the innermost open span, if any. +fn with_current(f: F) { + let _ = SPANS.try_with(|spans| { + if let Ok(mut spans) = spans.try_borrow_mut() + && let Some(span) = spans.last_mut() + { + f(span) + } + }); +} + +/// Closes the phase that ended now, naming it `name`, and starts the next one. +/// +/// Span-local: use [`mark_agg`] for phases that should also be aggregated +/// process-wide. +pub fn mark(name: &'static str) { + with_current(|span| { + let now = Instant::now(); + let elapsed = now.duration_since(span.last); + span.last = now; + if span.detailed { + span.phases.push((name, elapsed.as_micros())); + } + }); +} + +/// [`mark`], and additionally add the phase to the global counters. +pub fn mark_agg(phase: Phase) { + let now = Instant::now(); + let mut elapsed = None; + with_current(|span| { + let delta = now.duration_since(span.last); + span.last = now; + elapsed = Some(delta); + if span.detailed { + span.phases.push((phase.as_str(), delta.as_micros())); + } + }); + // A phase recorded outside any span (e.g. a ledger read served over RPC) + // still counts towards the process totals; it just has no line to appear on. + record_phase(phase, elapsed.unwrap_or_default()); +} + +/// Adds `elapsed` to a phase's global counters without touching the current +/// span's cursor. For phases measured with their own timer. +pub fn record_phase(phase: Phase, elapsed: Duration) { + let idx = phase.index(); + PHASE_NANOS[idx].fetch_add(elapsed.as_nanos() as u64, Ordering::Relaxed); + PHASE_COUNTS[idx].fetch_add(1, Ordering::Relaxed); +} + +/// Attaches a `key=value` field to the current span's log line. +/// +/// Formatting is skipped when timing output is disabled, but the value itself is +/// still evaluated at the call site — use [`note_with`] when producing the value +/// costs something. +pub fn note(key: &'static str, value: impl Display) { + with_current(|span| { + if span.detailed { + span.fields.push((key, value.to_string())); + } + }); +} + +/// [`note`], with the value computed lazily — for fields whose formatting costs +/// something (hex-encoding a hash, say). +pub fn note_with(key: &'static str, value: F) +where + F: FnOnce() -> V, + V: Display, +{ + with_current(|span| { + if span.detailed { + span.fields.push((key, value().to_string())); + } + }); +} + +/// Marks the current span as successful. Call it just before returning `Ok`; +/// a span dropped without it reports `outcome=err`. +pub fn ok() { + with_current(|span| span.outcome = "ok"); +} + +#[cfg(test)] +mod tests { + use super::*; + use std::sync::Mutex; + + #[test] + fn span_accumulates_op_totals() { + let before = Totals::snapshot(); + { + let _span = span(Op::ValidateTx); + ok(); + } + let delta = Totals::snapshot().since(&before); + assert_eq!(delta.op(Op::ValidateTx).count, 1); + assert_eq!(delta.op(Op::ApplyTx).count, 0); + } + + #[test] + fn marks_aggregate_into_phase_totals() { + let before = Totals::snapshot(); + { + let _span = span(Op::ApplyTx); + mark("uninteresting"); + mark_agg(Phase::ProofVerification); + mark_agg(Phase::ProofVerification); + ok(); + } + let delta = Totals::snapshot().since(&before); + assert_eq!(delta.phase(Phase::ProofVerification).count, 2); + assert_eq!(delta.phase(Phase::LedgerApply).count, 0); + } + + #[test] + fn marks_outside_a_span_are_ignored_but_phases_still_count() { + let before = Totals::snapshot(); + mark("orphan"); + mark_agg(Phase::LoadState); + let delta = Totals::snapshot().since(&before); + assert_eq!(delta.phase(Phase::LoadState).count, 1); + assert_eq!(delta.phase(Phase::LoadState).nanos, 0); + } + + #[test] + fn nested_spans_pop_in_order() { + let before = Totals::snapshot(); + { + let _outer = span(Op::ValidateTx); + { + let _inner = span(Op::PreDispatch); + mark_agg(Phase::Deserialize); + } + mark_agg(Phase::LedgerApply); + ok(); + } + let delta = Totals::snapshot().since(&before); + assert_eq!(delta.op(Op::ValidateTx).count, 1); + assert_eq!(delta.op(Op::PreDispatch).count, 1); + assert_eq!(delta.phase(Phase::Deserialize).count, 1); + assert_eq!(delta.phase(Phase::LedgerApply).count, 1); + // The stack must be empty again, or later spans would leak into it. + SPANS.with(|spans| assert!(spans.borrow().is_empty())); + } + + /// Captures every record on our target so the emitted line can be asserted on. + /// Installed once for the whole test binary; concurrent tests are filtered out + /// by looking for the marker field each assertion adds. + struct CapturingLogger; + + static CAPTURED: Mutex> = Mutex::new(Vec::new()); + + impl log::Log for CapturingLogger { + fn enabled(&self, metadata: &log::Metadata) -> bool { + metadata.target() == LOG_TARGET + } + + fn log(&self, record: &log::Record) { + if self.enabled(record.metadata()) { + CAPTURED.lock().unwrap().push(record.args().to_string()); + } + } + + fn flush(&self) {} + } + + fn install_logger() { + static INIT: std::sync::Once = std::sync::Once::new(); + INIT.call_once(|| { + log::set_logger(&CapturingLogger).expect("no other logger in this test binary"); + log::set_max_level(log::LevelFilter::Debug); + }); + } + + /// Lines captured so far that carry `marker`. + fn captured_with(marker: &str) -> Vec { + CAPTURED + .lock() + .unwrap() + .iter() + .filter(|l| l.contains(marker)) + .cloned() + .collect() + } + + #[test] + fn emits_one_line_with_fields_and_phases() { + install_logger(); + { + let _span = span(Op::ApplyTx); + note("marker", "emits-one-line"); + note("size", 4096); + mark("deserialize_ish"); + mark_agg(Phase::ProofVerification); + ok(); + } + + let lines = captured_with("emits-one-line"); + assert_eq!(lines.len(), 1, "expected exactly one line, got {lines:?}"); + let line = &lines[0]; + assert!(line.starts_with("op=apply_tx outcome=ok total_us="), "got {line}"); + assert!(line.contains(" size=4096"), "got {line}"); + assert!(line.contains(" deserialize_ish_us="), "got {line}"); + assert!(line.contains(" proof_verify_us="), "got {line}"); + } + + #[test] + fn error_unwind_still_reports_progress() { + install_logger(); + + fn failing() -> Result<(), ()> { + let _span = span(Op::ValidateTx); + note("marker", "error-unwind"); + mark_agg(Phase::Deserialize); + Err(())?; + ok(); + Ok(()) + } + assert!(failing().is_err()); + + let lines = captured_with("error-unwind"); + assert_eq!(lines.len(), 1, "expected exactly one line, got {lines:?}"); + assert!(lines[0].contains("outcome=err"), "got {}", lines[0]); + // The phase completed before the failure must still be attributed. + assert!(lines[0].contains(" deserialize_us="), "got {}", lines[0]); + } + + #[test] + fn since_is_saturating() { + let later = Totals::snapshot(); + let mut earlier = later; + earlier.ops[Op::ApplyTx.index()].count += 5; + assert_eq!(later.since(&earlier).op(Op::ApplyTx).count, 0); + } +} From 87d0f2760701c0f11fb499341211ea49d8c19f24 Mon Sep 17 00:00:00 2001 From: chrispalaskas Date: Thu, 6 Aug 2026 20:30:31 -0400 Subject: [PATCH 2/3] chore: add PR link to change file Assisted-by: Claude:claude-opus-5 Signed-off-by: chrispalaskas --- changes/node/added/tx-processing-phase-timing.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changes/node/added/tx-processing-phase-timing.md b/changes/node/added/tx-processing-phase-timing.md index 0ce078b9c..5f6f690e9 100644 --- a/changes/node/added/tx-processing-phase-timing.md +++ b/changes/node/added/tx-processing-phase-timing.md @@ -32,4 +32,4 @@ relaxed atomic adds per transaction. See `docs/tx-processing-profiling.md` for the field reference, the authoring-node caveats, and aggregation one-liners. -PR: +PR: https://github.com/midnightntwrk/midnight-node/pull/2003 From 0d1584342eadc5aa1e237287e56617cb76824d09 Mon Sep 17 00:00:00 2001 From: chrispalaskas Date: Thu, 6 Aug 2026 21:00:55 -0400 Subject: [PATCH 3/3] docs: link tx-processing profiling guide from README Assisted-by: Claude:claude-opus-5 Signed-off-by: chrispalaskas --- README.md | 1 + 1 file changed, 1 insertion(+) diff --git a/README.md b/README.md index 38b76d303..eed923ed8 100644 --- a/README.md +++ b/README.md @@ -168,6 +168,7 @@ that we are still in the process of being release. As such: - [Rust Installation](docs/rust-setup.md) - Setup instructions and toolchain information - [Chain Specifications](docs/chain_specs.md) - Working with different networks - [Block Weights](docs/weights.md) - Runtime weights documentation +- [Profiling Transaction Processing](docs/tx-processing-profiling.md) - Phase-level timing logs for Midnight transactions and block import - [Actionlint Guide](docs/actionlint-guide.md) - GitHub Actions validation - [Governance](docs/governance/overview.md) - Federated Authority Governance System documentation - [Runtime Upgrade Guide](docs/governance/example/runtime-upgrade.md) - Step-by-step guide for runtime upgrades via governance