Skip to content

perf(logging): render log lines with less work per field#3396

Open
chet wants to merge 1 commit into
NVIDIA:mainfrom
chet:gh-issue-3219
Open

perf(logging): render log lines with less work per field#3396
chet wants to merge 1 commit into
NVIDIA:mainfrom
chet:gh-issue-3219

Conversation

@chet

@chet chet commented Jul 11, 2026

Copy link
Copy Markdown
Contributor

logfmt rendered every field of every log line into its own heap String, sorted the formatted strings, rewrote them into the output buffer, and double-formatted debug values -- and carbide-api installed the admin UI's live log-stream layer (BTreeMap, timestamp/target Strings, a mutex, a 128MiB ring buffer per line) even with the admin UI disabled.

Now each field renders once at record time:

  • Each field renders once at record time and the write phase just copies the rendered parts, with the sort reproducing the exact rendered-token ordering -- pinned by tests for the key-prefix, escaped-key, duplicate-key, and literal-=-in-key edges (the last also keeps the comparator total).
  • Quoting classifies ASCII with a byte-range match; a full Unicode-scalar sweep pins it to the old probe, which non-ASCII still uses.
  • The admin log-stream layer installs only when enable_admin_ui is set, and closing spans move their field map out instead of cloning it.

Output bytes are a contract: all seventeen pre-existing golden tests pass unchanged. Benched at about -14% time and -43% allocations per line, with the clean-ASCII quoting scan several times faster.

This supports #3219

@chet chet requested a review from a team as a code owner July 11, 2026 01:33
@coderabbitai

coderabbitai Bot commented Jul 11, 2026

Copy link
Copy Markdown
Contributor

Review Change Stack

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info
⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Enterprise

Run ID: 2066b8f4-0f57-45dd-ba8f-b11bf2bc64eb

📥 Commits

Reviewing files that changed from the base of the PR and between 568c589 and db6442a.

