refactor(observability): unify timing instrumentation across runtimes

src/apps/desktop/src/api/tool_api.rs

@@ -10,6 +10,7 @@ use bitfun_core::agentic::{
     tools::{get_all_tools, get_readonly_tools},
     WorkspaceBinding,
 };
+use bitfun_core::util::elapsed_ms_u64;
 
 #[derive(Debug, Clone, Serialize, Deserialize)]
 #[serde(rename_all = "camelCase")]
@@ -268,7 +269,7 @@ pub async fn execute_tool(request: ToolExecutionRequest) -> Result<ToolExecution
                     result: None,
                     error: None,
                     validation_error: validation_result.message,
-                    duration_ms: start_time.elapsed().as_millis() as u64,
+                    duration_ms: elapsed_ms_u64(start_time),
                 });
             }
 
@@ -307,7 +308,7 @@ pub async fn execute_tool(request: ToolExecutionRequest) -> Result<ToolExecution
                         result: combined_result,
                         error: None,
                         validation_error: None,
-                        duration_ms: start_time.elapsed().as_millis() as u64,
+                        duration_ms: elapsed_ms_u64(start_time),
                     });
                 }
                 Err(e) => {
@@ -317,7 +318,7 @@ pub async fn execute_tool(request: ToolExecutionRequest) -> Result<ToolExecution
                         result: None,
                         error: Some(format!("Tool execution failed: {}", e)),
                         validation_error: None,
-                        duration_ms: start_time.elapsed().as_millis() as u64,
+                        duration_ms: elapsed_ms_u64(start_time),
                     });
                 }
             }

src/apps/desktop/src/lib.rs

@@ -12,12 +12,14 @@ use bitfun_core::agentic::tools::computer_use_host::ComputerUseHostRef;
 use bitfun_core::infrastructure::ai::AIClientFactory;
 use bitfun_core::infrastructure::{get_path_manager_arc, try_get_path_manager_arc};
 use bitfun_core::service::workspace::get_global_workspace_service;
+use bitfun_core::util::{elapsed_ms, TimingCollector};
 use bitfun_transport::{TauriTransportAdapter, TransportAdapter};
 use serde::Deserialize;
 use std::sync::{
     atomic::{AtomicBool, Ordering},
     Arc,
 };
+use std::time::Instant;
 #[cfg(target_os = "macos")]
 use tauri::Emitter;
 use tauri::Manager;
