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

Author: jmoseley

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,6 +108,7 @@ 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.
@@ -1007,6 +1010,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 +1031,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 +1127,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)]
                 {
@@ -1183,8 +1198,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 +1226,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);
@@ -1294,7 +1313,9 @@ impl Client {
             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 = Some(StartupTimings::millis(handshake_start.elapsed()));
         debug!(
             elapsed_ms = start_time.elapsed().as_millis(),
             "Client::start protocol verification complete"
@@ -1313,8 +1334,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 +1357,28 @@ 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 = Some(StartupTimings::millis(start_time.elapsed()));
+        // Single structured event with the full per-phase breakdown, so hosts
+        // can attribute startup latency to a phase without stitching together
+        // the individual debug lines above.
+        debug!(
+            program_resolve_ms = ?timings.program_resolve_ms,
+            process_spawn_ms = ?timings.process_spawn_ms,
+            port_wait_ms = ?timings.port_wait_ms,
+            handshake_ms = ?timings.handshake_ms,
+            session_fs_ms = ?timings.session_fs_ms,
+            llm_handler_ms = ?timings.llm_handler_ms,
+            total_ms = ?timings.total_ms,
+            "Client::start timings"
+        );
+        let _ = client.inner.startup_timings.set(timings);
         debug!(
             elapsed_ms = start_time.elapsed().as_millis(),
             "Client::start complete"
@@ -1507,6 +1547,7 @@ impl Client {
                 on_get_trace_context,
                 effective_connection_token,
                 mode,
+                startup_timings: OnceLock::new(),
             }),
         };
         client.spawn_lifecycle_dispatcher();
@@ -1683,7 +1724,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 +1737,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 +1763,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 +1802,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 +1986,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
@@ -3112,6 +3166,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,97 @@
+//! 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).
+///
+/// Every field is `Option<u64>` because a phase is only timed when it actually
+/// runs: `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).
+///
+/// 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>,
+    /// 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: Option<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: Option<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!(timings.handshake_ms.is_none());
+        assert!(timings.session_fs_ms.is_none());
+        assert!(timings.llm_handler_ms.is_none());
+        assert!(timings.total_ms.is_none());
+    }
+}