⛔ Files ignored due to path filters (1)
  • Cargo.lock is excluded by !**/*.lock
📒 Files selected for processing (6)
  • crates/api-core/src/logging/setup.rs
  • crates/api-core/src/logging/stream.rs
  • crates/api-core/src/run.rs
  • crates/logfmt/Cargo.toml
  • crates/logfmt/benches/logfmt_layer.rs
  • crates/logfmt/src/lib.rs

Summary by CodeRabbit

  • New Features

    • Admin UI log streaming can now be enabled or disabled through configuration.
    • Disabled log streaming avoids collecting and retaining live log data.
  • Improvements

    • Log output formatting and field ordering have been improved while preserving existing output behavior.
    • Completed span logs now handle retained data more efficiently.
  • Testing

    • Added coverage for admin UI logging behavior and log formatting, including quoting, ordering, and allocation benchmarks.

Walkthrough

Changes

The change gates admin UI log streaming by configuration, transfers span data on closure, and reworks logfmt field rendering and quoting classification with focused tests and Criterion benchmarks.

Admin-gated logging

Layer / File(s) Summary
Admin UI log-stream wiring
crates/api-core/src/logging/setup.rs, crates/api-core/src/run.rs
setup_logging accepts the admin UI flag, conditionally installs LogStreamLayer, and tests enabled versus disabled streaming and history behavior.
Span completion ownership
crates/api-core/src/logging/stream.rs
Span data is removed from extensions and used directly when emitting completion metadata.

Logfmt rendering and benchmarks

Layer / File(s) Summary
Rendered field emission
crates/logfmt/src/lib.rs
Fields use pre-rendered keys and values, rendered-token ordering, and direct emission during event formatting.
Quoting classification and validation
crates/logfmt/src/lib.rs
Quoting classification and value rendering are updated, with tests for Unicode, ordering, equality-containing keys, and grapheme-extended values.
Formatting benchmarks
crates/logfmt/Cargo.toml, crates/logfmt/benches/logfmt_layer.rs
Criterion benchmarks measure formatting, quoting scans, and allocations per emitted line.

Estimated code review effort: 4 (Complex) | ~45 minutes

Sequence Diagram(s)

sequenceDiagram
  participant CarbideConfig
  participant run
  participant setup_logging
  participant LogStreamLayer
  CarbideConfig->>run: provide enable_admin_ui
  run->>setup_logging: pass enable_admin_ui
  setup_logging->>LogStreamLayer: install when enabled
  LogStreamLayer-->>setup_logging: broadcast events and retain history
Loading
🚥 Pre-merge checks | ✅ 5
✅ Passed checks (5 passed)
Check name Status Explanation
Title check ✅ Passed The title is concise and accurately summarizes the main logging performance change.
Description check ✅ Passed The description is clearly related to the changeset and describes the logging and admin UI optimizations.
Docstring Coverage ✅ Passed Docstring coverage is 100.00% which is sufficient. The required threshold is 80.00%.
Linked Issues check ✅ Passed Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check ✅ Passed Check skipped because no linked issues were found for this pull request.
✨ Finishing Touches
🧪 Generate unit tests (beta)
  • Create PR with unit tests

Comment @coderabbitai help to get the list of available commands.

@chet

chet commented Jul 11, 2026

Copy link
Copy Markdown
Contributor Author

@coderabbitai full_review, thanks!

@coderabbitai

coderabbitai Bot commented Jul 11, 2026

Copy link
Copy Markdown
Contributor

@chet, sounds good — I'll redo the entire review of the PR from scratch.

(=^・ω・^=)

✅ Action performed

Full review finished.

@coderabbitai coderabbitai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🧹 Nitpick comments (3)
crates/logfmt/benches/logfmt_layer.rs (1)

97-108: 🚀 Performance & Scalability | 🔵 Trivial | 💤 Low value

Consider adding a "needs quoting" case to bench_quoting_scan.

Both benchmarked values are clean ASCII that never trip ASCII_NEEDS_QUOTING, so only the "no quoting needed" fast path (which must scan the full value) is measured. Since quoting classification presumably short-circuits on match, adding a value that requires quoting (e.g. one containing = or whitespace) would round out coverage of the perf claim ("clean-ASCII quoting scans ~5x faster") with the contrasting case.

🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/logfmt/benches/logfmt_layer.rs` around lines 97 - 108, The
bench_quoting_scan benchmark only measures clean values that do not require
quoting. Add a third benchmark input containing a quoting-triggering character
such as '=' or whitespace, and call value_needs_quoting through black_box with a
descriptive benchmark name to cover the short-circuit path alongside the
existing clean ASCII cases.
crates/logfmt/Cargo.toml (1)

33-36: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low value

Remove the unused local-time feature Keep env-filtercrates/logfmt/src/lib.rs uses tracing_subscriber::EnvFilter—but local-time is not exercised here, so trim it unless another path depends on it.

🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/logfmt/Cargo.toml` around lines 33 - 36, Remove the unused
"local-time" feature from the tracing-subscriber dependency in Cargo.toml,
retaining "env-filter" because it is used by tracing_subscriber::EnvFilter in
lib.rs.
crates/logfmt/src/lib.rs (1)

787-793: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low value

Consider consolidating the quote/escape decision to prevent silent divergence.

record_str reproduces the exact branch already expressed in render_value (Line 759). While the inlining is well-justified for avoiding an intermediate String, maintaining two independent copies of the quoting contract risks them drifting apart under future edits, producing inconsistent log rendering between &str and Debug/error paths. An #[inline] helper accepting &str would preserve the allocation-reuse behaviour while keeping a single source of truth.

♻️ Illustrative extraction
+/// Renders a value the way `Kvp` emits it, from a borrowed slice. `#[inline]`
+/// so `record_str` still renders straight into its quoted form.
+#[inline]
+fn render_value_str(value: &str) -> String {
+    if value_needs_quoting(value) {
+        format!("\"{}\"", value.escape_debug())
+    } else {
+        value.to_string()
+    }
+}
     fn record_str(&mut self, field: &Field, value: &str) {
-        let rendered = if value_needs_quoting(value) {
-            format!("\"{}\"", value.escape_debug())
-        } else {
-            value.to_string()
-        };
+        let rendered = render_value_str(value);
         self.fields.push(RenderedField::new(field, rendered));
     }
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@crates/logfmt/src/lib.rs` around lines 787 - 793, Consolidate the duplicated
string quoting and escaping logic used by record_str and render_value into a
shared #[inline] helper accepting &str. Preserve record_str’s allocation-reuse
behavior while making both paths use the same quoting contract and removing the
independent conditional branches.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Nitpick comments:
In `@crates/logfmt/benches/logfmt_layer.rs`:
- Around line 97-108: The bench_quoting_scan benchmark only measures clean
values that do not require quoting. Add a third benchmark input containing a
quoting-triggering character such as '=' or whitespace, and call
value_needs_quoting through black_box with a descriptive benchmark name to cover
the short-circuit path alongside the existing clean ASCII cases.

In `@crates/logfmt/Cargo.toml`:
- Around line 33-36: Remove the unused "local-time" feature from the
tracing-subscriber dependency in Cargo.toml, retaining "env-filter" because it
is used by tracing_subscriber::EnvFilter in lib.rs.

In `@crates/logfmt/src/lib.rs`:
- Around line 787-793: Consolidate the duplicated string quoting and escaping
logic used by record_str and render_value into a shared #[inline] helper
accepting &str. Preserve record_str’s allocation-reuse behavior while making
both paths use the same quoting contract and removing the independent
conditional branches.

ℹ️ Review info
⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Enterprise

Run ID: a2550059-0005-4503-b291-170f30e97608

📥 Commits

Reviewing files that changed from the base of the PR and between 83ea2c4 and 3ee8d39.

⛔ Files ignored due to path filters (1)
  • Cargo.lock is excluded by !**/*.lock