@@ -75,22 +77,27 @@ async fn webdriver_bridge_result(request: WebdriverBridgeResultRequest) -> Resul
 /// Tauri application entry point
 #[cfg_attr(mobile, tauri::mobile_entry_point)]
 pub async fn run() {
+    let startup_started = Instant::now();
+    let mut startup_timings = TimingCollector::default();
     let in_debug = cfg!(debug_assertions) || std::env::var("DEBUG").unwrap_or_default() == "1";
     let log_config = logging::LogConfig::new(in_debug);
     let log_targets = logging::build_log_targets(&log_config);
     let session_log_dir = log_config.session_log_dir.clone();
 
     eprintln!("=== BitFun Desktop Starting ===");
 
+    let step_started = Instant::now();
     if let Err(e) = bitfun_core::service::config::initialize_global_config().await {
         log::error!("Failed to initialize global config service: {}", e);
         return;
     }
+    startup_timings.record_elapsed("initialize_global_config", step_started);
 
     // Initialize global I18nService so bot/remote-connect language is always in sync.
     {
         use bitfun_core::service::config::get_global_config_service;
         use bitfun_core::service::i18n::initialize_global_i18n_service;
+        let step_started = Instant::now();
         match get_global_config_service().await {
             Ok(config_service) => {
                 if let Err(e) = initialize_global_i18n_service(Some(config_service)).await {
@@ -101,15 +108,19 @@ pub async fn run() {
                 log::error!("Failed to get config service for I18nService init: {}", e);
             }
         }
+        startup_timings.record_elapsed("initialize_global_i18n_service", step_started);
     }
 
     let startup_log_level = resolve_runtime_log_level(log_config.level).await;
 
+    let step_started = Instant::now();
     if let Err(e) = AIClientFactory::initialize_global().await {
         log::error!("Failed to initialize global AIClientFactory: {}", e);
         return;
     }
+    startup_timings.record_elapsed("initialize_global_ai_client_factory", step_started);
 
+    let step_started = Instant::now();
     let (coordinator, scheduler, event_queue, event_router, ai_client_factory, token_usage_service) =
         match init_agentic_system().await {
             Ok(state) => state,
@@ -118,19 +129,24 @@ pub async fn run() {
                 return;
             }
         };
+    startup_timings.record_elapsed("init_agentic_system", step_started);
 
+    let step_started = Instant::now();
     if let Err(e) = init_function_agents(ai_client_factory.clone()).await {
         log::error!("Failed to initialize function agents: {}", e);
         return;
     }
+    startup_timings.record_elapsed("init_function_agents", step_started);
 
+    let step_started = Instant::now();
     let app_state = match AppState::new_async(token_usage_service).await {
         Ok(state) => state,
         Err(e) => {
             log::error!("Failed to initialize AppState: {}", e);
             return;
         }
     };
+    startup_timings.record_elapsed("initialize_app_state", step_started);
 
     let coordinator_state = CoordinatorState {
         coordinator: coordinator.clone(),
@@ -165,6 +181,7 @@ pub async fn run() {
         .manage(scheduler)
         .manage(terminal_state)
         .setup(move |app| {
+            let setup_started = Instant::now();
             #[cfg(target_os = "macos")]
             {
                 app.on_menu_event(|app, event| {
@@ -178,6 +195,13 @@ pub async fn run() {
             }
 
             logging::register_runtime_log_state(startup_log_level, session_log_dir.clone());
+            for step in startup_timings.steps() {
+                log::debug!(
+                    "Desktop startup step completed: step={}, duration_ms={}",
+                    step.name,
+                    step.duration_ms
+                );
+            }
 
             // Register bundled mobile-web resource path for remote connect.
             // tauri.conf.json maps "../../mobile-web/dist" -> "mobile-web/dist",
@@ -222,8 +246,18 @@ pub async fn run() {
             }
 
             let app_handle = app.handle().clone();
+            let window_started = Instant::now();
             theme::create_main_window(&app_handle);
+            log::debug!(
+                "Desktop startup step completed: step=create_main_window, duration_ms={}",
+                elapsed_ms(window_started)
+            );
             bitfun_webdriver::maybe_start(app_handle.clone());
+            log::debug!(
+                "Desktop startup timing: phase=tauri_setup, duration_ms={}, since_process_start_ms={}",
+                elapsed_ms(setup_started),
+                elapsed_ms(startup_started)
+            );
 
             #[cfg(target_os = "macos")]
             {

src/crates/LOGGING.md

@@ -29,3 +29,23 @@
 8. Use appropriate log levels - reserve ERROR for actual failures, not expected error conditions
 9. Keep log messages concise and actionable - focus on what happened and why it matters
 10. Use conditional logging for expensive operations: `if log::log_enabled!(log::Level::Debug) { ... }`
+
+## Timing And Duration Fields
+
+Use shared timing helpers from `bitfun_core::util::timing` when recording internal durations.
+
+```rust
+use bitfun_core::util::{elapsed_ms_u64, TimingCollector};
+use std::time::Instant;
+
+let started_at = Instant::now();
+let duration_ms = elapsed_ms_u64(started_at);
+debug!("Git status completed: repo_path={}, duration_ms={}", repo_path, duration_ms);
+```
+
+Rules:
+
+1. Prefer `elapsed_ms`, `elapsed_ms_u64`, and `TimingCollector` over repeated `Instant::now()` plus `elapsed().as_millis()` formatting
+2. Use `duration_ms` for Rust diagnostic log keys
+3. Preserve existing protocol and model field names such as `duration_ms`, `execution_time_ms`, or `response_time_ms` when they are part of events, API responses, or persisted state
+4. Avoid introducing timing logs into tight loops or high-frequency runtime paths unless the diagnostic value clearly justifies it

src/crates/ai-adapters/src/client/healthcheck.rs

@@ -1,3 +1,4 @@
+use crate::client::utils::elapsed_ms_u64;
 use crate::client::AIClient;
 use crate::types::{ConnectionTestMessageCode, ConnectionTestResult, Message, ToolDefinition};
 use anyhow::Result;
@@ -78,7 +79,7 @@ pub(crate) async fn test_connection(client: &AIClient) -> Result<ConnectionTestR
 
     match client.send_message(test_messages, tools).await {
         Ok(response) => {
-            let response_time_ms = start_time.elapsed().as_millis() as u64;
+            let response_time_ms = elapsed_ms_u64(start_time);
             if response.tool_calls.is_some() {
                 Ok(ConnectionTestResult {
                     success: true,
@@ -98,7 +99,7 @@ pub(crate) async fn test_connection(client: &AIClient) -> Result<ConnectionTestR
             }
         }
         Err(e) => {
-            let response_time_ms = start_time.elapsed().as_millis() as u64;
+            let response_time_ms = elapsed_ms_u64(start_time);
             let error_msg = format!("{}", e);
             debug!("test connection failed: {}", error_msg);
             Ok(ConnectionTestResult {
@@ -164,7 +165,7 @@ pub(crate) async fn test_image_input_connection(client: &AIClient) -> Result<Con
             if image_test_response_matches_expected(&response.text) {
                 Ok(ConnectionTestResult {
                     success: true,
-                    response_time_ms: start_time.elapsed().as_millis() as u64,
+                    response_time_ms: elapsed_ms_u64(start_time),
                     model_response: Some(response.text),
                     message_code: None,
                     error_details: None,
@@ -178,7 +179,7 @@ pub(crate) async fn test_image_input_connection(client: &AIClient) -> Result<Con
                 debug!("test image input connection failed: {}", detail);
                 Ok(ConnectionTestResult {
                     success: false,
-                    response_time_ms: start_time.elapsed().as_millis() as u64,
+                    response_time_ms: elapsed_ms_u64(start_time),
                     model_response: Some(response.text),
                     message_code: Some(ConnectionTestMessageCode::ImageInputCheckFailed),
                     error_details: Some(detail),
@@ -190,7 +191,7 @@ pub(crate) async fn test_image_input_connection(client: &AIClient) -> Result<Con
             debug!("test image input connection failed: {}", error_msg);
             Ok(ConnectionTestResult {
                 success: false,
-                response_time_ms: start_time.elapsed().as_millis() as u64,
+                response_time_ms: elapsed_ms_u64(start_time),
                 model_response: None,
                 message_code: None,
                 error_details: Some(error_msg),

src/crates/ai-adapters/src/client/sse.rs

@@ -1,3 +1,4 @@
+use crate::client::utils::elapsed_ms_u64;
 use crate::client::StreamResponse;
 use crate::stream::UnifiedResponse;
 use anyhow::{anyhow, Result};
@@ -29,7 +30,7 @@ where
 
         let response = match response_result {
             Ok(resp) => {
-                let connect_time = request_start_time.elapsed().as_millis();
+                let connect_time = elapsed_ms_u64(request_start_time);
                 let status = resp.status();
 
                 if status.is_client_error() {

src/crates/ai-adapters/src/client/utils.rs

@@ -1,4 +1,5 @@
 use crate::types::{AIConfig, RemoteModelInfo};
+use std::time::Instant;
 
 pub(crate) fn merge_json_value(target: &mut serde_json::Value, overlay: serde_json::Value) {
     match (target, overlay) {
@@ -80,3 +81,7 @@ pub(crate) fn normalize_base_url_for_discovery(base_url: &str) -> String {
         .trim_end_matches('/')
         .to_string()
 }
+
+pub(crate) fn elapsed_ms_u64(started_at: Instant) -> u64 {
+    started_at.elapsed().as_millis() as u64
+}

src/crates/core/src/agentic/execution/execution_engine.rs

@@ -24,6 +24,7 @@ use crate::infrastructure::ai::get_global_ai_client_factory;
 use crate::service::config::get_global_config_service;
 use crate::service::config::types::{ModelCapability, ModelCategory};
 use crate::service::remote_ssh::workspace_state::get_remote_workspace_manager;
+use crate::util::elapsed_ms_u64;
 use crate::util::errors::{BitFunError, BitFunResult};
 use crate::util::token_counter::TokenCounter;
 use crate::util::types::Message as AIMessage;
@@ -719,27 +720,38 @@ impl ExecutionEngine {
                 // Update session compression state
                 session.compression_state.increment_compression_count();
 
-                info!(
-                    "Compression completed: messages {} -> {}, compression_count={}",
-                    old_messages_len,
-                    new_messages.len(),
-                    session.compression_state.compression_count
-                );
-
                 // Update session state
                 let _ = self
                     .session_manager
                     .update_compression_state(session_id, session.compression_state.clone())
                     .await;
 
                 // Calculate duration
-                let duration_ms = start_time.elapsed().as_millis() as u64;
+                let duration_ms = elapsed_ms_u64(start_time);
 
                 // Recalculate tokens after compression
                 let compressed_tokens = Self::estimate_request_tokens_internal(
                     &mut new_messages,
                     tool_definitions.as_deref(),
                 );
+                let summary_source = if compression_result.has_model_summary {
+                    "model"
+                } else {
+                    "local_fallback"
+                };
+
+                info!(
+                    "Compression completed: session_id={}, turn_id={}, messages {} -> {}, tokens {} -> {}, compression_count={}, duration_ms={}, summary_source={}",
+                    session_id,
+                    dialog_turn_id,
+                    old_messages_len,
+                    new_messages.len(),
+                    current_tokens,
+                    compressed_tokens,
+                    session.compression_state.compression_count,
+                    duration_ms,
+                    summary_source
+                );
 
                 // Emit compression completed event
                 self.emit_event(
@@ -753,11 +765,7 @@ impl ExecutionEngine {
                         compression_ratio: (compressed_tokens as f64) / (current_tokens as f64),
                         duration_ms,
                         has_summary: compression_result.has_model_summary,
-                        summary_source: if compression_result.has_model_summary {
-                            "model".to_string()
-                        } else {
-                            "local_fallback".to_string()
-                        },
+                        summary_source: summary_source.to_string(),
                         subagent_parent_info: event_subagent_parent_info.clone(),
                     },
                     EventPriority::Normal,
@@ -825,7 +833,7 @@ impl ExecutionEngine {
             .collect_all_turns_for_manual_compaction(session_id, messages)?;
 
         if turns.is_empty() {
-            let duration_ms = start_time.elapsed().as_millis() as u64;
+            let duration_ms = elapsed_ms_u64(start_time);
             let tokens_after = current_tokens;
             let compression_ratio = if current_tokens == 0 {
                 1.0
@@ -882,7 +890,7 @@ impl ExecutionEngine {
                     .update_compression_state(session_id, session.compression_state.clone())
                     .await;
 
-                let duration_ms = start_time.elapsed().as_millis() as u64;
+                let duration_ms = elapsed_ms_u64(start_time);
                 let tokens_after = compressed_messages
                     .iter_mut()
                     .map(|message| message.get_tokens())
@@ -1565,7 +1573,7 @@ impl ExecutionEngine {
             );
         }
 
-        let duration_ms = start_time.elapsed().as_millis() as u64;
+        let duration_ms = elapsed_ms_u64(start_time);
 
         info!(
             "Dialog turn loop completed: turn={}, rounds={}, total_tools={}",

src/crates/core/src/agentic/image_analysis/processor.rs

@@ -9,6 +9,7 @@ use super::image_processing::{
 use super::types::{AnalyzeImagesRequest, ImageAnalysisResult, ImageContextData};
 use crate::infrastructure::ai::AIClient;
 use crate::service::config::types::AIModelConfig;
+use crate::util::elapsed_ms_u64;
 use crate::util::errors::*;
 use log::{debug, error, info, warn};
 use std::path::PathBuf;
@@ -137,7 +138,7 @@ impl ImageAnalyzer {
         debug!("AI response content: {}", ai_response.text);
 
         let mut analysis_result = Self::parse_analysis_response(&ai_response.text, &image_ctx.id);
-        analysis_result.analysis_time_ms = start.elapsed().as_millis() as u64;
+        analysis_result.analysis_time_ms = elapsed_ms_u64(start);
 
         info!(
             "Image analysis completed: image_id={}, duration={}ms",