feat(stats): expose summary-stat cache hit/miss + timing as a structured signal - #944
Merged
Conversation
…red signal (#943) The xorq summary-stat snapshot cache already counts hits/misses but only emits them as a free-text log line. Make the outcome a first-class, timed, public signal so a telemetry consumer (tallyman's grid-load log, or the OTel work in #943) can read it: XorqStatPipeline now times each process_table run (cache_stats["secs"]) and exposes cache_run_stats() -> {hits, misses, snapshots, bytes, write_errors, secs, cached, status} where status is hit/miss/mixed/none/uncached; XorqDfStatsV2 passes it through; the per-run cache summary log line now includes elapsed time. Tested cold->miss, warm->hit, uncached. Telemetry transport (OTel SDK + trace-context propagation across companion->server->widget, plus the WS row-range spans) remains the larger #943 scope. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Contributor
📦 TestPyPI package publishedpip install --index-strategy unsafe-best-match --index-url https://test.pypi.org/simple/ --extra-index-url https://pypi.org/simple/ buckaroo==0.15.2.dev28206715756or with uv: uv pip install --index-strategy unsafe-best-match --index-url https://test.pypi.org/simple/ --extra-index-url https://pypi.org/simple/ buckaroo==0.15.2.dev28206715756MCP server for Claude Codeclaude mcp add buckaroo-table -- uvx --from "buckaroo[mcp]==0.15.2.dev28206715756" --index-strategy unsafe-best-match --index-url https://test.pypi.org/simple/ --extra-index-url https://pypi.org/simple/ buckaroo-table📖 Docs preview🎨 Storybook preview |
…ver MVP, #943) Promote the perf_log firstpull.* spans into bespoke, OTel-shaped telemetry records POSTed to the companion, correlated by buckaroo session id — the server half of #943, built on #944's cache_run_stats(). - perf_log: trace/source/sink ContextVars + telemetry_context(); http_sink() fire-and-forget POSTs (thread pool, can't stall the IOLoop); flush_telemetry() for tests. perf_span yields a span handle (set_attr) and emits a flat {trace, source, name, t_start_ms, t_end_ms, attrs} record when a sink is bound. - /load_expr: read telemetry_url from the payload, bind the sink + session trace around the firstpull.* spans, persist telemetry_url on the session. - WS handler: re-bind the sink from the session for firstpull.ws_first_payload (the POST and WS run in separate async contexts). - summary_stats span: attach the cache_run_stats() hit/miss/timing attrs (#944). Emission is decoupled from the BUCKAROO_PERF flag: a span emits when perf logging is on OR a sink is bound, so telemetry stays isolated to telemetry sessions and the emitted set is exactly the firstpull.* initial_load timeline. Widget spans (buckaroo-js-core) deferred per the MVP cut; the companion /internal/telemetry receiver lives in tallyman. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
…ad pool (#943) Replace the perf_log ThreadPoolExecutor + _pending_posts machinery with an AsyncHTTPClient sink in buckaroo/server/telemetry.py that fire-and-forgets each span POST via loop.spawn_callback. Records now post on the existing Tornado IOLoop with no threads to create, bound, or shut down, and perf_log stays transport-agnostic (no tornado import) for the widget/stats path. Also addresses PR review: - perf_span: gate the "perf span=" log line on BUCKAROO_PERF so a telemetry-only session emits records without writing perf lines into server.log. The log line and the emitted record are now independent. - derive t_end_ms from the monotonic perf_counter delta instead of a second wall-clock read, so a clock step can't make a span end before it starts. - test_load_expr: drive a real cache miss (cache_storage_path) and assert the exact cache_status + hit/miss counts end-to-end (#944), not just "not a hit"; hoist in-function imports to module scope. - add a perf_log telemetry test locking in the log/record decoupling. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
… for WS first-pull (#944) The telemetry HTTP sink was built independently in two places from the same telemetry_url: the /load_expr POST handler and the WS first-pull path. Build it once on the IOLoop in /load_expr and stash the callable on the session as `tele_sink`; the WS handler reads it back instead of rebuilding (a second AsyncHTTPClient capture + closure). Both handlers run on the same single-process IOLoop, so the captured loop stays valid. - session.py: replace the write-only `telemetry_url: str` field with `tele_sink: Optional[Callable[[Dict[str, Any]], None]]` — single source of truth, and the type guards against passing a raw URL where a sink is expected. Drop the now-unused `telemetry` import from websocket_handler. - WS gating is behavior-equivalent: `session.tele_sink` is None exactly when telemetry_url was absent, so `tele_sink = session.tele_sink if not_seen else None` matches the old `make_http_sink(...) if (url and not_seen)` across every case. Adds test_telemetry_sink_built_once_not_rebuilt_by_ws, a deterministic guard pinning make_http_sink to call_count == 1 across POST + WS. Verified it bites: simulating a WS-side rebuild fails it with 2 != 1. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
…k decoupling (#944) Two server-side telemetry gaps from the #944 review, each test seen failing on CI before its fix lands: - test_first_pull_telemetry_rearms_after_warm_reload: a warm /load_expr re-POST (same session+build_dir, no force_reload/config — the early-exit that returns cached metadata) leaves _perf_first_payload_seen True and never rebinds the sink, so the refreshed page's WS first-pull span is silently dropped. - test_internal_spans_emit_to_telemetry_sink_with_perf_off: XorqStatPipeline._span gates on perf_log.enabled() alone, so with BUCKAROO_PERF off a telemetry-only run emits firstpull.* but never the stat.xorq.* timeline — perf_span's enabled-OR-sink decoupling wasn't applied to _span. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
…t spans to a bound sink (#944) Two server-side telemetry gaps surfaced in the #944 review: 1. Warm-session early-exit dropped telemetry. A /load_expr re-POST that matched a warm session (same build_dir, no force_reload, no config field) returned cached metadata before the sink was built and before _perf_first_payload_seen was reset, and telemetry_url is not a config-bearing field — so a page refresh's WS first-pull (a genuine new time-to-first-rows) emitted nothing and a freshly-supplied telemetry_url was ignored. Build the sink before the early-exit and, in the warm branch, rebind existing.tele_sink and reset the first-pull flag so the warm path re-arms exactly like the full-load path. 2. XorqStatPipeline._span gated solely on perf_log.enabled(), so with BUCKAROO_PERF off a telemetry-only run emitted firstpull.* but never the stat.xorq.* timeline. Defer the gate to perf_span (which is live on enabled-OR-sink), keeping only the unit-test suppression here. Fixes the two tests added in 88dc3fb. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
…helper (#944) The first-pull and eager-second-window blocks were near-identical copy-paste — each picked a span (perf_span-or-nullcontext gated on first_payload), dispatched one window, wrote the JSON text frame, then the binary Parquet frame when non-empty. Extract _dispatch_and_send(pa, span_label) so the two-frame send contract and the span gating live in one place. Behavior-preserving; covered by the existing test_ws_first_payload / test_ws_eager_second_request telemetry tests. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Collaborator
Author
Review pass (
|
| # | Finding | Disposition |
|---|---|---|
| 1 | Warm-session early-exit drops telemetry. A /load_expr re-POST matching a warm session (same build_dir, no force_reload/config — telemetry_url isn't a config-bearing field) returned cached metadata before the sink was built and before _perf_first_payload_seen was reset, so a page-refresh's WS first-pull emitted nothing and a fresh telemetry_url was ignored. |
Fixed c36b1632 — build the sink before the early-exit; in the warm branch rebind existing.tele_sink and reset the first-pull flag, so the warm path re-arms exactly like the full-load path. Test: test_first_pull_telemetry_rearms_after_warm_reload. |
| 2 | _span decoupling gap. XorqStatPipeline._span gated solely on perf_log.enabled(), so a telemetry-only run (BUCKAROO_PERF off, sink bound) emitted firstpull.* but never the stat.xorq.* timeline. |
Fixed c36b1632 — defer the gate to perf_span (live on enabled-OR-sink), keeping only the unit-test suppression in _span. Test: test_internal_spans_emit_to_telemetry_sink_with_perf_off. |
| 3 | First-pull flag set only on success → double emit on dispatch-retry. | No change. The failed first dispatch is still logged (log.error) and emitted as an errored=true span record — nothing is lost. Leaving the flag unset is intentional (keep emitting until a clean first-pull lands); the errored=true tag is the dedupe key for a consumer. |
| 4 | make_http_sink docstring overstates backpressure — max_clients caps concurrency, not queue depth; a dead companion under sustained emission queues unboundedly. |
Filed as #946 (latent; current firstpull.*-only volume keeps it dormant). |
| 5 | Duplicated first/second WS payload blocks. | Fixed (refactor) 827b402a — extracted _dispatch_and_send(pa, span_label); behavior-preserving, covered by the existing WS payload telemetry tests. |
| 6 | cache_run_stats() computed unconditionally on the no-op span path. |
Declined — negligible (a dict copy + branch); not worth a guard. |
Collaborator
Author
|
@codex review |
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 827b402a4c
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
Comment on lines
+233
to
+234
| tele_sink = session.tele_sink if not_seen else None | ||
| first_payload = not_seen and (perf_log.enabled() or tele_sink is not None) |
There was a problem hiding this comment.
Because this reads session.tele_sink for any backend, a session can carry a sink from an earlier /load_expr into a later /load: /load clears xorq_dataflow/expr but never clears tele_sink. If the first WS payload had not yet run when the session is reused, the first plain-file infinite_request will POST telemetry to the old telemetry_url even though the new load did not opt in. Clear the sink when switching loaders or gate this on the xorq telemetry load.
Useful? React with 👍 / 👎.
| # seen flag — else the flag stays True from the prior load and the | ||
| # warm pull's span is silently dropped (#944). | ||
| existing.tele_sink = tele_sink | ||
| existing._perf_first_payload_seen = False |
There was a problem hiding this comment.
On the warm-session early exit this runs even when no_browser=true or an existing WS remains open, where the handler returns cached metadata without causing a page reload or sending a fresh initial state. Resetting the flag in that case makes the next ordinary scroll on the existing socket get labeled/emitted as firstpull.ws_first_payload, skewing the first-pull timeline; only re-arm when a new browser/WS pull is actually being initiated.
Useful? React with 👍 / 👎.
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
1 participant
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.
Part of #943 — the server-side summary-stats cache signal.
What
The xorq summary-stat snapshot cache already counts hits/misses per
process_tablerun, but only emits them as a free-textlog.infoline — nothing structured or timed a telemetry consumer can read.This makes the outcome a first-class, timed, public signal:
XorqStatPipelinenow times eachprocess_tablerun (_cache_stats["secs"]).XorqStatPipeline.cache_run_stats()→{hits, misses, snapshots, bytes, write_errors, secs, cached, status}, wherestatusishit/miss/mixed/none(cache configured) oruncached.XorqDfStatsV2.cache_run_stats()passes it through, so a consumer reading from the stats wrapper (the dataflow / widget) gets it without reaching into.ap.Why
#943 wants a timeline of the grid-load pipeline. "Whether the stat cache was used for summary stats" and "summary-stats start/end" are two of the requested signals, and they're only observable inside buckaroo — the companion (tallyman) passes the cache path but never learns hit/miss. This exposes that signal as structured, timed data: the foundation an OTel emitter (or any consumer) attaches to.
Scope — not in this PR
The telemetry transport — OTel SDK + trace-context propagation across companion → server → widget, plus the WebSocket row-range spans — remains the larger #943 work. This PR is the server-side cache/stats signal made first-class; it changes no request/response contract and adds no dependency.
Tests
tests/unit/test_xorq_stats_v2.py::TestSnapshotCacheRun:test_cache_run_stats_reports_status_and_timing— cold run →status="miss"+secs; warm run →status="hit".test_cache_run_stats_uncached— no cache →status="uncached".70 stats tests pass; ruff + paddy-format clean (pre-commit + pre-push).
🤖 Generated with Claude Code