diff --git a/rust/src/lib.rs b/rust/src/lib.rs index 65d9dab21..87659b225 100644 --- a/rust/src/lib.rs +++ b/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, } impl Client { @@ -1024,6 +1031,7 @@ impl Client { /// backend. pub async fn start(options: ClientOptions) -> Result { 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 { + ) -> 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,11 +1737,12 @@ 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( @@ -1708,7 +1750,7 @@ impl Client { 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 { + 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(), }), } } diff --git a/rust/src/startup_timings.rs b/rust/src/startup_timings.rs new file mode 100644 index 000000000..1a35e5a2d --- /dev/null +++ b/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` 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, + /// 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, + /// 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, + /// 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, + /// 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, + /// 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, + /// Total wall-clock time for [`Client::start`](crate::Client::start), from + /// entry to the client being ready. Always present. + pub total_ms: Option, +} + +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()); + } +}