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

* Add StartupTimings breakdown to Client::start

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

* Harden startup timing observability

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>

* Simplify optional startup timing fields

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>

---------

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Co-authored-by: Steve Sanderson <1101362+SteveSandersonMS@users.noreply.github.com>
Copilot-Session: 95834bd3-b7ac-40bc-8bf4-60102600d41a

Author: 3 people

rust/README.md

@@ -70,6 +70,20 @@ let pong = client.ping("hello").await?;
 client.stop().await?;
 ```
 
+After `Client::start` succeeds, inspect its startup cost without parsing logs:
+
+```rust,ignore
+let timings = client.startup_timings().expect("started by Client::start");
+println!(
+    "startup={}ms transport={}ms handshake={}ms",
+    timings.total_ms, timings.transport_setup_ms, timings.handshake_ms
+);
+```
+
+Transport-specific phases are optional. For example, `port_wait_ms` is present
+only for TCP and `process_spawn_ms` is absent for external and in-process
+transports.
+
 **`ClientOptions`:**
 
 | Field               | Type                        | Description                                                       |

rust/src/lib.rs

@@ -40,6 +40,8 @@ pub mod session;
 /// Custom session filesystem provider (virtualizable filesystem layer).
 pub mod session_fs;
 mod session_fs_dispatch;
+/// Per-phase timing breakdown for [`Client::start`].
+pub mod startup_timings;
 /// Event subscription handles returned by `subscribe()` methods.
 pub mod subscription;
 /// Typed tool definition framework and dispatch router.
@@ -106,12 +108,24 @@ pub use types::*;
 
 mod sdk_protocol_version;
 pub use sdk_protocol_version::{SDK_PROTOCOL_VERSION, get_sdk_protocol_version};
+pub use startup_timings::StartupTimings;
 pub use subscription::{EventSubscription, LifecycleSubscription};
 
 /// Minimum protocol version this SDK can communicate with.
 const MIN_PROTOCOL_VERSION: u32 = 3;
 const RUNTIME_SHUTDOWN_TIMEOUT: Duration = Duration::from_secs(10);
 
+fn record_optional_millis(span: &tracing::Span, field: &'static str, value: Option<u64>) {
+    match value {
+        Some(value) => {
+            span.record(field, value);
+        }
+        None => {
+            span.record(field, "None");
+        }
+    }
+}
+
 /// How the SDK communicates with the CLI server.
 #[derive(Debug, Default)]
 #[non_exhaustive]
@@ -1007,6 +1021,10 @@ struct ClientInner {
     /// SDK [`ClientMode`] captured at start time. Drives empty-mode safe
     /// defaults inside `create_session` / `resume_session`.
     pub(crate) mode: ClientMode,
+    /// Per-phase startup timing breakdown, populated once at the end of
+    /// [`Client::start`]. Empty for clients built via [`Client::from_streams`]
+    /// or [`Client::from_transport`] directly.
+    startup_timings: OnceLock<StartupTimings>,
 }
 
 impl Client {
@@ -1024,6 +1042,7 @@ impl Client {
     /// backend.
     pub async fn start(options: ClientOptions) -> Result<Self> {
         let start_time = Instant::now();
+        let mut timings = StartupTimings::default();
         let mut options = options;
         if matches!(options.transport, Transport::Default) {
             options.transport = resolve_default_transport(&options)?;
@@ -1119,9 +1138,16 @@ impl Client {
                 path.clone()
             }
             CliProgram::Resolve => {
+                let resolve_start = Instant::now();
                 let resolved = resolve::copilot_binary_with_extract_dir(
                     options.bundled_cli_extract_dir.as_deref(),
                 )?;
+                let resolve_elapsed = resolve_start.elapsed();
+                timings.program_resolve_ms = Some(StartupTimings::millis(resolve_elapsed));
+                debug!(
+                    elapsed_ms = resolve_elapsed.as_millis(),
+                    "Client::start CLI program resolution complete"
+                );
                 info!(path = %resolved.display(), "resolved copilot CLI");
                 #[cfg(windows)]
                 {
@@ -1148,6 +1174,7 @@ impl Client {
             }
         };
 
+        let transport_setup_start = Instant::now();
         let client = match options.transport {
             Transport::Default => unreachable!("default transport resolved above"),
             Transport::External {
@@ -1183,8 +1210,10 @@ impl Client {
                 port,
                 connection_token: _,
             } => {
-                let (mut child, actual_port) =
+                let (mut child, actual_port, spawn_elapsed, port_wait_elapsed) =
                     Self::spawn_tcp(&program, &options, &working_directory, port).await?;
+                timings.process_spawn_ms = Some(StartupTimings::millis(spawn_elapsed));
+                timings.port_wait_ms = Some(StartupTimings::millis(port_wait_elapsed));
                 let connect_start = Instant::now();
                 let stream = TcpStream::connect(("127.0.0.1", actual_port)).await?;
                 debug!(
@@ -1209,7 +1238,9 @@ impl Client {
                 )?
             }
             Transport::Stdio => {
-                let mut child = Self::spawn_stdio(&program, &options, &working_directory)?;
+                let (mut child, spawn_elapsed) =
+                    Self::spawn_stdio(&program, &options, &working_directory)?;
+                timings.process_spawn_ms = Some(StartupTimings::millis(spawn_elapsed));
                 let stdin = child.stdin.take().expect("stdin is piped");
                 let stdout = child.stdout.take().expect("stdout is piped");
                 Self::drain_stderr(&mut child);
@@ -1290,11 +1321,14 @@ impl Client {
                 unreachable!("in-process feature validation returned above")
             }
         };
+        timings.transport_setup_ms = StartupTimings::millis(transport_setup_start.elapsed());
         debug!(
             elapsed_ms = start_time.elapsed().as_millis(),
             "Client::start transport setup complete"
         );
+        let handshake_start = Instant::now();
         client.verify_protocol_version().await?;
+        timings.handshake_ms = StartupTimings::millis(handshake_start.elapsed());
         debug!(
             elapsed_ms = start_time.elapsed().as_millis(),
             "Client::start protocol verification complete"
@@ -1313,8 +1347,10 @@ impl Client {
                 session_state_path: cfg.session_state_path,
             };
             client.rpc().session_fs().set_provider(request).await?;
+            let session_fs_elapsed = session_fs_start.elapsed();
+            timings.session_fs_ms = Some(StartupTimings::millis(session_fs_elapsed));
             debug!(
-                elapsed_ms = session_fs_start.elapsed().as_millis(),
+                elapsed_ms = session_fs_elapsed.as_millis(),
                 "Client::start session filesystem setup complete"
             );
         }
@@ -1334,11 +1370,38 @@ impl Client {
                 client.inner.on_github_telemetry.clone(),
             );
             client.rpc().llm_inference().set_provider().await?;
+            let llm_inference_elapsed = llm_inference_start.elapsed();
+            timings.llm_handler_ms = Some(StartupTimings::millis(llm_inference_elapsed));
             debug!(
-                elapsed_ms = llm_inference_start.elapsed().as_millis(),
+                elapsed_ms = llm_inference_elapsed.as_millis(),
                 "Client::start Copilot request handler registration complete"
             );
         }
+        timings.total_ms = StartupTimings::millis(start_time.elapsed());
+        // A span allows optional fields to retain their numeric type when
+        // present while recording an explicit "None" when a phase did not run.
+        let timings_span = tracing::debug_span!(
+            "Client::start timings",
+            program_resolve_ms = tracing::field::Empty,
+            process_spawn_ms = tracing::field::Empty,
+            port_wait_ms = tracing::field::Empty,
+            transport_setup_ms = timings.transport_setup_ms,
+            handshake_ms = timings.handshake_ms,
+            session_fs_ms = tracing::field::Empty,
+            llm_handler_ms = tracing::field::Empty,
+            total_ms = timings.total_ms,
+        );
+        record_optional_millis(
+            &timings_span,
+            "program_resolve_ms",
+            timings.program_resolve_ms,
+        );
+        record_optional_millis(&timings_span, "process_spawn_ms", timings.process_spawn_ms);
+        record_optional_millis(&timings_span, "port_wait_ms", timings.port_wait_ms);
+        record_optional_millis(&timings_span, "session_fs_ms", timings.session_fs_ms);
+        record_optional_millis(&timings_span, "llm_handler_ms", timings.llm_handler_ms);
+        timings_span.in_scope(|| debug!("Client::start timings"));
+        let _ = client.inner.startup_timings.set(timings);
         debug!(
             elapsed_ms = start_time.elapsed().as_millis(),
             "Client::start complete"
@@ -1507,6 +1570,7 @@ impl Client {
                 on_get_trace_context,
                 effective_connection_token,
                 mode,
+                startup_timings: OnceLock::new(),
             }),
         };
         client.spawn_lifecycle_dispatcher();
@@ -1683,7 +1747,7 @@ impl Client {
         program: &Path,
         options: &ClientOptions,
         working_directory: &Path,
-    ) -> Result<Child> {
+    ) -> Result<(Child, Duration)> {
         info!(cwd = ?working_directory, program = %program.display(), "spawning copilot CLI (stdio)");
         let mut command = Self::build_command(program, options, working_directory);
         command
@@ -1696,19 +1760,20 @@ impl Client {
             .stdin(Stdio::piped());
         let spawn_start = Instant::now();
         let child = command.spawn()?;
+        let spawn_elapsed = spawn_start.elapsed();
         debug!(
-            elapsed_ms = spawn_start.elapsed().as_millis(),
+            elapsed_ms = spawn_elapsed.as_millis(),
             "Client::spawn_stdio subprocess spawned"
         );
-        Ok(child)
+        Ok((child, spawn_elapsed))
     }
 
     async fn spawn_tcp(
         program: &Path,
         options: &ClientOptions,
         working_directory: &Path,
         port: u16,
-    ) -> Result<(Child, u16)> {
+    ) -> Result<(Child, u16, Duration, Duration)> {
         info!(cwd = ?working_directory, program = %program.display(), port = %port, "spawning copilot CLI (tcp)");
         let mut command = Self::build_command(program, options, working_directory);
         command
@@ -1721,8 +1786,9 @@ impl Client {
             .stdin(Stdio::null());
         let spawn_start = Instant::now();
         let mut child = command.spawn()?;
+        let spawn_elapsed = spawn_start.elapsed();
         debug!(
-            elapsed_ms = spawn_start.elapsed().as_millis(),
+            elapsed_ms = spawn_elapsed.as_millis(),
             "Client::spawn_tcp subprocess spawned"
         );
         let stdout = child.stdout.take().expect("stdout is piped");
@@ -1759,13 +1825,14 @@ impl Client {
             .map_err(|_| Error::from(ErrorKind::Protocol(ProtocolErrorKind::CliStartupTimeout)))?
             .map_err(|_| Error::from(ErrorKind::Protocol(ProtocolErrorKind::CliStartupFailed)))?;
 
+        let port_wait_elapsed = port_wait_start.elapsed();
         debug!(
-            elapsed_ms = port_wait_start.elapsed().as_millis(),
+            elapsed_ms = port_wait_elapsed.as_millis(),
             port = actual_port,
             "Client::spawn_tcp TCP port wait complete"
         );
         info!(port = %actual_port, "CLI server listening");
-        Ok((child, actual_port))
+        Ok((child, actual_port, spawn_elapsed, port_wait_elapsed))
     }
 
     fn drain_stderr(child: &mut Child) {
@@ -1942,6 +2009,16 @@ impl Client {
         self.inner.negotiated_protocol_version.get().copied()
     }
 
+    /// Returns the per-phase [`StartupTimings`] breakdown captured during
+    /// [`start`](Self::start), if available.
+    ///
+    /// Returns `None` for clients created via
+    /// [`from_streams`](Self::from_streams), which bypasses the timed startup
+    /// sequence.
+    pub fn startup_timings(&self) -> Option<StartupTimings> {
+        self.inner.startup_timings.get().cloned()
+    }
+
     /// Verify the CLI server's protocol version is within the supported range.
     ///
     /// Called automatically by [`start`](Self::start). Call manually after
@@ -3065,6 +3142,7 @@ mod tests {
         let (client_write, _server_read) = tokio::io::duplex(8192);
         let (_server_write, client_read) = tokio::io::duplex(8192);
         let client = Client::from_streams(client_read, client_write, std::env::temp_dir()).unwrap();
+        assert!(client.startup_timings().is_none());
         let session_id = SessionId::new("resume-cancel-test");
         let handle = tokio::spawn({
             let client = client.clone();
@@ -3112,6 +3190,7 @@ mod tests {
                 on_get_trace_context: None,
                 effective_connection_token: None,
                 mode: ClientMode::default(),
+                startup_timings: OnceLock::new(),
             }),
         }
     }

rust/src/startup_timings.rs

@@ -0,0 +1,105 @@
+//! Per-phase timing breakdown for [`Client::start`](crate::Client::start).
+//!
+//! `Client::start` performs several sequential phases between "spawn the CLI"
+//! and "client is ready to create sessions": resolving (and possibly
+//! extracting) the CLI binary, spawning the subprocess, waiting for the TCP
+//! port announcement, the `connect` protocol handshake, and the optional
+//! `sessionFs.setProvider` / `llmInference.setProvider` registration RPCs.
+//!
+//! Each phase is already measured internally with an [`Instant`] and logged at
+//! `debug`. [`StartupTimings`] aggregates those durations into a single value
+//! so a host can attribute total startup latency ("time to first token"
+//! groundwork) to a specific phase — e.g. separating "process exec cost" from
+//! "handshake/negotiation cost" — instead of reconstructing it from scattered
+//! log lines.
+//!
+//! Retrieve it after start via
+//! [`Client::startup_timings`](crate::Client::startup_timings).
+//!
+//! [`Instant`]: std::time::Instant
+
+use std::time::Duration;
+
+/// Millisecond breakdown of the phases of [`Client::start`](crate::Client::start).
+///
+/// Optional fields represent phases that do not run for every configuration:
+/// `program_resolve_ms` is `None` when the caller supplies an explicit CLI path
+/// (no resolution/extraction), `port_wait_ms` is `Some` only for the TCP
+/// transport, and `session_fs_ms` / `llm_handler_ms` are `Some` only when the
+/// corresponding option is configured. `process_spawn_ms` is `None` for
+/// transports that do not spawn a subprocess (external server, in-process FFI
+/// runtime). `transport_setup_ms`, `handshake_ms`, and `total_ms` are always
+/// populated for a value returned by
+/// [`Client::startup_timings`](crate::Client::startup_timings).
+///
+/// Durations are whole milliseconds, matching the existing `elapsed_ms`
+/// tracing fields.
+#[derive(Debug, Clone, Default, PartialEq, Eq)]
+#[non_exhaustive]
+pub struct StartupTimings {
+    /// Time spent in `resolve::copilot_binary_with_extract_dir` locating (and,
+    /// for a bundled CLI, extracting) the copilot binary. `None` when the
+    /// caller passes an explicit [`CliProgram::Path`](crate::CliProgram::Path).
+    pub program_resolve_ms: Option<u64>,
+    /// Time spent spawning the CLI subprocess (`command.spawn()`). `None` for
+    /// the external-server and in-process transports, which do not spawn a
+    /// child.
+    pub process_spawn_ms: Option<u64>,
+    /// Time spent waiting for the TCP server to announce its listening port on
+    /// stdout. `Some` only for the TCP transport.
+    pub port_wait_ms: Option<u64>,
+    /// 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,
+    /// Time spent on the `connect` protocol handshake in
+    /// [`Client::verify_protocol_version`](crate::Client::verify_protocol_version),
+    /// including the fallback to the legacy `ping` RPC.
+    pub handshake_ms: u64,
+    /// Time spent registering the filesystem provider via
+    /// `sessionFs.setProvider`. `Some` only when
+    /// [`ClientOptions::session_fs`](crate::ClientOptions::session_fs) is set.
+    pub session_fs_ms: Option<u64>,
+    /// Time spent registering the LLM inference provider via
+    /// `llmInference.setProvider`. `Some` only when
+    /// [`ClientOptions::request_handler`](crate::ClientOptions::request_handler)
+    /// is set.
+    pub llm_handler_ms: Option<u64>,
+    /// Total wall-clock time for [`Client::start`](crate::Client::start), from
+    /// entry to the client being ready. Always present.
+    pub total_ms: u64,
+}
+
+impl StartupTimings {
+    /// Whole milliseconds of `duration`, saturating at [`u64::MAX`].
+    pub(crate) fn millis(duration: Duration) -> u64 {
+        u64::try_from(duration.as_millis()).unwrap_or(u64::MAX)
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn millis_truncates_to_whole_milliseconds() {
+        assert_eq!(StartupTimings::millis(Duration::from_micros(1_999)), 1);
+        assert_eq!(StartupTimings::millis(Duration::from_millis(250)), 250);
+        assert_eq!(StartupTimings::millis(Duration::ZERO), 0);
+    }
+
+    #[test]
+    fn default_leaves_every_phase_unset() {
+        let timings = StartupTimings::default();
+        assert_eq!(timings, StartupTimings::default());
+        assert!(timings.program_resolve_ms.is_none());
+        assert!(timings.process_spawn_ms.is_none());
+        assert!(timings.port_wait_ms.is_none());
+        assert_eq!(timings.transport_setup_ms, 0);
+        assert_eq!(timings.handshake_ms, 0);
+        assert!(timings.session_fs_ms.is_none());
+        assert!(timings.llm_handler_ms.is_none());
+        assert_eq!(timings.total_ms, 0);
+    }
+}