diff --git a/rust/README.md b/rust/README.md index 254a2b216..e89ea5560 100644 --- a/rust/README.md +++ b/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 | diff --git a/rust/src/lib.rs b/rust/src/lib.rs index 65d9dab21..f998d7225 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,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) { + 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, } impl Client { @@ -1024,6 +1042,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 +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 { + ) -> 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 +1760,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 +1773,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 +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 { + 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(), }), } } diff --git a/rust/src/startup_timings.rs b/rust/src/startup_timings.rs new file mode 100644 index 000000000..7938a462b --- /dev/null +++ b/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, + /// 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, + /// 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, + /// 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: 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); + } +} diff --git a/rust/tests/e2e/client.rs b/rust/tests/e2e/client.rs index 6dd0f27ac..0ac4c9d45 100644 --- a/rust/tests/e2e/client.rs +++ b/rust/tests/e2e/client.rs @@ -6,13 +6,25 @@ use github_copilot_sdk::{ CliProgram, Client, ClientOptions, Error, ListModelsHandler, Model, Transport, }; -use super::support::with_e2e_context; +use super::support::{is_inprocess_default, with_e2e_context}; #[tokio::test] async fn should_start_ping_and_stop_stdio_client() { with_e2e_context("client", "should_start_ping_and_stop_stdio_client", |ctx| { Box::pin(async move { let client = ctx.start_client().await; + let timings = client.startup_timings().expect("startup timings"); + if is_inprocess_default() { + assert!(timings.program_resolve_ms.is_some()); + assert!(timings.process_spawn_ms.is_none()); + } else { + assert!(timings.program_resolve_ms.is_none()); + assert!(timings.process_spawn_ms.is_some()); + } + assert!(timings.port_wait_ms.is_none()); + assert!(timings.total_ms >= timings.transport_setup_ms); + assert!(timings.total_ms >= timings.handshake_ms); + let response = client.ping(Some("hello from rust")).await.expect("ping"); assert_eq!(response.message, "pong: hello from rust"); assert!(!response.timestamp.is_empty()); @@ -33,6 +45,13 @@ async fn should_start_ping_and_stop_tcp_client() { })) .await .expect("start TCP client"); + let timings = client.startup_timings().expect("startup timings"); + assert_eq!(timings.program_resolve_ms.is_some(), is_inprocess_default()); + assert!(timings.process_spawn_ms.is_some()); + assert!(timings.port_wait_ms.is_some()); + assert!(timings.total_ms >= timings.transport_setup_ms); + assert!(timings.total_ms >= timings.handshake_ms); + let response = client.ping(Some("tcp hello")).await.expect("ping"); assert_eq!(response.message, "pong: tcp hello"); diff --git a/rust/tests/e2e/inprocess.rs b/rust/tests/e2e/inprocess.rs index 0c183a27d..ead05a0b5 100644 --- a/rust/tests/e2e/inprocess.rs +++ b/rust/tests/e2e/inprocess.rs @@ -7,6 +7,12 @@ async fn should_start_ping_and_stop_inprocess_client() { with_e2e_context("client", "should_start_ping_and_stop_stdio_client", |ctx| { Box::pin(async move { let client = ctx.start_inprocess_client().await; + let timings = client.startup_timings().expect("startup timings"); + assert!(timings.program_resolve_ms.is_some()); + assert!(timings.process_spawn_ms.is_none()); + assert!(timings.port_wait_ms.is_none()); + assert!(timings.total_ms >= timings.transport_setup_ms); + assert!(timings.total_ms >= timings.handshake_ms); let response = client .ping(Some("hello from rust in-process"))