Skip to content

feat(telemetry): first-run health — startup_ready, event_loop_stall, registration timing - #1294

Merged
anandgupta42 merged 1 commit into
mainfrom
feat/first-run-telemetry
Sep 10, 2026
Merged

anandgupta42 merged 1 commit into
mainfrom
feat/first-run-telemetry

Conversation

@anandgupta42

@anandgupta42 anandgupta42 commented Sep 9, 2026

Copy link
Copy Markdown
Contributor

Why

The 0.11.0 first-run freeze (#1292: an in-process @npmcli/arborist install blocking Bun's event loop for 2.5 to 5 minutes) shipped in six releases without a trace in telemetry. Three reasons, all structural:

  1. Nothing timed startup or registration. The first event a session reports is session_start; the next is a generation after the model answers. A freeze between them produced no number anywhere.
  2. Events flush on a 5 s setInterval on the same loop that was blocked. A frozen-then-killed process died with its buffer and left only session_start + task_classified (a "dead session": 0 to 2 s span, no generation, no error, no end).
  3. The only place it was visible was first-generation latency split by brand-new versus returning machines, which no default view does. Fresh machines on 0.9.5 and 0.9.7 had a p90 of 195 to 244 s versus 17 to 21 s for returning ones.

What

Event Emitted Fields
startup_ready once per process: serve listening, TUI transport resolved, run about to send its first prompt command, duration_ms (process uptime), fresh_install
event_loop_stall a 250 ms monitor tick that fires more than 1 s late; capped at 20 per process; main thread and TUI server worker blocked_ms, since_start_ms, thread, command
altimate_base_registration every registerAfterConsent outcome, so the TUI dialog and the HTTP consent route both count result, duration_ms, status

Plus: anchor events (first_launch, startup_ready, event_loop_stall, altimate_base_registration, session_start) flush immediately instead of waiting for the interval, and the CLI middleware records the top-level command via Telemetry.setCommand.

The stall monitor reports when the loop resumes, so a stall that ends in a killed process is still lost, but every stall a user waited through is now a number, and it is flushed before anything else can go wrong.

docs/internal/first-run-telemetry.md carries the rationale, the event table, and KQL for startup time, stalls, registration, and the fresh-versus-returning dead-session rate (the last one works on historical data).

Verification

  • bun test: 8 new tests (startup_ready once per process; pure lag check; monitor detects a synchronous 250 ms block and stays quiet otherwise; idempotent start/stop; registration success, HTTP 429 with status, misconfigured gateway URL, network failure) plus the existing telemetry, Altimate Base, TUI and provider-API suites, all green. tsgo --noEmit clean. Upstream marker guard clean.
  • Live: serve in a fresh isolated HOME with APPLICATIONINSIGHTS_CONNECTION_STRING pointed at a local sink received startup_ready command=serve within the anchor flush, from both the dev build (2048 ms) and a bun build --compile single-target binary (1561 ms), so the monitor and isMainThread behave in the compiled form.
  • Second-model review folded in: startup_ready now fires for run --command as well as plain prompts, and a ConfigurationError from the gateway URL is reported as result: configuration instead of escaping before the timer starts.

Known limit

Telemetry is initialised and shut down per prompt by session/prompt.ts, so in a long-lived serve process the stall monitor, like every other event, is dark between prompts. That is pre-existing lifecycle behaviour, noted here so nobody reads an absence of stalls outside a prompt window as proof of health.

🤖 Generated with Claude Code

https://claude.ai/code/session_01WrT7MEUL5CYvpjf9cJbeQR


Note

Medium Risk
Touches telemetry flush timing and runs instrumentation on CLI main thread and TUI worker at startup; low user-facing risk but changes when events ship and adds process-lifetime monitors tied to telemetry init/shutdown.

Overview
Adds first-run health telemetry so long startup freezes and silent “dead sessions” show up in App Insights instead of only session_start with no follow-up.

New events: startup_ready (once per process when tui / serve / run can work, with uptime and fresh_install), event_loop_stall (250 ms monitor, >1 s late tick, capped at 20, main vs worker), and altimate_base_registration (every registerAfterConsent outcome with duration and HTTP status when relevant).

Behavior: Selected anchor events (first_launch, startup_ready, event_loop_stall, altimate_base_registration, session_start) flush immediately instead of waiting on the 5 s interval. CLI middleware records the top-level command via Telemetry.setCommand; the TUI worker starts the stall monitor and calls Telemetry.init() at boot so pre-prompt blocking is observable.

Altimate Base: Registration paths report telemetry for expired consent, bad gateway URL (configuration), success/failure; caller aborts are classified as cancelled rather than network.

Docs/tests: docs/internal/first-run-telemetry.md with KQL for startup, stalls, registration, and dead-session rate; new unit tests plus an existing flush-retry test adjusted to avoid anchor auto-flush.

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


Summary by cubic

Adds first-run health telemetry so the 2.5–5 minute freeze from the 0.11.0 first-run @npmcli/arborist install shows up in telemetry instead of a "dead session" that reports only session_start.

  • Emits startup_ready once per process when serve, tui, or run can start work, with command, duration, and fresh-install flag.
  • Emits event_loop_stall when a 250 ms monitor tick is over 1 s late, capped at 20 per process, on main and worker threads; the TUI worker starts the monitor at boot.
  • Emits altimate_base_registration for every registration outcome on both TUI and HTTP consent paths; a caller abort reports cancelled and a bad gateway URL reports configuration.
  • Anchor events (first_launch, startup_ready, event_loop_stall, altimate_base_registration, session_start) flush immediately instead of waiting for the 5 s interval.
  • CLI middleware records the top-level command via Telemetry.setCommand, and documentation with KQL queries lives in docs/internal/first-run-telemetry.md.

Written for commit f6343e2. Summary will update on new commits.

Review in cubic

Summary by CodeRabbit

  • New Features

    • Added first-run health telemetry for startup readiness and event-loop stalls across CLI, server, and TUI workflows.
    • Added telemetry for Altimate Base registration outcomes, including duration, result type, cancellation status, and relevant HTTP status details.
    • Startup health events now flush immediately for more timely reporting.
  • Documentation

    • Added guidance for interpreting first-run health telemetry and querying startup, event-loop, registration, and session metrics.

Loading
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant