Repository navigation
prof: replace minstant with raw-tick clock; convert ticks→ns in the consumer - #3759
Merged
Merged
Conversation
…consumer minstant-0.1.7 registers a #[ctor] that busy-spins >=20ms calibrating the TSC before main() in EVERY process linking bex_events — packed binaries, baml-cli, the LSP, and each nextest test process — even with BAML_PROFILE=0 (empty packed binary: 31.3ms -> 15.2ms median after this change; with BAML_PROFILE=0 the startup delta vs pre-tracing is now +1.1ms, was +20.5ms). Producers now stamp records with clock::now_ticks() — raw rdtsc on x86_64 (gated on CPUID invariant-TSC), CNTVCT_EL0 on aarch64 (exact rate from mach_timebase_info on macOS / CNTFRQ_EL0 elsewhere), std::time::Instant fallback otherwise. No conversion, no calibration, no ctor on any producer path; the anchor is forced inside now_ticks() so every stamped tick postdates the process base regardless of init order. The consumer owns tick->ns conversion (TickConverter): exact rational rates where the platform states them; for the x86 TSC a ~2ms two-point estimate at consumer start, refined once across a >=1s window at heartbeat cadence with piecewise-linear anchor continuity (per-thread timestamp_ns stays monotone across the rate swap; pre-switch ticks keep converting through the previous segment). Disk format stays nanoseconds — wall(event) = started_at_epoch_ns + timestamp_ns is unchanged and prof_gate needed no source changes. The header gains informational clock_kind / tick rational / clock_quality fields (proto3-additive). Measured (Linux x86, 32-core dev box): - now_ticks 8.33 ns/read (minstant was 8.45); consumer-side to_ns ~free. - Tracing on-vs-off on pure-call-1m: ~24 ns/call-pair, down from ~42 (two tick->ns conversions left the VM hot path). - ARM reads go from OS-clock fallback to a raw counter read; rates are exact with zero calibration. Gates: bex_events 51 tests; prof_gate 17/17; loom (--cfg baml_loom) 34; miri 33; clippy --all-targets clean; wasm32 check clean; .init_array back to 53 entries; cargo tree shows minstant and [email protected] fully pruned.
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
Contributor
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Repository UI Review profile: CHILL Plan: Pro Run ID: 📒 Files selected for processing (2)
🚧 Files skipped from review as they are similar to previous changes (2)
📝 WalkthroughWalkthroughProducer-side timestamps changed from nanoseconds to raw hardware ticks (now_ticks); a TickConverter converts ticks→ns in the consumer. RawRecord variants, consumer transcoding, file headers/protobuf, engine/VM emission sites, tests, benches, and workspace dependency were updated accordingly. ChangesProfiling Clock Architecture Refactoring
Sequence DiagramsequenceDiagram
participant Engine as BEX Engine
participant Clock as prof::clock
participant Ring as Ring Buffer
participant Consumer as prof Consumer
participant Conv as TickConverter
Engine->>Clock: init() once
Clock->>Clock: detect_source (CPUID/EL0/fallback), record base_ticks & epoch
Engine->>Clock: now_ticks() per event
Engine->>Ring: emit RawRecord(ts_ticks)
Consumer->>Clock: ClockMode::Detect → TickConverter::from_clock()
Consumer->>Ring: read RawRecord(ts_ticks)
Consumer->>Conv: to_ns(ts_ticks)
Conv->>Conv: maybe_refine()
Conv-->>Consumer: timestamp_ns
Consumer->>Consumer: write protobuf Event + header metadata
Estimated code review effort🎯 4 (Complex) | ⏱️ ~60 minutes Possibly related PRs
Poem
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
⏭️ Performance benchmarks were skippedPerf benchmarks (CodSpeed) are opt-in on pull requests — they no longer run on every push. They always run automatically after merge to To run them on this PR, do any of the following, then push a commit (or re-run CI):
|
|
No description provided. |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
Actionable comments posted: 2
🤖 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 `@baml_language/crates/bex_events/benches/prof_clock.rs`:
- Around line 3-6: The TickConverter::to_ns benchmark currently calls
now_ticks() inside the timed closure, so it measures the producer tick read plus
conversion; to fix, either hoist a tick sample out of the timed closure (call
let t = now_ticks() before the bench iteration and pass t into
TickConverter::to_ns inside the closure) to measure only the consumer tick→ns
cost, or explicitly relabel the benchmark row to indicate it is an end-to-end
measurement; locate uses of TickConverter::to_ns and now_ticks() in
prof_clock.rs and apply one of these changes consistently for the converter
benchmark (also update the similar cases around lines 35–39).
In `@baml_language/crates/bex_events/src/prof/clock.rs`:
- Around line 110-143: The detect() logic currently treats CPUID invariant-TSC
(has_invariant_tsc()) as sufficient to choose Source::Tsc, but that doesn't
guarantee cross-core synchronized rdtsc; change detect() to perform a runtime
cross-core monotonicity/synchronization probe before returning Source::Tsc: if
has_invariant_tsc() is true then run a short OS-backed multi-core probe (e.g.,
schedule/affine two threads on different logical CPUs and compare rdtsc reads or
validate monotonic increments across cores) and only return (Source::Tsc, None)
when that probe confirms cross-core ordering; otherwise return (Source::Instant,
Some((1,1))). Update has_invariant_tsc() to remain as a quick CPUID check but do
not by itself drive the Source choice—use it only as a prerequisite for running
the runtime probe. Ensure the probe code is referenced/triggered from detect()
and documented so now_ticks()/Source consumers rely on safe fallback to Instant
when synchronization cannot be verified.
🪄 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: Repository UI
Review profile: CHILL
Plan: Pro
Run ID: 3dc6557a-1221-4b3f-8d38-5e75198ff8cf
⛔ Files ignored due to path filters (1)
baml_language/Cargo.lockis excluded by!**/*.lock
📒 Files selected for processing (14)
baml_language/Cargo.tomlbaml_language/crates/bex_engine/src/lib.rsbaml_language/crates/bex_events/Cargo.tomlbaml_language/crates/bex_events/benches/prof_clock.rsbaml_language/crates/bex_events/src/prof/clock.rsbaml_language/crates/bex_events/src/prof/concurrency_tests.rsbaml_language/crates/bex_events/src/prof/config.rsbaml_language/crates/bex_events/src/prof/consumer.rsbaml_language/crates/bex_events/src/prof/file.rsbaml_language/crates/bex_events/src/prof/mod.rsbaml_language/crates/bex_events/src/prof/proto/bamlprof.protobaml_language/crates/bex_events/src/prof/record.rsbaml_language/crates/bex_events/src/prof/registry.rsbaml_language/crates/bex_vm/src/vm.rs
💤 Files with no reviewable changes (1)
- baml_language/Cargo.toml
We stamp ticks with CNTVCT_EL0 but converted using mach_timebase_info's rational, which describes mach_absolute_time. On M1-M3 both counters run at 24 MHz so they coincided; on M4/M5 CNTVCT_EL0 runs at 1 GHz while mach_absolute_time stays at 24 MHz, so applying the mach rational (125/3) to raw CNTVCT_EL0 reads inflated every timestamp ~41.7x. Read CNTFRQ_EL0 (the architectural rate of CNTVCT_EL0) on every aarch64 OS, macOS included. Correct on both M1-M3 (24 MHz) and M4/M5 (1 GHz); converter_rate_sane now passes on Apple Silicon M5.
The CPUID invariant-TSC bit guarantees constant-rate/never-stop, not cross-core synchronization. On Linux, additionally require the kernel's clocksource verdict (it measures cross-CPU TSC sync at boot) — the same check minstant relied on. Relabel the prof_clock converter row as the end-to-end read+convert measurement it is.
This branch was previously deployed
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
minstant-0.1.7registers a#[ctor]static initializer that busy-spins ≥20 ms calibrating the TSC beforemain()in every process that linksbex_events— packed binaries,baml-cli, the LSP, and every nextest test process — even withBAML_PROFILE=0. Its calibration loop (_cycles_per_sec) requires ≥10 ms per sample window and ≥2 converging windows by construction.Measured impact: an empty packed program (
function main() -> int { return 0; }) ran 10.8 ms pre-tracing → 31.3 ms on canary. This constant per-process tax was the dominant end-to-end regression from the tracing merge (#3740) — it inflated every short-running benchmark by +50–145% and is a large chunk of the test-suite wall-time increase.Secondary problems: minstant only uses the TSC on Linux x86 (Macs silently fall back to the OS clock), and the producer hot path paid a tick→ns conversion on every clock read.
Fix
clock::now_ticks()):rdtscon x86_64 (gated on a CPUID invariant-TSC probe),mrs CNTVCT_EL0on aarch64, monotonic-Instantfallback otherwise. No conversion, no calibration, no ctor on any producer path. The anchor is forced insidenow_ticks(), so every stamped tick postdates the process base regardless of init order.TickConverter, built on the consumer thread): exact rational rates where the platform states them (mach_timebase_infoon macOS — Apple Silicon's 125/3 handled exactly;CNTFRQ_EL0on Linux ARM); for the x86 TSC, a ~2 ms two-point estimate at consumer start, refined once across a ≥1 s window at heartbeat cadence with piecewise-linear anchor continuity (per-threadtimestamp_nsstays monotone across the rate swap; late-draining ring events convert through the previous segment)..bamlproftimestamps remain nanoseconds;wall(event) = started_at_epoch_ns + timestamp_nsholds;prof_gateneeded zero source changes. The header gains informationalclock_kind/ tick-rate rational /clock_qualityfields (proto3-additive).minstant(and the[email protected]it pulled in) removed from the workspace.Measured (Linux x86, 32-core dev box)
BAML_PROFILE=0, vs pre-tracing baselinenow_ticksread (prof_clock bench)The per-pair improvement comes from the two tick→ns conversions leaving the VM hot path. End-to-end (speedtest corpus, packed binaries): small/loop-heavy workloads return to ≈pre-tracing (+3–11%); remaining overhead concentrates proportionally to traced call volume.
Verification
cargo test -p bex_events(51),cargo test -p bex_engine --test prof_gate(17/17)rustup run 1.93.0 cargo test -p bex_events -p bex_vm -p bex_engine --all-features— all green--cfg baml_loom, 34) and miri (33) prof suites--all-targetsclean; wasm32cargo checkclean.init_arrayback to 53 entries (the ctor is gone);cargo tree -i minstant/-i [email protected]→ no matchesNotes for reviewers
converter_rate_sanefails loudly on a wrong rational). Known monitor-don't-block risk: 24 MHz CNTVCT granularity on M1–M3 slightly raises timestamp-tie probability in prof_gate's large streams; ties are stable-sort-safe.CLOCK_QUALITY_COARSEin the header.Summary by CodeRabbit
Refactor
Chores