Skip to content

Add StartupTimings per-phase breakdown to Client::start - #2066

Merged
SteveSandersonMS merged 3 commits into
mainfrom
jmoseley-ttft-sdk-seams
Jul 28, 2026
Merged

Add StartupTimings per-phase breakdown to Client::start#2066
SteveSandersonMS merged 3 commits into
mainfrom
jmoseley-ttft-sdk-seams

Conversation

@jmoseley

@jmoseley jmoseley commented Jul 23, 2026

Copy link
Copy Markdown
Contributor

Summary

Adds a StartupTimings struct to the Rust SDK that decomposes the CLI spawn + handshake cost of Client::start into per-phase millisecond fields. This is Phase 1 of a cross-repo effort to reduce and instrument time to first token (TTFT): the github-app host currently only measures the total Client::start(config).await duration and can't attribute cold-start latency to a specific phase.

What's included

New module rust/src/startup_timings.rs with a #[non_exhaustive] public StartupTimings struct:

Field Type Phase
program_resolve_ms Option<u64> Bundled-CLI resolution/extraction (resolve::copilot_binary_with_extract_dir); None for an explicit CLI path
process_spawn_ms Option<u64> Subprocess command.spawn(); None for external and in-process transports
port_wait_ms Option<u64> TCP port-announcement wait; present only for TCP transport
transport_setup_ms u64 Full transport setup, including spawn/connect, external connect, or in-process FFI startup
handshake_ms u64 verify_protocol_version connect round-trip
session_fs_ms Option<u64> sessionFs.setProvider RPC when configured
llm_handler_ms Option<u64> llmInference.setProvider RPC when configured
total_ms u64 Full Client::start wall-clock time

Required fields are always populated on a successful Client::start. Optional fields are present only when their phase runs.

Surfacing (non-breaking)

  • Timings are stored on ClientInner via a OnceLock and exposed through Client::startup_timings() -> Option<StartupTimings>.
  • A single structured debug span carries the full breakdown. Optional timing fields are numeric when present and the string "None" otherwise.
  • Client::start's return type is unchanged. Existing per-phase debug logs are retained.

Validation

  • Rust formatting and type checking pass.
  • Unit coverage verifies duration conversion, defaults, and from_streams behavior.
  • E2E coverage verifies startup timing behavior for stdio, TCP, and in-process transports.
  • PR CI exercises Rust on Linux, macOS, and Windows, including bundled and in-process configurations.

Scope

SDK crate only. The github-app host will consume these after a vendored SDK bump (separate follow-up); this PR does not touch github-app.

Introduce a `StartupTimings` struct that decomposes the CLI spawn +
handshake cost into per-phase millisecond fields, so hosts can attribute
"time to first token" startup latency to a specific phase instead of
reconstructing it from scattered debug lines.

Phases captured:
- program_resolve_ms: NEW timer around bundled-CLI resolution/extraction
  (`resolve::copilot_binary_with_extract_dir`), previously untimed and the
  prime suspect for cold-start cost on Windows.
- process_spawn_ms: subprocess `command.spawn()`.
- port_wait_ms: TCP port-announcement wait (tcp transport only).
- handshake_ms: `verify_protocol_version` connect round-trip.
- session_fs_ms / llm_handler_ms: post-handshake provider-registration RPCs.
- total_ms: full Client::start wall-clock.

Surfacing is non-breaking: timings are stored on ClientInner via a
`OnceLock` and exposed through a new `Client::startup_timings()` getter,
plus a single structured `debug!` event. `Client::start`'s return type is
unchanged. Existing per-phase debug logs are retained.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Copilot-Session: 95834bd3-b7ac-40bc-8bf4-60102600d41a
Copilot AI review requested due to automatic review settings July 23, 2026 19:42
@jmoseley
jmoseley requested a review from a team as a code owner July 23, 2026 19:42

Copilot AI 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.

Pull request overview

Adds per-phase Rust SDK startup timing instrumentation for TTFT analysis.

Changes:

  • Introduces the public StartupTimings type.
  • Measures startup phases and exposes them through Client::startup_timings().
  • Emits a consolidated tracing event.
Show a summary per file
File Description
rust/src/startup_timings.rs Defines timing fields and duration conversion tests.
rust/src/lib.rs Captures, stores, logs, and exposes startup timings.

Review details

  • Files reviewed: 2/2 changed files
  • Comments generated: 2
  • Review effort level: Medium

Comment thread rust/src/lib.rs Outdated
Comment thread rust/src/lib.rs
Emit numeric structured fields, cover all transport setup, tighten always-present timing values, and exercise startup timings in Rust E2E tests.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings July 28, 2026 10:52

Copilot AI 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.

Review details

Comments suppressed due to low confidence (1)

rust/src/startup_timings.rs:55

  • The PR description documents every timing field as Option<u64> and omits transport_setup_ms, while the public API makes this field (along with handshake_ms and total_ms) a required u64. Please align the PR's advertised API shape with the implementation so the downstream host integration is not planned against the wrong contract.
    /// Total transport setup time. This includes spawning and connecting to a
    /// subprocess, connecting to an external server, or starting the in-process
    /// FFI runtime. `process_spawn_ms` and `port_wait_ms` provide nested detail
    /// for spawned transports.
    pub transport_setup_ms: u64,
  • Files reviewed: 5/5 changed files
  • Comments generated: 0 new
  • Review effort level: Medium

Record each optional timing as a numeric span field when present and the string None otherwise, without companion presence flags.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings July 28, 2026 10:57

Copilot AI 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.

Review details

Comments suppressed due to low confidence (2)

rust/src/lib.rs:1403

  • The timing values are attached to a span, while this debug! event contains only its message. Event-oriented tracing layers/exporters therefore do not receive the promised structured timing fields without separately collecting and joining span callbacks, contrary to the PR's single-event goal. Emit the fields on the event itself (or change the documented logging contract).
        timings_span.in_scope(|| debug!("Client::start timings"));

rust/src/startup_timings.rs:39

  • The public shape differs from the stated contract: the PR description says the seven timing fields are all Option<u64> and does not list transport_setup_ms, while this struct adds that field and makes transport_setup_ms, handshake_ms, and total_ms plain u64. Since the follow-up host is expected to consume this API, align the implementation and PR contract before merging.
pub struct StartupTimings {
  • Files reviewed: 5/5 changed files
  • Comments generated: 0 new
  • Review effort level: Medium

@SteveSandersonMS
SteveSandersonMS added this pull request to the merge queue Jul 28, 2026
Merged via the queue into main with commit 2b5e237 Jul 28, 2026
20 checks passed
@SteveSandersonMS
SteveSandersonMS deleted the jmoseley-ttft-sdk-seams branch July 28, 2026 11:14
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.

3 participants