feat(probes): time_probe! macro — safe one-line async timing by joelteply · Pull Request #1540 · CambrianTech/continuum

joelteply · 2026-06-06T19:53:29Z

Summary

time_probe! macro for one-line async timing — substrate refinement caught during cognition work per [[refine-tools-as-you-use-them]]. Companion to time_sync!; both emit to the substrate's timing probe class.

Revised after the reviewer mandate flagged real issues. Three adversarial reviewers per [[reviewer-mandate-elegance-and-substrate-viability]] all BLOCKED with substantive findings. The mandate worked — it surfaced both in-scope macro fixes AND deeper substrate gaps the substrate has been carrying silently.

What's in this PR (after revision)

time_probe!("seam.path", future) — collapses three-line .instrument(info_span!(...)).await ceremony to one line. Same timing probe class as time_sync!.
Field is seam (not name) so it doesn't collide with other probes' use of name.
Fully-qualified ::tracing::Instrument::instrument(future, span).await expansion — no hidden use import inside macro body.
Honest cost docstring: ~24 bytes per call site, one extra branch per poll, Span allocates regardless of subscriber state. Acceptable for cognition seams (Qwen dominates wall-clock by 4-5 orders of magnitude); benchmark per task Integrate Refined detectQueryIntent with Optimized Thresholds #198 before sprinkling into a hot loop.
Manual updated to show time_probe! alongside time_sync! in the "How to add a probe" example block, with explicit persistence caveat (see follow-up file/save command has parameter parsing bug preventing recipe creation #196).

Tests (3 passing)

time_probe_returns_inner_future_value — value transparency
time_probe_propagates_error_from_inner_future (NEW) — Result futures don't get errors swallowed per [[no-fallbacks-ever]]
time_probe_nested_compose_and_return_inner_value — nested spans compose

Reviewer findings — what's in vs follow-up

Finding	Status
Field `name` collision risk	Fixed — renamed to `seam`
Hidden `use ... as _` inside macro	Fixed — fully-qualified call
Docstring overclaim "zero cost"	Fixed — honest cost section
No error-path test	Fixed — new test
Manual example missing `time_probe!`	Fixed
`ProbeRouterLayer` / `JsonlProbeFileSink` only do `on_event` — span-close events from `time_sync!` + `time_probe!` aren't actually persisted to JSONL today	Tracked as task #196. The macro docstring + manual carry the caveat.
Flat `timing` class vs hierarchical taxonomy (`CONTINUUM_PROBE_CLASSES=cognition` won't catch cognition timings)	Tracked as task #197
Per-event HashMap allocation under multi-persona load	Tracked as task #198 — audit + bench before broad sprinkle

Why revise rather than withdraw

The call-site shape (time_probe!("seam", future)) is stable. The routing-side gap (#196) is its own slice worth doing right. Shipping the macro now means: when #196 lands, every existing time_sync! AND time_probe! call site starts emitting JSONL with zero further code changes. The docstring + manual carry the caveat so no one mistakes the macro for an end-to-end shipping observability primitive — yet.

How the reviewer mandate worked

Per [[reviewer-mandate-elegance-and-substrate-viability]], three adversarial reviewers were spawned with explicit prompts naming the seven lens dimensions (architecture / design / traits / modularity / speed / Intel-Mac viability / probe coverage). All three found different real issues that pure correctness review would have missed:

Architecture reviewer caught the hidden use import + naming subtleties + the missing integration verification
Speed-viability reviewer caught the docstring overclaim + the Layer's HashMap allocation pressure (now tracked)
Probe-coverage reviewer caught the field collision + the class taxonomy violation + the missing adoption story (now tracked)

The mandate is now in [[reviewer-mandate-elegance-and-substrate-viability]] so future PRs get the same depth of review by default.

Doctrine

[[refine-tools-as-you-use-them]] — substrate refinement caught while doing cognition work; ship both ends
[[reviewer-mandate-elegance-and-substrate-viability]] — adversarial reviewers find depth that pure correctness review misses
[[no-fallbacks-ever]] — error-path test pinned; no silent swallowing
[[jtag-probes-are-rtos-debugger]] — "easy one-liners or it won't happen"; this is the async one-liner

cards: substrate refinement under [[refine-tools-as-you-use-them]]
companion PRs: #1538 (boot wiring + typed-config) + #1539 (silence affordance + identity grounding)
follow-up tasks: #196 (span-close persistence) + #197 (class taxonomy) + #198 (allocation audit)

…ition seams Per Joel 2026-06-06 `[[refine-tools-as-you-use-them]]`: I hit this friction in the silence-affordance + identity-grounding work and sat on it. Every async timing site in the cognition path was an `.instrument(info_span!("time", name=..., probe_class="timing")).await` ceremony — three lines plus a `use tracing::Instrument` import, nobody writes those when adding a new seam in a hurry. The result: async cognition stages stayed untimed even though `time_sync!` makes sync-block timing one line. `time_probe!` collapses async timing to the same one-line shape: ```rust // Before — every async timing site: use tracing::Instrument; let span = tracing::info_span!("time", name = "analyze", probe_class = "timing"); let analysis = analyze(input).instrument(span).await; // After: let analysis = time_probe!("analyze", analyze(input)); ``` ## Why this didn't ship in PR #1529 The existing comment block in `routing/macros.rs` documents why an `async`-timing macro was deliberately deferred: 1. Naming collision with `crate::logging::time_async!` (RAII TimingGuard shape — different observability path). 2. The previous `time!` macro was a foot-gun: it expanded to `let _enter = span.enter(); $body` where `$body` contained `.await`, holding `_enter` across the await suspension and breaking `URI_STACK` per the d1cf19d dispatch fix. This commit addresses both: - **Naming**: `time_probe!` (not `time_async!`) — the suffix names the OUTPUT (a timing probe), not the executor shape. Keeps the `crate::logging::time_async!` namespace untouched; the two macros stay disjoint. - **Safety by construction**: the macro expands to `$future.instrument(span).await`. The future itself enters / exits the span via `Future::poll` boundaries — no scope guard ever held across an await. Same shape `CommandExecutor::dispatch` uses. The comment block in macros.rs is replaced with the new macro's docstring, which preserves the safety reasoning + names the prior foot-gun for future-developer context. ## Tests (+2) `routing::macros::tests`: - `time_probe_returns_inner_future_value` — pin that the macro is VALUE-TRANSPARENT. `time_probe!("seam", expr)` and `expr.await` must produce the same value at the call site, so adding the probe is a pure observability addition with no shape change. Uses a `current_thread` tokio runtime so the test stays executor-light. - `time_probe_nested_compose_and_return_inner_value` — pin that multiple `time_probe!` calls compose. The inner span becomes a child of the outer span (same as `time_sync!` nesting); the value flows through both layers unchanged. The existing `time_sync!` tests stay unchanged — sync timing is unaffected by this addition. ## Manual updated `docs/architecture/RTOS-DEBUGGER-PROBES.md` — the macro table at the top now lists `time_probe!` alongside `probe!` / `time_sync!` / `time_async!` / `stack!` with a brief "prefer this over bare `.instrument(...)` ceremony" note + a contrast with the RAII-shape `time_async!` from `crate::logging`. Operators filter sync + async timings together via `CONTINUUM_PROBE_CLASSES=timing` and see one flat timeline. ## Why this lands here (not a separate PR) Per Joel's `[[refine-tools-as-you-use-them]]`: refine the substrate AS I use it, not after. I'm shipping cognition fixes that need timing seams across async boundaries (#149 prefill caching, #112-114 inference-handle bypass, future analyze optimizations). Without `time_probe!` the next time I'd sprinkle async timing I'd skip it because the ceremony is prohibitive. Better: refine the substrate, ship the cognition work + the substrate refinement that makes it sustainable. Parent task: substrate refinement under `[[refine-tools-as-you-use-them]]` Companion PRs in flight: #1538 (boot wiring) + #1539 (silence + identity) Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>

Three adversarial reviewers spawned per the new reviewer-mandate doctrine (`[[reviewer-mandate-elegance-and-substrate-viability]]`) BLOCKED with substantive findings. This commit addresses the in-scope ones; the deeper substrate gaps are tracked as follow-ups. ## In-scope fixes (this commit) 1. **Field rename `name` → `seam`.** Reviewer 3 flagged collision risk — other probes use `name` for different semantics. `seam` is unambiguous and tells operators to write `jq 'select(.fields.seam == "cognition.analyze")'`. 2. **Hidden `use ::tracing::Instrument as _;` removed.** Reviewer 1 flagged the scoped import inside macro body as unconventional and cognitively load-bearing. Replaced with fully-qualified `::tracing::Instrument::instrument(future, span).await` call — no hidden import, contract visible at the call site. 3. **Docstring honesty.** Reviewer 2 flagged the prior "zero cost when disabled" claim as overclaim — `Instrumented<F>` wrapper persists at runtime even with `release_max_level_*` features. New cost section: ~24 bytes per call site, one branch per poll, allocates `Span` regardless of subscriber state. Acceptable for cognition seams (Qwen dominates wall-clock); bench per task #198 before sprinkling into hot loops. 4. **Error-path test.** Reviewer 3 flagged missing Result-future coverage. New `time_probe_propagates_error_from_inner_future` pins that `Err` flows through unchanged per `[[no-fallbacks-ever]]`. 5. **Manual example block.** Reviewer 3 flagged the "How to add a probe" section showing only `time_async!` (the RAII shape) but not `time_probe!`. Now shows both with explicit guidance: substrate seams use `time_probe!`; legacy logging-crate seams use `time_async!`. Includes the persistence caveat (see #196). ## Follow-up substrate gaps (separate tasks) - **#196**: `ProbeRouterLayer` + `JsonlProbeFileSink` only implement `on_event`, not `on_close`. `time_sync!` AND `time_probe!` emit SPANS, not events — neither timing macro actually persists timings to the JSONL log today. The call shape ships here; the routing side ships in #196. The macro docstring + manual carry the caveat explicitly. - **#197**: Probe class taxonomy decision — flat `timing` vs hierarchical. Operators filtering `cognition` won't catch cognition timings under the flat scheme; substrate convention needs to be picked. - **#198**: Probe Layer allocation hot-path audit — reviewer 2 estimated ~50-100 HashMap allocs/sec per persona; benchmark before sprinkling into every async seam. ## Why this lands as a revision rather than withdrawal Per `[[refine-tools-as-you-use-them]]`: ship the call-site shape that becomes stable. The routing-side gap (#196) is its own slice worth doing right rather than rushing into this PR. The docstring + manual carry the caveat so no one mistakes the macro for an end-to-end shipping observability primitive — yet. ## Tests 3 passing: - `time_probe_returns_inner_future_value` - `time_probe_propagates_error_from_inner_future` (new — pins Result futures don't swallow errors) - `time_probe_nested_compose_and_return_inner_value` ## Doctrine - `[[reviewer-mandate-elegance-and-substrate-viability]]` — three adversarial lenses (architecture / speed-viability / probe- coverage) all surfaced real findings. The mandate works. - `[[refine-tools-as-you-use-them]]` — revising a primitive in response to reviewer feedback IS the application work informing the substrate. - `[[no-fallbacks-ever]]` — error-path test pinned; substrate refuses silent swallowing at any seam. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com>

…ow persist (#196) (#1541) * feat(probes): time_probe! macro — safe one-line async timing for cognition seams Per Joel 2026-06-06 `[[refine-tools-as-you-use-them]]`: I hit this friction in the silence-affordance + identity-grounding work and sat on it. Every async timing site in the cognition path was an `.instrument(info_span!("time", name=..., probe_class="timing")).await` ceremony — three lines plus a `use tracing::Instrument` import, nobody writes those when adding a new seam in a hurry. The result: async cognition stages stayed untimed even though `time_sync!` makes sync-block timing one line. `time_probe!` collapses async timing to the same one-line shape: ```rust // Before — every async timing site: use tracing::Instrument; let span = tracing::info_span!("time", name = "analyze", probe_class = "timing"); let analysis = analyze(input).instrument(span).await; // After: let analysis = time_probe!("analyze", analyze(input)); ``` ## Why this didn't ship in PR #1529 The existing comment block in `routing/macros.rs` documents why an `async`-timing macro was deliberately deferred: 1. Naming collision with `crate::logging::time_async!` (RAII TimingGuard shape — different observability path). 2. The previous `time!` macro was a foot-gun: it expanded to `let _enter = span.enter(); $body` where `$body` contained `.await`, holding `_enter` across the await suspension and breaking `URI_STACK` per the d1cf19d dispatch fix. This commit addresses both: - **Naming**: `time_probe!` (not `time_async!`) — the suffix names the OUTPUT (a timing probe), not the executor shape. Keeps the `crate::logging::time_async!` namespace untouched; the two macros stay disjoint. - **Safety by construction**: the macro expands to `$future.instrument(span).await`. The future itself enters / exits the span via `Future::poll` boundaries — no scope guard ever held across an await. Same shape `CommandExecutor::dispatch` uses. The comment block in macros.rs is replaced with the new macro's docstring, which preserves the safety reasoning + names the prior foot-gun for future-developer context. ## Tests (+2) `routing::macros::tests`: - `time_probe_returns_inner_future_value` — pin that the macro is VALUE-TRANSPARENT. `time_probe!("seam", expr)` and `expr.await` must produce the same value at the call site, so adding the probe is a pure observability addition with no shape change. Uses a `current_thread` tokio runtime so the test stays executor-light. - `time_probe_nested_compose_and_return_inner_value` — pin that multiple `time_probe!` calls compose. The inner span becomes a child of the outer span (same as `time_sync!` nesting); the value flows through both layers unchanged. The existing `time_sync!` tests stay unchanged — sync timing is unaffected by this addition. ## Manual updated `docs/architecture/RTOS-DEBUGGER-PROBES.md` — the macro table at the top now lists `time_probe!` alongside `probe!` / `time_sync!` / `time_async!` / `stack!` with a brief "prefer this over bare `.instrument(...)` ceremony" note + a contrast with the RAII-shape `time_async!` from `crate::logging`. Operators filter sync + async timings together via `CONTINUUM_PROBE_CLASSES=timing` and see one flat timeline. ## Why this lands here (not a separate PR) Per Joel's `[[refine-tools-as-you-use-them]]`: refine the substrate AS I use it, not after. I'm shipping cognition fixes that need timing seams across async boundaries (#149 prefill caching, #112-114 inference-handle bypass, future analyze optimizations). Without `time_probe!` the next time I'd sprinkle async timing I'd skip it because the ceremony is prohibitive. Better: refine the substrate, ship the cognition work + the substrate refinement that makes it sustainable. Parent task: substrate refinement under `[[refine-tools-as-you-use-them]]` Companion PRs in flight: #1538 (boot wiring) + #1539 (silence + identity) Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com> * refactor(probes): time_probe! revision per reviewer mandate findings Three adversarial reviewers spawned per the new reviewer-mandate doctrine (`[[reviewer-mandate-elegance-and-substrate-viability]]`) BLOCKED with substantive findings. This commit addresses the in-scope ones; the deeper substrate gaps are tracked as follow-ups. ## In-scope fixes (this commit) 1. **Field rename `name` → `seam`.** Reviewer 3 flagged collision risk — other probes use `name` for different semantics. `seam` is unambiguous and tells operators to write `jq 'select(.fields.seam == "cognition.analyze")'`. 2. **Hidden `use ::tracing::Instrument as _;` removed.** Reviewer 1 flagged the scoped import inside macro body as unconventional and cognitively load-bearing. Replaced with fully-qualified `::tracing::Instrument::instrument(future, span).await` call — no hidden import, contract visible at the call site. 3. **Docstring honesty.** Reviewer 2 flagged the prior "zero cost when disabled" claim as overclaim — `Instrumented<F>` wrapper persists at runtime even with `release_max_level_*` features. New cost section: ~24 bytes per call site, one branch per poll, allocates `Span` regardless of subscriber state. Acceptable for cognition seams (Qwen dominates wall-clock); bench per task #198 before sprinkling into hot loops. 4. **Error-path test.** Reviewer 3 flagged missing Result-future coverage. New `time_probe_propagates_error_from_inner_future` pins that `Err` flows through unchanged per `[[no-fallbacks-ever]]`. 5. **Manual example block.** Reviewer 3 flagged the "How to add a probe" section showing only `time_async!` (the RAII shape) but not `time_probe!`. Now shows both with explicit guidance: substrate seams use `time_probe!`; legacy logging-crate seams use `time_async!`. Includes the persistence caveat (see #196). ## Follow-up substrate gaps (separate tasks) - **#196**: `ProbeRouterLayer` + `JsonlProbeFileSink` only implement `on_event`, not `on_close`. `time_sync!` AND `time_probe!` emit SPANS, not events — neither timing macro actually persists timings to the JSONL log today. The call shape ships here; the routing side ships in #196. The macro docstring + manual carry the caveat explicitly. - **#197**: Probe class taxonomy decision — flat `timing` vs hierarchical. Operators filtering `cognition` won't catch cognition timings under the flat scheme; substrate convention needs to be picked. - **#198**: Probe Layer allocation hot-path audit — reviewer 2 estimated ~50-100 HashMap allocs/sec per persona; benchmark before sprinkling into every async seam. ## Why this lands as a revision rather than withdrawal Per `[[refine-tools-as-you-use-them]]`: ship the call-site shape that becomes stable. The routing-side gap (#196) is its own slice worth doing right rather than rushing into this PR. The docstring + manual carry the caveat so no one mistakes the macro for an end-to-end shipping observability primitive — yet. ## Tests 3 passing: - `time_probe_returns_inner_future_value` - `time_probe_propagates_error_from_inner_future` (new — pins Result futures don't swallow errors) - `time_probe_nested_compose_and_return_inner_value` ## Doctrine - `[[reviewer-mandate-elegance-and-substrate-viability]]` — three adversarial lenses (architecture / speed-viability / probe- coverage) all surfaced real findings. The mandate works. - `[[refine-tools-as-you-use-them]]` — revising a primitive in response to reviewer feedback IS the application work informing the substrate. - `[[no-fallbacks-ever]]` — error-path test pinned; substrate refuses silent swallowing at any seam. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com> * fix(probes): on_close in both probe Layers — time_sync!/time_probe! now persist (#196) Load-bearing fix discovered by reviewer-mandate review of #1540 (time_probe!): both `ProbeRouterLayer` and `JsonlProbeFileSink` only implemented `on_event`, so the timing spans emitted by `time_sync!` and `time_probe!` were observed by no consumer. Operators running `CONTINUUM_PROBE_CLASSES=timing` saw zero timing records on disk no matter how many seams were instrumented. The macros were theatrical — Joel's RTOS-debugger framing required actual wall-clock persistence to "hunt down bottlenecks." This commit closes the gap: - `ProbeRouterLayer`: add `SpanProbeMeta` + `on_new_span` + `on_close` so each `probe_class`-carrying span fans out a `ProbeEvent { class, duration_ms, .. }` on close. Spans without `probe_class` are ignored at zero allocation cost per `[[no-fallbacks-ever]]`. - `JsonlProbeFileSink`: mirror the same shape — `FileSinkSpanMeta` + `on_new_span` + `on_close`. Same class filter applies; `duration_ms` is injected into the on-disk JSON `fields` so the line shape matches the broadcast envelope. - `time_sync!`: unify field name to `seam = $name` (was `name`) so it matches `time_probe!`. Operators get one `jq` query — `.fields.seam == "phase"` — that works for either macro. The pre-existing value-transparency tests don't assert on field names so this rename is non-breaking. Tests: - `probe_router::tests::time_sync_span_close_fans_out_timing_event` - `probe_router::tests::time_probe_span_close_fans_out_timing_event` - `probe_router::tests::span_without_probe_class_does_not_fanout` - `probe_file_sink::tests::time_sync_span_close_persists_timing_to_jsonl` - `probe_file_sink::tests::time_probe_span_close_persists_timing_to_jsonl` - `probe_file_sink::tests::plain_span_close_does_not_persist_to_jsonl` - `probe_file_sink::tests::class_filter_applies_to_timing_spans` 244/244 routing tests pass; 13/13 macro tests pass. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com> * refactor(probes): hoist SpanProbeMeta to shared module — addresses R1+R2 BLOCKs Reviewer-mandate review of #1541's first commit BLOCKED twice with overlapping load-bearing concerns: - R1 (architecture/design): SpanProbeMeta + FileSinkSpanMeta were byte-for-byte identical with ~60 lines of copy-pasted lock/visit logic. Each Layer captured its own Instant::now() at on_new_span -> router and sink reported subtly different duration_ms for the same span. No test verified both layers compose in one subscriber. - R2 (speed/Intel-Mac viability): on_new_span fired for EVERY tracing span the substrate emits (tokio executor, framework, plain info_span!). Each Layer's visitor allocated a HashMap + walked ALL fields with format!(...) before discarding when probe_class was missing. Per-span allocator pressure on the LCD floor. This refactor hoists the lifecycle into routing/probe_span_meta.rs: 1. span_carries_probe_class(attrs) - cheap static check. Walks attrs.metadata().fields() (static field set, no allocation) for the probe_class name. The vast majority of spans short-circuit here with zero visitor work. Addresses R2's per-span hot-path cost. 2. ensure_probe_meta(attrs, span_ref) - idempotent install. First Layer to see the span populates the extension; second Layer finds it already present and no-ops. Both Layers visit the attrs ONCE total, not once per Layer. Addresses R2's doubled-cost concern. 3. build_timing_event_from_meta(span_ref, uri_chain) - shared event builder. Both Layers read the SAME start: Instant from the extension -> identical duration_ms on broadcast stream and JSONL log. Addresses R1's timing-drift concern. 4. New composition test: probe_file_sink::tests::both_layers_in_one_subscriber_agree_on_duration_ms installs ProbeRouterLayer + JsonlProbeFileSink in one subscriber, fires a time_sync!, asserts the broadcast subscriber + JSONL line agree on class + seam + duration_ms. Pins R1's "no composition test" gap. 5. docs/architecture/RTOS-DEBUGGER-PROBES.md pins the seam-not-name field-naming convention per R1's minor - operators can jq '.fields.seam' against both time_sync! and time_probe! output without thinking about which macro emitted the record. Tests: 247/247 routing tests pass (3 net new). The composition test would have caught the original duplication-induced drift had it existed. Co-Authored-By: Claude Opus 4.7 <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.7 <noreply@anthropic.com>

github-actions Bot added the size: M label Jun 6, 2026

joelteply mentioned this pull request Jun 6, 2026

fix(probes): on_close in both probe Layers — time_sync!/time_probe! now persist (#196) #1541

Merged

4 tasks

joelteply merged commit ebb37d3 into canary Jun 6, 2026
3 checks passed

joelteply deleted the time-probe-macro branch June 6, 2026 21:37

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(probes): time_probe! macro — safe one-line async timing#1540

feat(probes): time_probe! macro — safe one-line async timing#1540
joelteply merged 2 commits into
canaryfrom
time-probe-macro

joelteply commented Jun 6, 2026 •

edited

Loading

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Conversation

joelteply commented Jun 6, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

What's in this PR (after revision)

Tests (3 passing)

Reviewer findings — what's in vs follow-up

Why revise rather than withdraw

How the reviewer mandate worked

Doctrine

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

joelteply commented Jun 6, 2026 •

edited

Loading