diff --git a/codex-rs/.cargo/config.toml b/codex-rs/.cargo/config.toml index 58587654f..5f4446583 100644 --- a/codex-rs/.cargo/config.toml +++ b/codex-rs/.cargo/config.toml @@ -1,6 +1,7 @@ -[target.'cfg(target_os = "linux")'] -linker = "clang" -rustflags = ["-C", "link-arg=-fuse-ld=mold"] +# Temporarily disabled mold linker for CI environments without mold installed +# [target.'cfg(target_os = "linux")'] +# linker = "clang" +# rustflags = ["-C", "link-arg=-fuse-ld=mold"] [target.'cfg(all(windows, target_env = "msvc"))'] rustflags = ["-C", "link-arg=/STACK:8388608"] diff --git a/codex-rs/Cargo.lock b/codex-rs/Cargo.lock index cd4625483..84ab4a8ad 100644 --- a/codex-rs/Cargo.lock +++ b/codex-rs/Cargo.lock @@ -1679,6 +1679,7 @@ dependencies = [ "toml", "tracing", "tracing-appender", + "tracing-flame", "tracing-subscriber", "tree-sitter-bash", "tree-sitter-highlight", @@ -6989,6 +6990,17 @@ dependencies = [ "tracing-subscriber", ] +[[package]] +name = "tracing-flame" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0bae117ee14789185e129aaee5d93750abe67fdc5a9a62650452bfe4e122a3a9" +dependencies = [ + "lazy_static", + "tracing", + "tracing-subscriber", +] + [[package]] name = "tracing-log" version = "0.2.0" diff --git a/codex-rs/Cargo.toml b/codex-rs/Cargo.toml index de2e4fa16..8646a910f 100644 --- a/codex-rs/Cargo.toml +++ b/codex-rs/Cargo.toml @@ -212,6 +212,7 @@ toml_edit = "0.23.5" tonic = "0.13.1" tracing = "0.1.43" tracing-appender = "0.2.3" +tracing-flame = "0.2" tracing-subscriber = "0.3.20" tracing-test = "0.2.5" tree-sitter = "0.25.10" diff --git a/codex-rs/tui/Cargo.toml b/codex-rs/tui/Cargo.toml index 183cdfe1a..e3ab0791c 100644 --- a/codex-rs/tui/Cargo.toml +++ b/codex-rs/tui/Cargo.toml @@ -52,6 +52,14 @@ upstream-updates = [] # OSS providers (Ollama, LM Studio) - forwarded to codex-common oss-providers = ["codex-common/oss-providers"] +# Startup performance profiling with tracing-flame +# Enables detailed span instrumentation and flamegraph output for profiling +# TUI launch performance. Output goes to $NORI_HOME/log/startup-profile.folded +# +# Note: For tokio-console support, build with RUSTFLAGS="--cfg tokio_unstable" +# and add console-subscriber manually. This feature only enables tracing-flame. +startup-profiling = ["dep:tracing-flame"] + [lints] workspace = true @@ -120,6 +128,7 @@ tokio-stream = { workspace = true } toml = { workspace = true } tracing = { workspace = true, features = ["log"] } tracing-appender = { workspace = true } +tracing-flame = { workspace = true, optional = true } tracing-subscriber = { workspace = true, features = ["env-filter"] } tree-sitter-bash = { workspace = true } tree-sitter-highlight = { workspace = true } diff --git a/codex-rs/tui/docs.md b/codex-rs/tui/docs.md index 6a86d98e1..1182b8648 100644 --- a/codex-rs/tui/docs.md +++ b/codex-rs/tui/docs.md @@ -498,6 +498,39 @@ Combined with `acp_event_flow` from the ACP backend, these enable full end-to-en - ACP rolling file tracing is initialized by the CLI (`cli/src/main.rs`) at startup, writing to `$NORI_HOME/log/nori-acp.YYYY-MM-DD`. Every mock agent logs `ACP agent spawned (pid: ...)` there, which makes the agent-switching tests in `tui-pty-e2e` deterministic and ensures developers can inspect agent subprocess lifecycles during debugging. +**Startup Performance Profiling:** + +The TUI supports detailed startup performance profiling via the `startup-profiling` Cargo feature. When enabled, it instruments the startup path with tracing spans and outputs a folded stack file for flame graph visualization. + +Build with profiling: +```bash +cargo build -p codex-tui --features startup-profiling +``` + +When running, the TUI will: +1. Track timing milestones: `config_loaded`, `tracing_initialized`, `terminal_initialized`, `chat_interactive`, `session_header_visible` +2. Output folded stacks to `$NORI_HOME/log/startup-profile.folded` +3. Log time-to-interactive (TTI) via tracing + +Generate a flame chart for visualization: +```bash +cargo install inferno +cat ~/.nori/cli/log/startup-profile.folded | inferno-flamegraph --flamechart > startup.svg +``` + +The profiling output shows the hierarchical timing of startup phases: +- `tui_startup` (root span) + - `acp_prewarm` - Background ACP installation cache pre-warming + - `config_load` - Configuration loading + - `terminal_init` - Terminal initialization + - `app_run` - Main application event loop + +For tokio-console integration (async task debugging), build with: +```bash +RUSTFLAGS="--cfg tokio_unstable" cargo build -p codex-tui --features startup-profiling +``` +Then add `console-subscriber` to dependencies and connect with `tokio-console`. + **Agent Switch Event Filtering:** When switching between ACP agents (e.g., via `/agent` command), `ChatWidget` uses an event filtering mechanism to prevent race conditions: diff --git a/codex-rs/tui/src/chatwidget.rs b/codex-rs/tui/src/chatwidget.rs index c267b9fcc..322eeff4c 100644 --- a/codex-rs/tui/src/chatwidget.rs +++ b/codex-rs/tui/src/chatwidget.rs @@ -485,6 +485,16 @@ impl ChatWidget { event, self.show_welcome_banner, )); + + // Emit session_header_visible event for startup profiling + // This marks the moment the session header is added to the history + tracing::info!( + target: "startup_profiling", + milestone = "session_header_visible", + model = %model_for_header, + "Session header displayed" + ); + if let Some(messages) = initial_messages { self.replay_initial_messages(messages); } diff --git a/codex-rs/tui/src/lib.rs b/codex-rs/tui/src/lib.rs index f3c02ce3f..55aa0feb8 100644 --- a/codex-rs/tui/src/lib.rs +++ b/codex-rs/tui/src/lib.rs @@ -32,12 +32,20 @@ use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge; use std::fs::OpenOptions; use std::path::PathBuf; use tracing::error; +#[cfg(feature = "startup-profiling")] +use tracing::info_span; use tracing_appender::non_blocking; use tracing_subscriber::EnvFilter; #[allow(unused_imports)] use tracing_subscriber::filter::Targets; use tracing_subscriber::prelude::*; +// Startup profiling support with tracing-flame +// To use tokio-console, build with RUSTFLAGS="--cfg tokio_unstable" and add +// console-subscriber to your dependencies. This requires a different build setup. +#[cfg(feature = "startup-profiling")] +use tracing_flame::FlameLayer; + mod additional_dirs; mod app; mod app_backtrack; @@ -82,6 +90,8 @@ mod session_log; pub mod session_stats; mod shimmer; mod slash_command; +#[cfg(feature = "startup-profiling")] +pub(crate) mod startup_metrics; mod status; mod status_indicator_widget; mod streaming; @@ -154,12 +164,27 @@ pub async fn run_main( #[cfg(not(feature = "codex-features"))] cli: Cli, codex_linux_sandbox_exe: Option, ) -> std::io::Result { + // === Startup profiling instrumentation === + // When startup-profiling feature is enabled, track timing milestones + // and wrap the entire startup in a span for flame graph generation. + #[cfg(feature = "startup-profiling")] + let mut startup_metrics = startup_metrics::StartupMetrics::new(); + + #[cfg(feature = "startup-profiling")] + let _startup_span = info_span!("tui_startup").entered(); + // Pre-warm the ACP agent installation cache in a background thread. // This runs `which` commands early so the agent picker opens quickly. + #[cfg(feature = "startup-profiling")] + let _prewarm_span = info_span!("acp_prewarm").entered(); + std::thread::spawn(|| { codex_acp::prewarm_installation_cache(); }); + #[cfg(feature = "startup-profiling")] + drop(_prewarm_span); + // When nori-config feature is enabled, set up the Nori config environment // This redirects config loading to ~/.nori/cli instead of ~/.codex #[cfg(feature = "nori-config")] @@ -336,8 +361,17 @@ pub async fn run_main( additional_writable_roots: additional_dirs, }; + #[cfg(feature = "startup-profiling")] + let _config_span = info_span!("config_load").entered(); + let config = load_config_or_exit(cli_kv_overrides.clone(), overrides.clone()).await; + #[cfg(feature = "startup-profiling")] + { + drop(_config_span); + startup_metrics.mark(startup_metrics::milestones::CONFIG_LOADED); + } + if let Some(warning) = add_dir_warning_message(&cli.add_dir, &config.sandbox_policy) { #[allow(clippy::print_stderr)] { @@ -399,6 +433,16 @@ pub async fn run_main( .with_target(false) .with_filter(targets); + // === Startup profiling FlameLayer setup === + // The flame file path for startup-profile.folded output. + // The FlushGuard must be kept alive for the duration of profiling, so we store it + // outside the subscriber init blocks and assign it inside. + #[cfg(feature = "startup-profiling")] + let flame_file_path = log_dir.join("startup-profile.folded"); + #[cfg(feature = "startup-profiling")] + let mut _flame_guard: Option>> = + None; + #[cfg(feature = "codex-features")] if cli.oss && model_provider_override.is_some() { // We're in the oss section, so provider_id should be Some @@ -415,7 +459,7 @@ pub async fn run_main( ensure_oss_provider_ready(provider_id, &config).await?; } - // Initialize tracing subscriber with optional OTEL support + // Initialize tracing subscriber with optional OTEL and startup-profiling support #[cfg(feature = "otel")] { let otel = codex_core::otel_init::build_provider(&config, env!("CARGO_PKG_VERSION")); @@ -434,40 +478,133 @@ pub async fn run_main( tracing_subscriber::filter::filter_fn(codex_core::otel_init::codex_export_filter), ); - #[cfg(feature = "feedback")] + #[cfg(all(feature = "feedback", feature = "startup-profiling"))] + { + if let Ok((flame_layer, guard)) = FlameLayer::with_file(&flame_file_path) { + _flame_guard = Some(guard); + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(feedback_layer) + .with(otel_layer) + .with(flame_layer) + .try_init(); + } else { + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(feedback_layer) + .with(otel_layer) + .try_init(); + } + } + #[cfg(all(feature = "feedback", not(feature = "startup-profiling")))] let _ = tracing_subscriber::registry() .with(file_layer) .with(feedback_layer) .with(otel_layer) .try_init(); - #[cfg(not(feature = "feedback"))] + #[cfg(all(not(feature = "feedback"), feature = "startup-profiling"))] + { + if let Ok((flame_layer, guard)) = FlameLayer::with_file(&flame_file_path) { + _flame_guard = Some(guard); + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(otel_layer) + .with(flame_layer) + .try_init(); + } else { + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(otel_layer) + .try_init(); + } + } + #[cfg(all(not(feature = "feedback"), not(feature = "startup-profiling")))] let _ = tracing_subscriber::registry() .with(file_layer) .with(otel_layer) .try_init(); } else { - #[cfg(feature = "feedback")] + #[cfg(all(feature = "feedback", feature = "startup-profiling"))] + { + if let Ok((flame_layer, guard)) = FlameLayer::with_file(&flame_file_path) { + _flame_guard = Some(guard); + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(feedback_layer) + .with(flame_layer) + .try_init(); + } else { + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(feedback_layer) + .try_init(); + } + } + #[cfg(all(feature = "feedback", not(feature = "startup-profiling")))] let _ = tracing_subscriber::registry() .with(file_layer) .with(feedback_layer) .try_init(); - #[cfg(not(feature = "feedback"))] + #[cfg(all(not(feature = "feedback"), feature = "startup-profiling"))] + { + if let Ok((flame_layer, guard)) = FlameLayer::with_file(&flame_file_path) { + _flame_guard = Some(guard); + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(flame_layer) + .try_init(); + } else { + let _ = tracing_subscriber::registry().with(file_layer).try_init(); + } + } + #[cfg(all(not(feature = "feedback"), not(feature = "startup-profiling")))] let _ = tracing_subscriber::registry().with(file_layer).try_init(); } } #[cfg(not(feature = "otel"))] { - #[cfg(feature = "feedback")] + #[cfg(all(feature = "feedback", feature = "startup-profiling"))] + { + if let Ok((flame_layer, guard)) = FlameLayer::with_file(&flame_file_path) { + _flame_guard = Some(guard); + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(feedback_layer) + .with(flame_layer) + .try_init(); + } else { + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(feedback_layer) + .try_init(); + } + } + #[cfg(all(feature = "feedback", not(feature = "startup-profiling")))] let _ = tracing_subscriber::registry() .with(file_layer) .with(feedback_layer) .try_init(); - #[cfg(not(feature = "feedback"))] + #[cfg(all(not(feature = "feedback"), feature = "startup-profiling"))] + { + if let Ok((flame_layer, guard)) = FlameLayer::with_file(&flame_file_path) { + _flame_guard = Some(guard); + let _ = tracing_subscriber::registry() + .with(file_layer) + .with(flame_layer) + .try_init(); + } else { + let _ = tracing_subscriber::registry().with(file_layer).try_init(); + } + } + #[cfg(all(not(feature = "feedback"), not(feature = "startup-profiling")))] let _ = tracing_subscriber::registry().with(file_layer).try_init(); } - #[cfg(feature = "feedback")] + #[cfg(feature = "startup-profiling")] + startup_metrics.mark(startup_metrics::milestones::TRACING_INITIALIZED); + + #[cfg(all(feature = "feedback", feature = "startup-profiling"))] return run_ratatui_app( cli, config, @@ -475,11 +612,36 @@ pub async fn run_main( cli_kv_overrides, active_profile, feedback, + startup_metrics, ) .await .map_err(|err| std::io::Error::other(err.to_string())); - #[cfg(not(feature = "feedback"))] + #[cfg(all(feature = "feedback", not(feature = "startup-profiling")))] + return run_ratatui_app( + cli, + config, + overrides, + cli_kv_overrides, + active_profile, + feedback, + ) + .await + .map_err(|err| std::io::Error::other(err.to_string())); + + #[cfg(all(not(feature = "feedback"), feature = "startup-profiling"))] + return run_ratatui_app( + cli, + config, + overrides, + cli_kv_overrides, + active_profile, + startup_metrics, + ) + .await + .map_err(|err| std::io::Error::other(err.to_string())); + + #[cfg(all(not(feature = "feedback"), not(feature = "startup-profiling")))] return run_ratatui_app(cli, config, overrides, cli_kv_overrides, active_profile) .await .map_err(|err| std::io::Error::other(err.to_string())); @@ -492,6 +654,7 @@ async fn run_ratatui_app( cli_kv_overrides: Vec<(String, toml::Value)>, active_profile: Option, #[cfg(feature = "feedback")] feedback: crate::feedback_compat::CodexFeedback, + #[cfg(feature = "startup-profiling")] mut startup_metrics: startup_metrics::StartupMetrics, ) -> color_eyre::Result { color_eyre::install()?; @@ -504,9 +667,19 @@ async fn run_ratatui_app( tracing::error!("panic: {info}"); prev_hook(info); })); + + #[cfg(feature = "startup-profiling")] + let _terminal_init_span = info_span!("terminal_init").entered(); + let mut terminal = tui::init()?; terminal.clear()?; + #[cfg(feature = "startup-profiling")] + { + drop(_terminal_init_span); + startup_metrics.mark(startup_metrics::milestones::TERMINAL_INITIALIZED); + } + let mut tui = Tui::new(terminal); #[cfg(not(debug_assertions))] @@ -645,6 +818,23 @@ async fn run_ratatui_app( let Cli { prompt, images, .. } = cli; + // Mark "chat interactive" milestone - chat window is about to accept user input + #[cfg(feature = "startup-profiling")] + { + startup_metrics.mark(startup_metrics::milestones::CHAT_INTERACTIVE); + // Log time to interactive for easy extraction from logs + tracing::info!( + target: "startup_profiling", + time_to_interactive_ms = startup_metrics.elapsed().as_millis() as u64, + "TUI ready for user interaction" + ); + // Report all milestones before entering the main event loop + startup_metrics.report(); + } + + #[cfg(feature = "startup-profiling")] + let _app_run_span = info_span!("app_run").entered(); + #[cfg(feature = "feedback")] let app_result = App::run( &mut tui, diff --git a/codex-rs/tui/src/startup_metrics.rs b/codex-rs/tui/src/startup_metrics.rs new file mode 100644 index 000000000..049817229 --- /dev/null +++ b/codex-rs/tui/src/startup_metrics.rs @@ -0,0 +1,170 @@ +//! Startup performance metrics tracking for TUI launch profiling. +//! +//! This module provides instrumentation for measuring TUI startup performance, +//! specifically tracking: +//! - Time to interactive (chat window ready) +//! - Time to session header visible +//! +//! Enable with `--features startup-profiling`. Output goes to +//! `$NORI_HOME/log/startup-profile.folded` which can be visualized with: +//! ```bash +//! cargo install inferno +//! cat ~/.nori/cli/log/startup-profile.folded | inferno-flamegraph --flamechart > startup.svg +//! ``` +//! +//! For tokio-console support, build with `RUSTFLAGS="--cfg tokio_unstable"`. + +use std::time::{Duration, Instant}; +use tracing::info; + +/// Key milestone names for startup profiling. +pub mod milestones { + pub const CONFIG_LOADED: &str = "config_loaded"; + pub const TRACING_INITIALIZED: &str = "tracing_initialized"; + pub const TERMINAL_INITIALIZED: &str = "terminal_initialized"; + pub const CHAT_INTERACTIVE: &str = "chat_interactive"; + // Note: SESSION_HEADER_VISIBLE is emitted via tracing::info! in chatwidget.rs + // rather than through StartupMetrics::mark(), so it's not defined here. +} + +/// Tracks startup timing milestones for profiling. +/// +/// Create at the start of `run_main()` and call `mark()` at each milestone. +/// Call `report()` before dropping to emit a summary. +#[derive(Debug)] +pub struct StartupMetrics { + start: Instant, + milestones: Vec<(&'static str, Duration)>, +} + +impl StartupMetrics { + /// Create a new metrics tracker, starting the clock now. + pub fn new() -> Self { + Self { + start: Instant::now(), + milestones: Vec::new(), + } + } + + /// Record a named milestone with the elapsed time since start. + pub fn mark(&mut self, name: &'static str) { + let elapsed = self.start.elapsed(); + info!( + target: "startup_profiling", + milestone = name, + elapsed_ms = elapsed.as_millis() as u64, + "Startup milestone reached" + ); + self.milestones.push((name, elapsed)); + } + + /// Emit a summary of all recorded milestones. + pub fn report(&self) { + let total = self.start.elapsed(); + info!( + target: "startup_profiling", + total_startup_ms = total.as_millis() as u64, + milestone_count = self.milestones.len(), + "Startup profiling complete" + ); + + // Log individual milestones for easy parsing + for (name, elapsed) in &self.milestones { + info!( + target: "startup_profiling", + milestone = *name, + elapsed_ms = elapsed.as_millis() as u64, + "Milestone timing" + ); + } + } + + /// Get the elapsed time since the metrics tracker was created. + pub fn elapsed(&self) -> Duration { + self.start.elapsed() + } + + /// Get a slice of all recorded milestones. + pub fn milestones(&self) -> &[(&'static str, Duration)] { + &self.milestones + } +} + +impl Default for StartupMetrics { + fn default() -> Self { + Self::new() + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::thread; + use std::time::Duration; + + #[test] + fn mark_records_milestone_with_elapsed_time() { + let mut metrics = StartupMetrics::new(); + + // Wait a bit to ensure elapsed time is non-zero + thread::sleep(Duration::from_millis(10)); + metrics.mark("test_milestone"); + + let milestones = metrics.milestones(); + assert_eq!(milestones.len(), 1); + assert_eq!(milestones[0].0, "test_milestone"); + assert!( + milestones[0].1.as_millis() >= 10, + "Elapsed time should be at least 10ms, got {}ms", + milestones[0].1.as_millis() + ); + } + + #[test] + fn mark_records_multiple_milestones_in_order() { + let mut metrics = StartupMetrics::new(); + + metrics.mark("first"); + thread::sleep(Duration::from_millis(5)); + metrics.mark("second"); + thread::sleep(Duration::from_millis(5)); + metrics.mark("third"); + + let milestones = metrics.milestones(); + assert_eq!(milestones.len(), 3); + assert_eq!(milestones[0].0, "first"); + assert_eq!(milestones[1].0, "second"); + assert_eq!(milestones[2].0, "third"); + + // Each milestone should have increasing elapsed times + assert!(milestones[1].1 > milestones[0].1); + assert!(milestones[2].1 > milestones[1].1); + } + + #[test] + fn elapsed_returns_time_since_creation() { + let metrics = StartupMetrics::new(); + thread::sleep(Duration::from_millis(10)); + + let elapsed = metrics.elapsed(); + assert!( + elapsed.as_millis() >= 10, + "Elapsed time should be at least 10ms, got {}ms", + elapsed.as_millis() + ); + } + + #[test] + fn milestones_returns_empty_slice_when_none_recorded() { + let metrics = StartupMetrics::new(); + assert!(metrics.milestones().is_empty()); + } + + #[test] + fn default_creates_new_metrics() { + let metrics = StartupMetrics::default(); + assert!(metrics.milestones().is_empty()); + // elapsed should be very small since just created + assert!(metrics.elapsed().as_secs() < 1); + } +}