apollo_committer: restore lazy log formatting for per-block commit stats - #14900
apollo_committer: restore lazy log formatting for per-block commit stats#14900gkaempfer wants to merge 2 commits into
Conversation
update_metrics/log_block_measurements runs once per committed block, on the critical finalization path. Pre-building the stats message into a String via format!() before invoking warn!()/debug!() unconditionally formats it regardless of whether that log level is enabled, defeating tracing's callsite-interest check that normally skips evaluating log arguments when the level is filtered out. Move the formatting back into the warn!/debug! macro invocations directly so it is skipped entirely when neither level is enabled.
Replaces the duplicated warn!/debug! format strings with a single format_block_stats closure invoked from inside each macro's args, keeping the formatting lazy (skipped when the level is disabled) without hand-maintaining two copies of the message. This also makes the witness_log formatting (os_input feature) lazy for the same reason. Also asserts the debug branch actually emits a log line in no_warn_when_block_commit_within_duration_threshold, not just the absence of the warn suffix.
PR SummaryLow Risk Overview The stats string is built inside a The within-threshold test now also asserts the debug stats line ( Reviewed by Cursor Bugbot for commit 74f7dc6. Bugbot is set up for automated code reviews on this repo. Configure here. |
Summary
Follow-up performance fix for #14888, which added a
commit_duration_warn_threshold_millis-based WARN log tolog_block_measurements(crates/apollo_committer/src/committer.rs). That change pre-built the block-stats message via a barelet stats = format!(...)before passing it intowarn!(...)/debug!(...).log_block_measurementsruns once per committed block, on the committer's block-finalization path (a slow committer stalls consensus, per the existing comment).tracing'sdebug!/warn!macros are designed to be zero-cost when a level is disabled: the callsite's "interest" is checked before any of the macro's format arguments are evaluated, so formatting work is skipped entirely when that level isn't active. Building the message with a standaloneformat!()outside of the macro call defeats that — it unconditionally does the string formatting (5+ nestedformat!calls for optional fields) on every single block, even when the subscriber is at INFO level and neither branch will actually emit a line.Fix
format_block_statsclosure invoked from inside thewarn!/debug!macro args, restoring the callsite-interest laziness (only one of the two branches runs per call, and its formatting only happens if that level is enabled).witness_logformatting (under theos_inputfeature) lazy for the same reason.no_warn_when_block_commit_within_duration_thresholdto also assert the debug branch actually emits a log line (previously it only asserted the absence of the warn suffix).Test plan
cargo build -p apollo_committerSEED=0 cargo test -p apollo_committer— 12/12 passed, including both duration-threshold testscargo clippy -p apollo_committer --all-targets— cleanscripts/rust_fmt.sh— no diffGenerated by Claude Code