chore(ui): add startup + search latency timing under RUST_LOG=debug

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

@@ -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::time::Instant> = 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.

crates/owlry/src/main.rs

@@ -37,6 +37,10 @@ fn try_acquire_lock() -> Option<std::fs::File> {
 }
 
 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

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();