From 8f5d6b83fb09aec45225b84949f202183d2cef5b Mon Sep 17 00:00:00 2001 From: vikingowl Date: Mon, 1 Jun 2026 16:55:38 +0200 Subject: [PATCH] chore(ui): add startup + search latency timing under RUST_LOG=debug MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Phase deltas across activation (boot → activate → present → first paint) in app.rs, and per-query dispatch→IPC→paint timing in the keystroke search path, to localise launcher latency in the field. Gated behind debug log level via `log::debug!`; no cost in normal runs. --- crates/owlry/src/app.rs | 40 ++++++++++++++++++++++++++++++ crates/owlry/src/main.rs | 4 +++ crates/owlry/src/ui/main_window.rs | 28 +++++++++++++++++++++ 3 files changed, 72 insertions(+) diff --git a/crates/owlry/src/app.rs b/crates/owlry/src/app.rs index b6e6958..e209e80 100644 --- a/crates/owlry/src/app.rs +++ b/crates/owlry/src/app.rs @@ -18,6 +18,11 @@ use std::rc::Rc; const APP_ID: &str = "org.owlry.launcher"; +/// Process-start timestamp, set once at the top of `main()`. Lets `on_activate` +/// measure the pre-activate gap (GApplication/GTK/Wayland/D-Bus init) that the +/// `t0`-relative deltas below cannot see. Enable with RUST_LOG=debug. +pub static BOOT: std::sync::OnceLock = std::sync::OnceLock::new(); + pub struct OwlryApp { app: Application, } @@ -43,11 +48,24 @@ impl OwlryApp { fn on_activate(app: &Application, args: &CliArgs) { debug!("Activating Owlry"); + // Startup phase timing. Enable with RUST_LOG=debug to confirm where + // per-open latency goes (GTK build vs. layer-shell vs. present vs. the + // initial daemon query). Deltas are cumulative from activate(). + let t0 = std::time::Instant::now(); + if let Some(boot) = BOOT.get() { + debug!( + "startup: activate reached +{:.1?} after process boot (GTK/display/D-Bus init)", + boot.elapsed() + ); + } + // Register bundled icon resources gio::resources_register_include!("icons.gresource") .expect("Failed to register icon resources"); + debug!("startup: gresource registered +{:.1?}", t0.elapsed()); let config = Rc::new(RefCell::new(Config::load_or_default())); + debug!("startup: config loaded +{:.1?}", t0.elapsed()); // Build backend based on mode let dmenu_mode = DmenuProvider::has_stdin_data(); @@ -81,6 +99,8 @@ impl OwlryApp { } }; + debug!("startup: backend ready +{:.1?}", t0.elapsed()); + let backend = Rc::new(RefCell::new(backend)); // Create filter from CLI args, profile, and config @@ -107,6 +127,7 @@ impl OwlryApp { ProviderFilter::new(None, None, &config.borrow().providers, &tabs) }; let filter = Rc::new(RefCell::new(filter)); + debug!("startup: filter built +{:.1?}", t0.elapsed()); let window = MainWindow::new( app, @@ -115,6 +136,7 @@ impl OwlryApp { filter.clone(), args.prompt.clone(), ); + debug!("startup: MainWindow built +{:.1?}", t0.elapsed()); // Set up layer shell for Wayland overlay behavior window.init_layer_shell(); @@ -130,17 +152,35 @@ impl OwlryApp { // Position from top window.set_margin(Edge::Top, 200); + debug!("startup: layer-shell configured +{:.1?}", t0.elapsed()); // Set up icon theme fallbacks Self::setup_icon_theme(); + debug!("startup: icon theme set +{:.1?}", t0.elapsed()); // Load CSS styling with config for theming Self::load_css(&config.borrow()); + debug!("startup: CSS loaded +{:.1?}", t0.elapsed()); + + // Fires when the surface is actually mapped by the compositor — the + // closest signal to "the user sees the window". Captures first-frame / + // GPU cost that happens after present() returns. + { + let t0_map = t0; + window.connect_map(move |_| { + debug!( + "startup: window mapped (first paint) +{:.1?}", + t0_map.elapsed() + ); + }); + } window.present(); + debug!("startup: present() returned +{:.1?}", t0.elapsed()); // Populate results AFTER present() so the window appears immediately window.schedule_initial_results(); + debug!("startup: scheduled initial results +{:.1?}", t0.elapsed()); } /// Create a local backend as fallback when daemon is unavailable. diff --git a/crates/owlry/src/main.rs b/crates/owlry/src/main.rs index b03ffa9..8964691 100644 --- a/crates/owlry/src/main.rs +++ b/crates/owlry/src/main.rs @@ -37,6 +37,10 @@ fn try_acquire_lock() -> Option { } fn main() { + // Capture process-start as early as possible so the UI can measure the + // pre-activate GTK/display/D-Bus init cost (see app::on_activate timing). + let _ = owlry::app::BOOT.set(std::time::Instant::now()); + let args = CliArgs::parse_args(); // Subcommand dispatch. Each commands::* function calls std::process::exit diff --git a/crates/owlry/src/ui/main_window.rs b/crates/owlry/src/ui/main_window.rs index 8fb473c..6c607aa 100644 --- a/crates/owlry/src/ui/main_window.rs +++ b/crates/owlry/src/ui/main_window.rs @@ -620,6 +620,11 @@ impl MainWindow { // Clear the source ID since we're now executing *debounce_source_for_closure.borrow_mut() = None; + // Search latency timing (keystroke path). The 50ms debounce + // precedes this closure; `dispatch_t` measures from query + // dispatch through IPC return to painted rows. + let dispatch_t = std::time::Instant::now(); + let cfg = config.borrow(); let max_results = cfg.general.max_results; drop(cfg); @@ -643,11 +648,17 @@ impl MainWindow { gtk4::glib::spawn_future_local(async move { if let Ok(result) = rx.await { + log::debug!( + "search: dispatch→IPC return +{:.1?} ({} items)", + dispatch_t.elapsed(), + result.items.len() + ); // Discard stale results: the user has typed something new // since this query was dispatched. if search_entry_for_stale.text().as_str() != raw_text_at_dispatch { return; } + let paint_t = std::time::Instant::now(); results_list_cb.remove_all(); let items = result.items; @@ -667,6 +678,12 @@ impl MainWindow { lazy.all_results = items; lazy.displayed_count = initial_count; lazy.query = query_for_highlight; + log::debug!( + "search: paint {} rows +{:.1?} | total dispatch→paint +{:.1?}", + initial_count, + paint_t.elapsed(), + dispatch_t.elapsed() + ); } }); } else { @@ -1192,15 +1209,26 @@ impl MainWindow { let current_results = self.current_results.clone(); let lazy_state = self.lazy_state.clone(); + let scheduled_at = std::time::Instant::now(); gtk4::glib::idle_add_local_once(move || { + log::debug!( + "startup: initial-results idle fired +{:.1?} after schedule", + scheduled_at.elapsed() + ); let cfg = config.borrow(); let max_results = cfg.general.max_results; drop(cfg); + let query_start = std::time::Instant::now(); let results = backend .borrow_mut() .search("", max_results, &filter.borrow(), &config.borrow()); + log::debug!( + "startup: initial daemon query returned {} items in {:.1?}", + results.len(), + query_start.elapsed() + ); // Clear existing results results_list.remove_all();