Skip to content

apollo_committer: restore lazy log formatting for per-block commit stats - #14900

Open
gkaempfer wants to merge 2 commits into
mainfrom
claude/perf/apollo-committer-lazy-log-71042
Open

apollo_committer: restore lazy log formatting for per-block commit stats#14900
gkaempfer wants to merge 2 commits into
mainfrom
claude/perf/apollo-committer-lazy-log-71042

Conversation

@gkaempfer

Copy link
Copy Markdown
Contributor

Summary

Follow-up performance fix for #14888, which added a commit_duration_warn_threshold_millis-based WARN log to log_block_measurements (crates/apollo_committer/src/committer.rs). That change pre-built the block-stats message via a bare let stats = format!(...) before passing it into warn!(...)/debug!(...).

log_block_measurements runs once per committed block, on the committer's block-finalization path (a slow committer stalls consensus, per the existing comment). tracing's debug!/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 standalone format!() outside of the macro call defeats that — it unconditionally does the string formatting (5+ nested format! 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

  • Moved the message formatting into a format_block_stats closure invoked from inside the warn!/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).
  • This also happens to make the pre-existing witness_log formatting (under the os_input feature) lazy for the same reason.
  • Net removal of duplicate code vs. formatting the message twice (once per branch).
  • Strengthened no_warn_when_block_commit_within_duration_threshold to 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_committer
  • SEED=0 cargo test -p apollo_committer — 12/12 passed, including both duration-threshold tests
  • cargo clippy -p apollo_committer --all-targets — clean
  • scripts/rust_fmt.sh — no diff
  • Reviewed by an independent Opus pass, which verified the duplicated-then-deduped log message is byte-identical to the original and found no blocking issues

Generated by Claude Code

claude added 2 commits July 30, 2026 15:47
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.
@cursor

cursor Bot commented Jul 30, 2026

Copy link
Copy Markdown

PR Summary

Low Risk
Logging-only performance fix with identical message content; no commit or consensus logic changes.

Overview
Restores lazy formatting for per-block commit stats in log_block_measurements, which runs on every committed block.

The stats string is built inside a format_block_stats closure passed into warn! / debug! instead of a standalone format! before the macro, so tracing can skip work when that level is disabled (e.g. INFO with no debug/warn emission). The same pattern makes os_input witness stats lazy again. Log text is unchanged; the slow-commit branch inlines the warn threshold millis in the macro args.

The within-threshold test now also asserts the debug stats line (Block 0 stats) is present, not only that the warn suffix is absent.

Reviewed by Cursor Bugbot for commit 74f7dc6. Bugbot is set up for automated code reviews on this repo. Configure here.

@reviewable-StarkWare

Copy link
Copy Markdown

This change is Reviewable

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.

4 participants