📒 Files selected for processing (6)
  • crates/api-core/src/logging/setup.rs
  • crates/api-core/src/logging/stream.rs
  • crates/api-core/src/run.rs
  • crates/logfmt/Cargo.toml
  • crates/logfmt/benches/logfmt_layer.rs
  • crates/logfmt/src/lib.rs

@coderabbitai coderabbitai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 1

🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Inline comments:
In `@crates/logfmt/src/lib.rs`:
- Around line 653-665: Add a CI workflow job for the crates/logfmt benchmark
target that runs with the bench-hooks feature enabled, ensuring the
feature-gated bench_hooks module is compiled and exercised. Configure the job to
invoke the appropriate cargo benchmark command for crates/logfmt with --features
bench-hooks, matching existing CI conventions.
🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

  • Push a commit to this branch (recommended)
  • Create a new PR with the fixes

ℹ️ Review info
⚙️ Run configuration

Configuration used: Path: .coderabbit.yaml

Review profile: CHILL

Plan: Enterprise

Run ID: 9877d454-285b-4cc7-9d17-e2a979823434

📥 Commits

Reviewing files that changed from the base of the PR and between 83ea2c4 and 3ee8d39.

⛔ Files ignored due to path filters (1)
  • Cargo.lock is excluded by !**/*.lock
📒 Files selected for processing (6)
  • crates/api-core/src/logging/setup.rs
  • crates/api-core/src/logging/stream.rs
  • crates/api-core/src/run.rs
  • crates/logfmt/Cargo.toml
  • crates/logfmt/benches/logfmt_layer.rs
  • crates/logfmt/src/lib.rs

Comment thread crates/logfmt/src/lib.rs
@github-actions

Copy link
Copy Markdown

🔍 Container Scan Summary

Service Total Critical High Medium Low Other
boot-artifacts-aarch64 3 0 0 3 0 0
boot-artifacts-x86_64 3 0 0 3 0 0
forge-admin-cli-x86_64 271 13 34 91 7 126
machine-validation-runner 804 40 237 296 36 195
machine_validation 804 40 237 296 36 195
machine_validation-aarch64 804 40 237 296 36 195
nvmetal-carbide 804 40 237 296 36 195
TOTAL 3493 173 982 1281 151 906

Per-CVE detail lives in the per-service grype-* artifacts (JSON + SARIF). Severity counts only — no CVE IDs published here.

@chet

chet commented Jul 11, 2026

Copy link
Copy Markdown
Contributor Author

@coderabbitai full_review, thanks!

@coderabbitai

coderabbitai Bot commented Jul 11, 2026

Copy link
Copy Markdown
Contributor

@chet, got it — kicking off a full review of the PR from scratch again.

(=^・ω・^=)

✅ Action performed

Full review finished.

logfmt rendered every field of every line into its own heap String, sorted the formatted strings, then rewrote them into the output buffer, and debug values were formatted twice. The quoting decision built a `char::escape_debug` iterator for every character of every value. On top of that, carbide-api installed the admin UI's live log-stream layer unconditionally, so every INFO line was visited twice -- a BTreeMap, a timestamp and target String, a mutex, and a 128MiB ring buffer -- even with the admin UI disabled.

Field values now render once at record time and the write phase just copies each rendered key and value into the reused buffer; the sort reproduces the exact rendered-token ordering, pinned by tests for the key-prefix, escaped-key, and duplicate-key edges. Quoting classifies ASCII with a byte-range match, keeping the original probe for non-ASCII. The log-stream layer installs only when the admin UI is enabled, and closing spans move their field map out instead of cloning it.

- One render per field; copy-only write phase; rendered-token-order sort.
- ASCII byte-match quoting classifier; non-ASCII decisions unchanged.
- Admin log-stream layer gated on `enable_admin_ui`.

Output bytes are a contract: all seventeen golden tests pass unchanged, and a sweep of every Unicode scalar pins the new classifier to the old one. Benched at about -14% time and -43% allocations per line, with the clean-ASCII quoting scan several times faster.

This supports NVIDIA#3219

Signed-off-by: Chet Nichols III <chetn@nvidia.com>
@chet

chet commented Jul 11, 2026

Copy link
Copy Markdown
Contributor Author

@coderabbitai full_review, thanks!

@coderabbitai

coderabbitai Bot commented Jul 11, 2026

Copy link
Copy Markdown
Contributor

@chet, got it — kicking off another full review of the PR from scratch.

(=^・ω・^=)

✅ Action performed

Full review finished.

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.

1 participant