From ef20f44616cb441b4a66f361ebae8f1c9d7961c6 Mon Sep 17 00:00:00 2001 From: jmoseley Date: Thu, 23 Jul 2026 12:42:00 -0700 Subject: [PATCH 1/3] 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 --- rust/src/lib.rs | 77 ++++++++++++++++++++++++----- rust/src/startup_timings.rs | 97 +++++++++++++++++++++++++++++++++++++ 2 files changed, 163 insertions(+), 11 deletions(-) create mode 100644 rust/src/startup_timings.rs 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()); + } +} From 2440f107224f2bacaa2166fd43d47b057fed8111 Mon Sep 17 00:00:00 2001 From: Steve Sanderson <1101362+SteveSandersonMS@users.noreply.github.com> Date: Tue, 28 Jul 2026 10:51:13 +0000 Subject: [PATCH 2/3] 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> --- rust/README.md | 14 ++++++++++++++ rust/src/lib.rs | 27 ++++++++++++++++++--------- rust/src/startup_timings.rs | 30 +++++++++++++++++++----------- rust/tests/e2e/client.rs | 21 ++++++++++++++++++++- rust/tests/e2e/inprocess.rs | 6 ++++++ 5 files changed, 77 insertions(+), 21 deletions(-) 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 87659b225..8932768f2 100644 --- a/rust/src/lib.rs +++ b/rust/src/lib.rs @@ -1163,6 +1163,7 @@ impl Client { } }; + let transport_setup_start = Instant::now(); let client = match options.transport { Transport::Default => unreachable!("default transport resolved above"), Transport::External { @@ -1309,13 +1310,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 = Some(StartupTimings::millis(handshake_start.elapsed())); + timings.handshake_ms = StartupTimings::millis(handshake_start.elapsed()); debug!( elapsed_ms = start_time.elapsed().as_millis(), "Client::start protocol verification complete" @@ -1364,18 +1366,24 @@ impl Client { "Client::start Copilot request handler registration complete" ); } - timings.total_ms = Some(StartupTimings::millis(start_time.elapsed())); + timings.total_ms = 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, + program_resolve_ms = timings.program_resolve_ms.unwrap_or_default(), + program_resolve_present = timings.program_resolve_ms.is_some(), + process_spawn_ms = timings.process_spawn_ms.unwrap_or_default(), + process_spawn_present = timings.process_spawn_ms.is_some(), + port_wait_ms = timings.port_wait_ms.unwrap_or_default(), + port_wait_present = timings.port_wait_ms.is_some(), + transport_setup_ms = timings.transport_setup_ms, + handshake_ms = timings.handshake_ms, + session_fs_ms = timings.session_fs_ms.unwrap_or_default(), + session_fs_present = timings.session_fs_ms.is_some(), + llm_handler_ms = timings.llm_handler_ms.unwrap_or_default(), + llm_handler_present = timings.llm_handler_ms.is_some(), + total_ms = timings.total_ms, "Client::start timings" ); let _ = client.inner.startup_timings.set(timings); @@ -3119,6 +3127,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(); diff --git a/rust/src/startup_timings.rs b/rust/src/startup_timings.rs index 1a35e5a2d..7938a462b 100644 --- a/rust/src/startup_timings.rs +++ b/rust/src/startup_timings.rs @@ -22,13 +22,15 @@ 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). +/// 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. @@ -46,10 +48,15 @@ pub struct StartupTimings { /// 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: Option, + 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. @@ -61,7 +68,7 @@ pub struct StartupTimings { 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, + pub total_ms: u64, } impl StartupTimings { @@ -89,9 +96,10 @@ mod tests { 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_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!(timings.total_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")) From 33f6be39b62547df04cf8197dffb5ec5175ef643 Mon Sep 17 00:00:00 2001 From: Steve Sanderson <1101362+SteveSandersonMS@users.noreply.github.com> Date: Tue, 28 Jul 2026 10:57:06 +0000 Subject: [PATCH 3/3] 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> --- rust/src/lib.rs | 45 ++++++++++++++++++++++++++++++--------------- 1 file changed, 30 insertions(+), 15 deletions(-) diff --git a/rust/src/lib.rs b/rust/src/lib.rs index 8932768f2..f998d7225 100644 --- a/rust/src/lib.rs +++ b/rust/src/lib.rs @@ -115,6 +115,17 @@ pub use subscription::{EventSubscription, LifecycleSubscription}; 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] @@ -1367,25 +1378,29 @@ impl Client { ); } timings.total_ms = 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.unwrap_or_default(), - program_resolve_present = timings.program_resolve_ms.is_some(), - process_spawn_ms = timings.process_spawn_ms.unwrap_or_default(), - process_spawn_present = timings.process_spawn_ms.is_some(), - port_wait_ms = timings.port_wait_ms.unwrap_or_default(), - port_wait_present = timings.port_wait_ms.is_some(), + // 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 = timings.session_fs_ms.unwrap_or_default(), - session_fs_present = timings.session_fs_ms.is_some(), - llm_handler_ms = timings.llm_handler_ms.unwrap_or_default(), - llm_handler_present = timings.llm_handler_ms.is_some(), + session_fs_ms = tracing::field::Empty, + llm_handler_ms = tracing::field::Empty, total_ms = timings.total_ms, - "Client::start timings" ); + 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(),