From 7ca89c6cec7c1d58ab75402f04a18936dc573af6 Mon Sep 17 00:00:00 2001 From: limit_yan Date: Thu, 23 Apr 2026 14:19:24 +0800 Subject: [PATCH] refactor(observability): unify timing instrumentation --- src/apps/desktop/src/api/tool_api.rs | 7 +- src/apps/desktop/src/lib.rs | 34 ++++++ src/crates/LOGGING.md | 20 ++++ .../ai-adapters/src/client/healthcheck.rs | 11 +- src/crates/ai-adapters/src/client/sse.rs | 3 +- src/crates/ai-adapters/src/client/utils.rs | 5 + .../src/agentic/execution/execution_engine.rs | 40 ++++--- .../src/agentic/image_analysis/processor.rs | 3 +- .../tools/implementations/bash_tool.rs | 7 +- .../tools/implementations/control_hub_tool.rs | 3 +- .../agentic/tools/implementations/git_tool.rs | 5 +- .../agentic/tools/pipeline/tool_pipeline.rs | 3 +- .../core/src/service/filesystem/service.rs | 36 ++++++- .../core/src/service/git/git_service.rs | 25 ++--- .../core/src/service/snapshot/manager.rs | 9 +- src/crates/core/src/util/mod.rs | 2 + src/crates/core/src/util/timing.rs | 36 +++++++ src/web-ui/LOGGING.md | 27 +++++ src/web-ui/src/app/hooks/useWindowControls.ts | 12 +-- .../src/flow_chat/services/EventBatcher.ts | 15 +-- .../api/service-api/ApiClient.ts | 19 ++-- .../infrastructure/i18n/core/I18nService.ts | 45 ++++++-- src/web-ui/src/main.tsx | 65 +++++++++-- src/web-ui/src/shared/utils/debugProbe.ts | 29 ++++- src/web-ui/src/shared/utils/index.ts | 2 + src/web-ui/src/shared/utils/timing.ts | 101 ++++++++++++++++++ .../tools/editor/components/CodeEditor.tsx | 8 +- .../editor/components/MarkdownEditor.tsx | 8 +- .../src/tools/git/services/GitService.ts | 14 ++- .../src/tools/git/state/GitStateManager.ts | 9 +- .../src/tools/lsp/services/LspDiagnostics.ts | 12 ++- .../lsp/services/LspExtensionRegistry.ts | 12 +-- .../src/tools/lsp/services/LspService.ts | 78 +++++--------- .../tools/terminal/components/Terminal.tsx | 12 +-- 34 files changed, 528 insertions(+), 189 deletions(-) create mode 100644 src/crates/core/src/util/timing.rs create mode 100644 src/web-ui/src/shared/utils/timing.ts diff --git a/src/apps/desktop/src/api/tool_api.rs b/src/apps/desktop/src/api/tool_api.rs index 6f006caf5..6eef04b25 100644 --- a/src/apps/desktop/src/api/tool_api.rs +++ b/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 Result { @@ -317,7 +318,7 @@ pub async fn execute_tool(request: ToolExecutionRequest) -> Result 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); @@ -82,15 +86,18 @@ pub async fn run() { 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,12 +129,16 @@ 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) => { @@ -131,6 +146,7 @@ pub async fn run() { 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")] { diff --git a/src/crates/LOGGING.md b/src/crates/LOGGING.md index cb3e20ada..170ea50b5 100644 --- a/src/crates/LOGGING.md +++ b/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 diff --git a/src/crates/ai-adapters/src/client/healthcheck.rs b/src/crates/ai-adapters/src/client/healthcheck.rs index 19262baf5..4a25ebb94 100644 --- a/src/crates/ai-adapters/src/client/healthcheck.rs +++ b/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 { - 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 { - 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 Result Result { - 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() { diff --git a/src/crates/ai-adapters/src/client/utils.rs b/src/crates/ai-adapters/src/client/utils.rs index da0388bb7..cbf93baf4 100644 --- a/src/crates/ai-adapters/src/client/utils.rs +++ b/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 +} diff --git a/src/crates/core/src/agentic/execution/execution_engine.rs b/src/crates/core/src/agentic/execution/execution_engine.rs index 6588cf901..70103105d 100644 --- a/src/crates/core/src/agentic/execution/execution_engine.rs +++ b/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,13 +720,6 @@ 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 @@ -733,13 +727,31 @@ impl ExecutionEngine { .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={}", diff --git a/src/crates/core/src/agentic/image_analysis/processor.rs b/src/crates/core/src/agentic/image_analysis/processor.rs index e72639a92..eb643f664 100644 --- a/src/crates/core/src/agentic/image_analysis/processor.rs +++ b/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", diff --git a/src/crates/core/src/agentic/tools/implementations/bash_tool.rs b/src/crates/core/src/agentic/tools/implementations/bash_tool.rs index e2e5c8210..a9da4feb6 100644 --- a/src/crates/core/src/agentic/tools/implementations/bash_tool.rs +++ b/src/crates/core/src/agentic/tools/implementations/bash_tool.rs @@ -7,6 +7,7 @@ use crate::infrastructure::events::event_system::BackendEvent::{ ToolExecutionProgress, ToolTerminalReady, }; use crate::service::config::global::get_global_config_service; +use crate::util::elapsed_ms_u64; use crate::util::errors::{BitFunError, BitFunResult}; use crate::util::types::event::{ToolExecutionProgressInfo, ToolTerminalReadyInfo}; use async_trait::async_trait; @@ -620,7 +621,7 @@ Usage notes: let output = exec_result.combined_output(); - let execution_time_ms = start_time.elapsed().as_millis() as u64; + let execution_time_ms = elapsed_ms_u64(start_time); let working_directory = context .workspace_root() .map(|p| p.to_string_lossy().to_string()) @@ -902,7 +903,7 @@ Usage notes: } // 6. Build result - let execution_time_ms = start_time.elapsed().as_millis() as u64; + let execution_time_ms = elapsed_ms_u64(start_time); let result_data = json!({ "success": final_exit_code.unwrap_or(-1) == 0, @@ -1091,7 +1092,7 @@ impl BashTool { }); } - let execution_time_ms = start_time.elapsed().as_millis() as u64; + let execution_time_ms = elapsed_ms_u64(start_time); let output_file_str = output_file_path.as_deref().map(|p| p.display().to_string()); let output_file_reference = context diff --git a/src/crates/core/src/agentic/tools/implementations/control_hub_tool.rs b/src/crates/core/src/agentic/tools/implementations/control_hub_tool.rs index d5bb7ccbc..e2bc00ba2 100644 --- a/src/crates/core/src/agentic/tools/implementations/control_hub_tool.rs +++ b/src/crates/core/src/agentic/tools/implementations/control_hub_tool.rs @@ -25,6 +25,7 @@ use crate::agentic::tools::framework::{ }; use crate::service::config::global::GlobalConfigManager; use crate::service::config::types::AIConfig; +use crate::util::elapsed_ms_u64; use crate::util::errors::{BitFunError, BitFunResult}; use async_trait::async_trait; use serde_json::{json, Value}; @@ -3085,7 +3086,7 @@ for control flow. Ok(Ok(o)) => o, }; - let elapsed_ms = started.elapsed().as_millis() as u64; + let elapsed_ms = elapsed_ms_u64(started); let stdout_full = String::from_utf8_lossy(&output.stdout).to_string(); let stderr_full = String::from_utf8_lossy(&output.stderr).to_string(); let (stdout, stdout_truncated) = truncate_with_marker(&stdout_full, max_output_bytes); diff --git a/src/crates/core/src/agentic/tools/implementations/git_tool.rs b/src/crates/core/src/agentic/tools/implementations/git_tool.rs index 1995bbdf5..33e94cc61 100644 --- a/src/crates/core/src/agentic/tools/implementations/git_tool.rs +++ b/src/crates/core/src/agentic/tools/implementations/git_tool.rs @@ -9,6 +9,7 @@ use crate::service::git::{ execute_git_command, GitAddParams, GitCommitParams, GitDiffParams, GitLogParams, GitPullParams, GitPushParams, GitService, }; +use crate::util::elapsed_ms_u64; use crate::util::errors::{BitFunError, BitFunResult}; use async_trait::async_trait; use log::debug; @@ -545,7 +546,7 @@ impl GitTool { match execute_git_command(repo_path, &cmd_args).await { Ok(output) => { - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(json!({ "success": true, "exit_code": 0, @@ -555,7 +556,7 @@ impl GitTool { })) } Err(e) => { - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); // Git command failed but still return result Ok(json!({ "success": false, diff --git a/src/crates/core/src/agentic/tools/pipeline/tool_pipeline.rs b/src/crates/core/src/agentic/tools/pipeline/tool_pipeline.rs index 6a3120393..4d59473f4 100644 --- a/src/crates/core/src/agentic/tools/pipeline/tool_pipeline.rs +++ b/src/crates/core/src/agentic/tools/pipeline/tool_pipeline.rs @@ -10,6 +10,7 @@ use crate::agentic::events::types::ToolEventData; use crate::agentic::tools::computer_use_host::ComputerUseHostRef; use crate::agentic::tools::framework::{ToolResult as FrameworkToolResult, ToolUseContext}; use crate::agentic::tools::registry::ToolRegistry; +use crate::util::elapsed_ms_u64; use crate::util::errors::{BitFunError, BitFunResult}; use dashmap::DashMap; use futures::future::join_all; @@ -679,7 +680,7 @@ impl ToolPipeline { match result { Ok(tool_result) => { - let duration_ms = start_time.elapsed().as_millis() as u64; + let duration_ms = elapsed_ms_u64(start_time); self.state_manager .update_state( diff --git a/src/crates/core/src/service/filesystem/service.rs b/src/crates/core/src/service/filesystem/service.rs index 0958c61cf..a677f1da7 100644 --- a/src/crates/core/src/service/filesystem/service.rs +++ b/src/crates/core/src/service/filesystem/service.rs @@ -4,11 +4,15 @@ use crate::infrastructure::{ FileSearchResult, FileTreeNode, FileTreeService, FileWriteResult, }; use crate::util::errors::*; +use crate::util::elapsed_ms_u64; +use log::debug; use std::sync::atomic::AtomicBool; use std::sync::Arc; use super::types::{DirectoryScanResult, DirectoryStats, FileSearchOptions, FileSystemConfig}; +const SLOW_FILESYSTEM_OPERATION_LOG_MS: u64 = 500; + /// Unified file system service pub struct FileSystemService { file_tree_service: Arc, @@ -44,10 +48,25 @@ impl FileSystemService { root_path: &str, preferred_remote_connection_id: Option<&str>, ) -> BitFunResult> { - self.file_tree_service + let started_at = std::time::Instant::now(); + let tree = self + .file_tree_service .build_tree_with_remote_hint(root_path, preferred_remote_connection_id) .await - .map_err(BitFunError::service) + .map_err(BitFunError::service)?; + let duration_ms = elapsed_ms_u64(started_at); + + if duration_ms >= SLOW_FILESYSTEM_OPERATION_LOG_MS { + debug!( + "File tree built: root_path={}, preferred_remote_connection_id={}, duration_ms={}, root_entries={}", + root_path, + preferred_remote_connection_id.unwrap_or("local"), + duration_ms, + tree.len() + ); + } + + Ok(tree) } /// Scans a directory and returns a detailed result. @@ -59,7 +78,18 @@ impl FileSystemService { .build_tree_with_stats(root_path) .await?; - let scan_time_ms = start_time.elapsed().as_millis() as u64; + let scan_time_ms = elapsed_ms_u64(start_time); + + if scan_time_ms >= SLOW_FILESYSTEM_OPERATION_LOG_MS { + debug!( + "Directory scan completed: root_path={}, duration_ms={}, total_files={}, total_directories={}, total_size_bytes={}", + root_path, + scan_time_ms, + statistics.total_files, + statistics.total_directories, + statistics.total_size_bytes + ); + } Ok(DirectoryScanResult { files, diff --git a/src/crates/core/src/service/git/git_service.rs b/src/crates/core/src/service/git/git_service.rs index 591b1cb69..1c06f4275 100644 --- a/src/crates/core/src/service/git/git_service.rs +++ b/src/crates/core/src/service/git/git_service.rs @@ -1,6 +1,7 @@ /** * Git service implementation */ +use crate::util::elapsed_ms_u64; use super::git_types::*; use super::git_utils::*; use git2::{BranchType, Commit, Repository}; @@ -449,7 +450,7 @@ impl GitService { } let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -497,7 +498,7 @@ impl GitService { let args_refs: Vec<&str> = args.iter().map(|s| s.as_str()).collect(); let output = execute_git_command(&repo_path, &args_refs).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -547,7 +548,7 @@ impl GitService { .await .map_err(|_| GitError::NetworkError("Push operation timed out".to_string()))??; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -592,7 +593,7 @@ impl GitService { .await .map_err(|_| GitError::NetworkError("Pull operation timed out".to_string()))??; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -617,7 +618,7 @@ impl GitService { let args = vec!["checkout", branch_name]; let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -646,7 +647,7 @@ impl GitService { } let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -672,7 +673,7 @@ impl GitService { let flag = if force { "-D" } else { "-d" }; let args = vec!["branch", flag, branch_name]; let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -714,7 +715,7 @@ impl GitService { let args = vec!["reset", mode_flag, commit_hash]; let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -906,7 +907,7 @@ impl GitService { args.push(commit_hash); let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -935,7 +936,7 @@ impl GitService { let args = vec!["cherry-pick", "--abort"]; let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -961,7 +962,7 @@ impl GitService { let args = vec!["cherry-pick", "--continue"]; let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, @@ -1110,7 +1111,7 @@ impl GitService { args.push(worktree_path); let output = execute_git_command(&repo_path, &args).await?; - let duration = start_time.elapsed().as_millis() as u64; + let duration = elapsed_ms_u64(start_time); Ok(GitOperationResult { success: true, diff --git a/src/crates/core/src/service/snapshot/manager.rs b/src/crates/core/src/service/snapshot/manager.rs index 0b2956549..1573ba38e 100644 --- a/src/crates/core/src/service/snapshot/manager.rs +++ b/src/crates/core/src/service/snapshot/manager.rs @@ -551,7 +551,7 @@ impl WrappedTool { let start_time = std::time::Instant::now(); let results = self.original_tool.call(input, context).await?; - let duration_ms = start_time.elapsed().as_millis() as u64; + let duration_ms = crate::util::elapsed_ms_u64(start_time); snapshot_service .complete_file_modification(&session_id, &operation_id, duration_ms) @@ -559,8 +559,11 @@ impl WrappedTool { .map_err(|e| crate::util::errors::BitFunError::Tool(e.to_string()))?; debug!( - "File modification tool completed: tool_name={}", - self.name() + "File modification tool completed: tool_name={}, operation_id={}, duration_ms={}, file_path={}", + self.name(), + operation_id, + duration_ms, + file_path.display() ); Ok(results) } diff --git a/src/crates/core/src/util/mod.rs b/src/crates/core/src/util/mod.rs index a55acad2b..7bee99efd 100644 --- a/src/crates/core/src/util/mod.rs +++ b/src/crates/core/src/util/mod.rs @@ -5,6 +5,7 @@ pub mod front_matter_markdown; pub mod json_extract; pub mod plain_output; pub mod process_manager; +pub mod timing; pub mod token_counter; pub mod types; @@ -13,5 +14,6 @@ pub use front_matter_markdown::FrontMatterMarkdown; pub use json_extract::extract_json_from_ai_response; pub use plain_output::sanitize_plain_model_output; pub use process_manager::*; +pub use timing::*; pub use token_counter::*; pub use types::*; diff --git a/src/crates/core/src/util/timing.rs b/src/crates/core/src/util/timing.rs new file mode 100644 index 000000000..54b42e044 --- /dev/null +++ b/src/crates/core/src/util/timing.rs @@ -0,0 +1,36 @@ +use std::time::Instant; + +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct TimingStep { + pub name: &'static str, + pub duration_ms: u128, +} + +#[derive(Debug, Default, Clone)] +pub struct TimingCollector { + steps: Vec, +} + +impl TimingCollector { + pub fn push_duration(&mut self, name: &'static str, duration_ms: u128) { + self.steps.push(TimingStep { name, duration_ms }); + } + + pub fn record_elapsed(&mut self, name: &'static str, started_at: Instant) -> u128 { + let duration_ms = elapsed_ms(started_at); + self.push_duration(name, duration_ms); + duration_ms + } + + pub fn steps(&self) -> &[TimingStep] { + &self.steps + } +} + +pub fn elapsed_ms(started_at: Instant) -> u128 { + started_at.elapsed().as_millis() +} + +pub fn elapsed_ms_u64(started_at: Instant) -> u64 { + started_at.elapsed().as_millis() as u64 +} diff --git a/src/web-ui/LOGGING.md b/src/web-ui/LOGGING.md index 7647b2275..3d4a81e69 100644 --- a/src/web-ui/LOGGING.md +++ b/src/web-ui/LOGGING.md @@ -76,3 +76,30 @@ Examples: 4. Avoid logging sensitive data (tokens, passwords, PII) 5. Avoid excessive logging in hot paths (loops, frequent callbacks) 6. Use TRACE for expensive computations that may impact performance + +## Timing And Probes + +Use `src/web-ui/src/shared/utils/timing.ts` as the single timing helper for frontend diagnostics. + +```typescript +import { createLogger } from '@/shared/utils/logger'; +import { measureAsyncAndLog, sendDebugProbe } from '@/shared/utils'; + +const log = createLogger('ModuleName'); + +await measureAsyncAndLog(log, 'Workspace loaded', () => loadWorkspace(), { + data: { workspacePath }, +}); + +sendDebugProbe('ModuleName.ts:42', 'Workspace refresh completed', { workspacePath }, { + startedAt, +}); +``` + +Rules: + +1. Prefer `measureSync`, `measureAsync`, `measureSyncAndLog`, `measureAsyncAndLog`, `logDuration`, and `logElapsed` over handwritten `performance.now()` / `Date.now()` timing logs +2. Use `durationMs` for frontend diagnostic log fields +3. Treat `sendDebugProbe` as a thin wrapper over the shared logger/timing helpers, not as a separate logging system +4. Do not replace protocol or persisted fields such as `duration_ms` when they are part of API payloads, events, or stored data +5. Do not migrate animation, polling, or deadline logic that depends on raw clock semantics into the logging helper layer diff --git a/src/web-ui/src/app/hooks/useWindowControls.ts b/src/web-ui/src/app/hooks/useWindowControls.ts index c4fa63450..301e4cf68 100644 --- a/src/web-ui/src/app/hooks/useWindowControls.ts +++ b/src/web-ui/src/app/hooks/useWindowControls.ts @@ -4,6 +4,7 @@ import { useWorkspaceContext } from '../../infrastructure/contexts/WorkspaceCont import { notificationService } from '@/shared/notification-system'; import { createLogger } from '@/shared/utils/logger'; import { sendDebugProbe } from '@/shared/utils/debugProbe'; +import { nowMs } from '@/shared/utils/timing'; import { useI18n } from '@/infrastructure/i18n'; import { isMacOSDesktopRuntime, supportsNativeWindowControls } from '@/infrastructure/runtime'; @@ -101,7 +102,7 @@ export const useWindowControls = (options?: { isToolbarMode?: boolean }) => { const appWindow = getCurrentWindow(); // Delay update until window fully restores setTimeout(async () => { - const startedAt = typeof performance !== 'undefined' ? performance.now() : Date.now(); + const startedAt = nowMs(); try { await updateWindowState(appWindow); await restoreMacOSOverlayTitlebar(appWindow); @@ -109,14 +110,9 @@ export const useWindowControls = (options?: { isToolbarMode?: boolean }) => { 'useWindowControls.ts:handleVisibilityChange', 'Window restore sync completed', { - durationMs: - Math.round( - ((typeof performance !== 'undefined' ? performance.now() : Date.now()) - - startedAt) * - 10 - ) / 10, isToolbarMode, - } + }, + { startedAt } ); } catch (error) { sendDebugProbe( diff --git a/src/web-ui/src/flow_chat/services/EventBatcher.ts b/src/web-ui/src/flow_chat/services/EventBatcher.ts index 00af41f91..8d58d864b 100644 --- a/src/web-ui/src/flow_chat/services/EventBatcher.ts +++ b/src/web-ui/src/flow_chat/services/EventBatcher.ts @@ -10,6 +10,7 @@ */ import { createLogger } from '@/shared/utils/logger'; +import { elapsedMs, nowMs } from '@/shared/utils/timing'; const log = createLogger('EventBatcher'); @@ -82,7 +83,7 @@ export class EventBatcher { if (this.scheduled) return; this.scheduled = true; - const now = performance.now(); + const now = nowMs(); const timeSinceLastUpdate = now - this.lastUpdateTime; if (timeSinceLastUpdate >= this.UPDATE_INTERVAL) { @@ -90,7 +91,7 @@ export class EventBatcher { this.flush(); this.scheduled = false; this.frameId = null; - this.lastUpdateTime = performance.now(); + this.lastUpdateTime = nowMs(); }); } else { const delay = this.UPDATE_INTERVAL - timeSinceLastUpdate; @@ -99,7 +100,7 @@ export class EventBatcher { this.flush(); this.scheduled = false; this.frameId = null; - this.lastUpdateTime = performance.now(); + this.lastUpdateTime = nowMs(); }); this.timeoutId = null; }, delay); @@ -109,7 +110,7 @@ export class EventBatcher { private flush(): void { if (this.buffer.size === 0) return; - const startTime = performance.now(); + const startTime = nowMs(); const bufferedEvents = Array.from(this.buffer.values()); const mergedEventCount = bufferedEvents.length; const rawEventCount = bufferedEvents.reduce((count, event) => count + event.sourceCount, 0); @@ -134,12 +135,12 @@ export class EventBatcher { this.buffer = new Map(); this.onFlush(events); - const duration = performance.now() - startTime; - if (duration > 10) { + const durationMs = elapsedMs(startTime); + if (durationMs > 10) { log.warn('Event batch processing took longer than expected', { rawEventCount, mergedEventCount, - duration: duration.toFixed(2) + durationMs, }); } } diff --git a/src/web-ui/src/infrastructure/api/service-api/ApiClient.ts b/src/web-ui/src/infrastructure/api/service-api/ApiClient.ts index 49363209f..129e0fa2b 100644 --- a/src/web-ui/src/infrastructure/api/service-api/ApiClient.ts +++ b/src/web-ui/src/infrastructure/api/service-api/ApiClient.ts @@ -14,6 +14,7 @@ import { ApiConfig } from './types'; import { createLogger } from '@/shared/utils/logger'; +import { elapsedMs, nowMs } from '@/shared/utils/timing'; const log = createLogger('ApiClient'); const SENSITIVE_KEY_PATTERNS = [ @@ -190,7 +191,7 @@ export class ApiClient implements IApiClient { } private async executeRequest(request: ApiRequest): Promise { - const startTime = Date.now(); + const startedAt = nowMs(); this.updateStats({ totalRequests: this.stats.totalRequests + 1 }); @@ -218,15 +219,15 @@ export class ApiClient implements IApiClient { this.activeRequests.delete(request.id); - const responseTime = Date.now() - startTime; - this.recordResponseTime(responseTime); + const durationMs = elapsedMs(startedAt); + this.recordResponseTime(durationMs); this.updateStats({ successfulRequests: this.stats.successfulRequests + 1 }); if (this.config.enableLogging) { log.debug('Request completed', { type: request.type, - responseTime, + durationMs, config: sanitizeForLog(request.config) }); } @@ -469,20 +470,20 @@ export const api = { export function createLoggingMiddleware(): ApiMiddleware { const middlewareLog = createLogger('ApiMiddleware'); return async (request: ApiRequest, next: (request: ApiRequest) => Promise) => { - const startTime = Date.now(); + const startedAt = nowMs(); try { const response = await next(request); - const duration = Date.now() - startTime; + const durationMs = elapsedMs(startedAt); middlewareLog.debug('Request completed', { type: request.type, - duration, + durationMs, config: sanitizeForLog(request.config) }); return response; } catch (error) { - const duration = Date.now() - startTime; - middlewareLog.error('Request failed', { type: request.type, duration, error }); + const durationMs = elapsedMs(startedAt); + middlewareLog.error('Request failed', { type: request.type, durationMs, error }); throw error; } }; diff --git a/src/web-ui/src/infrastructure/i18n/core/I18nService.ts b/src/web-ui/src/infrastructure/i18n/core/I18nService.ts index 2e09f446a..46409fc43 100644 --- a/src/web-ui/src/infrastructure/i18n/core/I18nService.ts +++ b/src/web-ui/src/infrastructure/i18n/core/I18nService.ts @@ -24,6 +24,7 @@ import { useI18nStore } from '../store/i18nStore'; import { i18nAPI } from '@/infrastructure/api/service-api/I18nAPI'; import { createLogger } from '@/shared/utils/logger'; +import { logDuration, measureSync, nowMs, elapsedMs } from '@/shared/utils/timing'; const log = createLogger('I18nService'); @@ -49,7 +50,14 @@ function buildResources(): Resource { }, {}); } -const resources = buildResources(); +const resourcesResult = measureSync(() => buildResources()); +const resources = resourcesResult.value; +logDuration(log, 'I18n resources prepared', resourcesResult.durationMs, { + data: { + localeCount: Object.keys(resources).length, + moduleCount: Object.keys(localeModules).length, + }, +}); export class I18nService { @@ -91,6 +99,7 @@ export class I18nService { return; } + const startedAt = nowMs(); try { let localeToUse: LocaleId = DEFAULT_LOCALE; const preInjectedLocale = document.documentElement.getAttribute('lang'); @@ -114,12 +123,21 @@ export class I18nService { this.initialized = true; log.info('Initialization completed', { locale: this.currentLocaleId }); + logDuration(log, 'I18n initialization timing', elapsedMs(startedAt), { + level: 'debug', + data: { + locale: this.currentLocaleId, + }, + }); const seqAtInitEnd = this.localeChangeSeq; const localeAtInitEnd = this.currentLocaleId; this.loadAndApplyBackendLocale(seqAtInitEnd, localeAtInitEnd); } catch (error) { - log.error('Initialization failed', error); + log.error('Initialization failed', { + error, + durationMs: elapsedMs(startedAt), + }); this.initialized = true; const store = useI18nStore.getState(); @@ -128,6 +146,7 @@ export class I18nService { } private async loadAndApplyBackendLocale(seqAtInitEnd: number, localeAtInitEnd: LocaleId): Promise { + const startedAt = nowMs(); try { const savedLocale = await this.loadCurrentLocale(); if (!savedLocale || savedLocale === this.currentLocaleId) { @@ -140,6 +159,11 @@ export class I18nService { } await this.changeLanguage(savedLocale); + logDuration(log, 'Backend locale applied after initialization', elapsedMs(startedAt), { + data: { + locale: savedLocale, + }, + }); } catch (error) { log.debug('Failed to load backend locale (ignored)', error); } @@ -147,6 +171,7 @@ export class I18nService { private async loadCurrentLocale(): Promise { + const startedAt = nowMs(); try { const timeoutPromise = new Promise((resolve) => { @@ -158,12 +183,18 @@ export class I18nService { timeoutPromise, ]); - if (locale && isLocaleSupported(locale)) { - return locale; - } - return null; + const resolvedLocale = locale && isLocaleSupported(locale) ? locale : null; + logDuration(log, 'Backend locale load completed', elapsedMs(startedAt), { + data: { + locale: resolvedLocale ?? locale ?? 'timeout', + }, + }); + return resolvedLocale; } catch (error) { - log.debug('Failed to load locale config (ignored)', error); + log.debug('Failed to load locale config (ignored)', { + error, + durationMs: elapsedMs(startedAt), + }); return null; } } diff --git a/src/web-ui/src/main.tsx b/src/web-ui/src/main.tsx index a89dad86d..cf76905f2 100644 --- a/src/web-ui/src/main.tsx +++ b/src/web-ui/src/main.tsx @@ -16,6 +16,7 @@ import { initContextMenuSystem } from "./shared/context-menu-system"; import { loader } from '@monaco-editor/react'; import { getMonacoPath, getMonacoWorkerPath, logMonacoResourceCheck } from './tools/editor/utils/monacoPathHelper'; import { bootstrapLogger, createLogger, initLogger } from './shared/utils/logger'; +import { elapsedMs, logElapsed, measureAsyncAndLog, nowMs } from './shared/utils/timing'; import { buildReactCrashLogPayload, isMinifiedReactErrorMessage, @@ -215,27 +216,50 @@ const DEFAULT_WORKER = 'base/worker/workerMain.js'; /** Logger, theme, and minimal deps — must finish before first React paint (F5 / webview reload does not re-run Tauri init script). */ async function initializeBeforeRender(): Promise { - await initLogger(); + const phaseStartedAt = nowMs(); + await measureAsyncAndLog(log, 'Startup step completed', () => initLogger(), { + data: { step: 'initLogger' }, + }); - const { initializeFrontendLogLevelSync } = await import('./infrastructure/config/services/FrontendLogLevelSync'); - await initializeFrontendLogLevelSync(); + await measureAsyncAndLog(log, 'Startup step completed', async () => { + const { initializeFrontendLogLevelSync } = await import('./infrastructure/config/services/FrontendLogLevelSync'); + await initializeFrontendLogLevelSync(); + }, { + data: { step: 'initializeFrontendLogLevelSync' }, + }); log.debug('Monaco loader configured', { vs: monacoPath, isDev }); log.info('Initializing BitFun'); - const { registerDefaultContextTypes } = await import('./shared/context-system/core/registerDefaultTypes'); - registerDefaultContextTypes(); + await measureAsyncAndLog(log, 'Startup step completed', async () => { + const { registerDefaultContextTypes } = await import('./shared/context-system/core/registerDefaultTypes'); + registerDefaultContextTypes(); + }, { + data: { step: 'registerDefaultContextTypes' }, + }); - const { initRecommendationProviders } = await import('./flow_chat/components/smart-recommendations'); - initRecommendationProviders(); + await measureAsyncAndLog(log, 'Startup step completed', async () => { + const { initRecommendationProviders } = await import('./flow_chat/components/smart-recommendations'); + initRecommendationProviders(); + }, { + data: { step: 'initRecommendationProviders' }, + }); - const { themeService } = await import('./infrastructure/theme'); - await themeService.initialize(); + await measureAsyncAndLog(log, 'Startup step completed', async () => { + const { themeService } = await import('./infrastructure/theme'); + await themeService.initialize(); + }, { + data: { step: 'themeService.initialize' }, + }); log.info('Theme system initialized'); + logElapsed(log, 'Startup phase completed', phaseStartedAt, { + data: { phase: 'initializeBeforeRender' }, + }); } /** Rest of startup runs after the shell is visible so refresh latency stays reasonable. */ async function initializeAfterRender(): Promise { + const phaseStartedAt = nowMs(); const { fontPreferenceService } = await import('./infrastructure/font-preference'); await fontPreferenceService.initialize(); log.info('Font preference initialized at startup'); @@ -274,9 +298,13 @@ async function initializeAfterRender(): Promise { }); log.info('BitFun core systems initialized successfully'); + logElapsed(log, 'Startup phase completed', phaseStartedAt, { + data: { phase: 'initializeAfterRender' }, + }); } async function startApplication(): Promise { + const appStartedAt = nowMs(); try { await initializeBeforeRender(); } catch (error) { @@ -284,8 +312,15 @@ async function startApplication(): Promise { } // I18n Provider. - const { I18nProvider } = await import('./infrastructure/i18n'); + const i18nProviderImportResult = await measureAsyncAndLog( + log, + 'Startup step completed', + () => import('./infrastructure/i18n'), + { data: { step: 'loadI18nProvider' } } + ); + const { I18nProvider } = i18nProviderImportResult.value; + const renderStartedAt = nowMs(); ReactDOM.createRoot(document.getElementById('root') as HTMLElement).render( @@ -295,12 +330,22 @@ async function startApplication(): Promise { ); + logElapsed(log, 'Startup step completed', renderStartedAt, { + data: { + step: 'scheduleInitialRender', + sinceStartupMs: elapsedMs(appStartedAt), + }, + }); try { await initializeAfterRender(); } catch (error) { log.error('Failed to complete post-render initialization', error); } + + logElapsed(log, 'Startup phase completed', appStartedAt, { + data: { phase: 'startApplication' }, + }); } void startApplication(); diff --git a/src/web-ui/src/shared/utils/debugProbe.ts b/src/web-ui/src/shared/utils/debugProbe.ts index 7024e4a2c..85e0e7ce9 100644 --- a/src/web-ui/src/shared/utils/debugProbe.ts +++ b/src/web-ui/src/shared/utils/debugProbe.ts @@ -1,8 +1,13 @@ import { createLogger } from './logger'; +import { logElapsed, logWithLevel, type LogLevelName } from './timing'; type DebugProbeData = Record; +type DebugProbeOptions = { + level?: LogLevelName; + startedAt?: number; +}; -const log = createLogger('RestoreProbe'); +const log = createLogger('DebugProbe'); function serializeProbeValue(value: unknown): unknown { if (value instanceof Error) { @@ -26,7 +31,8 @@ function serializeProbeValue(value: unknown): unknown { export function sendDebugProbe( location: string, message: string, - data?: DebugProbeData + data?: DebugProbeData, + options: DebugProbeOptions = {} ): void { const serializedData = data ? Object.fromEntries( @@ -34,8 +40,21 @@ export function sendDebugProbe( ) : undefined; - log.info(message, { + const payload: Record = { location, - ...serializedData, - }); + ...(serializedData ?? {}), + }; + + if ( + options.startedAt !== undefined && + typeof payload.durationMs !== 'number' + ) { + logElapsed(log, message, options.startedAt, { + level: options.level ?? 'debug', + data: payload, + }); + return; + } + + logWithLevel(log, options.level ?? 'debug', message, payload); } diff --git a/src/web-ui/src/shared/utils/index.ts b/src/web-ui/src/shared/utils/index.ts index bb7b1a526..ca4d9cef4 100644 --- a/src/web-ui/src/shared/utils/index.ts +++ b/src/web-ui/src/shared/utils/index.ts @@ -6,6 +6,8 @@ export * from './validation'; export * from './logger'; +export * from './timing'; +export * from './debugProbe'; export * from './configConverter'; diff --git a/src/web-ui/src/shared/utils/timing.ts b/src/web-ui/src/shared/utils/timing.ts new file mode 100644 index 000000000..f4986430e --- /dev/null +++ b/src/web-ui/src/shared/utils/timing.ts @@ -0,0 +1,101 @@ +export interface MeasuredValue { + value: T; + durationMs: number; +} + +export type LogLevelName = 'trace' | 'debug' | 'info' | 'warn' | 'error'; + +export interface LoggerLike { + trace: (message: string, data?: unknown) => void; + debug: (message: string, data?: unknown) => void; + info: (message: string, data?: unknown) => void; + warn: (message: string, data?: unknown) => void; + error: (message: string, data?: unknown) => void; +} + +export interface TimedLogOptions { + level?: LogLevelName; + data?: Record; +} + +export function nowMs(): number { + return typeof performance !== 'undefined' ? performance.now() : Date.now(); +} + +export function roundDurationMs(durationMs: number): number { + return Math.round(durationMs * 10) / 10; +} + +export function elapsedMs(startedAt: number): number { + return roundDurationMs(nowMs() - startedAt); +} + +export function measureSync(task: () => T): MeasuredValue { + const startedAt = nowMs(); + return { + value: task(), + durationMs: elapsedMs(startedAt), + }; +} + +export async function measureAsync(task: () => Promise | T): Promise> { + const startedAt = nowMs(); + return { + value: await task(), + durationMs: elapsedMs(startedAt), + }; +} + +export function logWithLevel( + logger: LoggerLike, + level: LogLevelName, + message: string, + data?: Record +): void { + logger[level](message, data); +} + +export function logDuration( + logger: LoggerLike, + message: string, + durationMs: number, + options: TimedLogOptions = {} +): number { + const roundedDurationMs = roundDurationMs(durationMs); + logWithLevel(logger, options.level ?? 'debug', message, { + ...(options.data ?? {}), + durationMs: roundedDurationMs, + }); + return roundedDurationMs; +} + +export function logElapsed( + logger: LoggerLike, + message: string, + startedAt: number, + options: TimedLogOptions = {} +): number { + return logDuration(logger, message, elapsedMs(startedAt), options); +} + +export function measureSyncAndLog( + logger: LoggerLike, + message: string, + task: () => T, + options: TimedLogOptions = {} +): MeasuredValue { + const result = measureSync(task); + logDuration(logger, message, result.durationMs, options); + return result; +} + +export async function measureAsyncAndLog( + logger: LoggerLike, + message: string, + task: () => Promise | T, + options: TimedLogOptions = {} +): Promise> { + const result = await measureAsync(task); + logDuration(logger, message, result.durationMs, options); + return result; +} diff --git a/src/web-ui/src/tools/editor/components/CodeEditor.tsx b/src/web-ui/src/tools/editor/components/CodeEditor.tsx index 58e25a32f..e68bce50c 100644 --- a/src/web-ui/src/tools/editor/components/CodeEditor.tsx +++ b/src/web-ui/src/tools/editor/components/CodeEditor.tsx @@ -25,6 +25,7 @@ import { CubeLoading } from '@/component-library'; import { getMonacoLanguage } from '@/infrastructure/language-detection'; import { createLogger } from '@/shared/utils/logger'; import { sendDebugProbe } from '@/shared/utils/debugProbe'; +import { elapsedMs, nowMs } from '@/shared/utils/timing'; import { isSamePath } from '@/shared/utils/pathUtils'; import { diskContentMatchesEditorForExternalSync, @@ -1565,7 +1566,7 @@ const CodeEditor: React.FC = ({ } isCheckingFileRef.current = true; - const startedAt = typeof performance !== 'undefined' ? performance.now() : Date.now(); + const startedAt = nowMs(); let outcome = 'started'; let usedHashFallback = false; let probeError: string | null = null; @@ -1684,10 +1685,7 @@ const CodeEditor: React.FC = ({ } log.error('Failed to check file modification', err); } finally { - const durationMs = - Math.round( - ((typeof performance !== 'undefined' ? performance.now() : Date.now()) - startedAt) * 10 - ) / 10; + const durationMs = elapsedMs(startedAt); if (probeError || outcome !== 'no-change' || durationMs >= 80) { sendDebugProbe( 'CodeEditor.tsx:checkFileModification', diff --git a/src/web-ui/src/tools/editor/components/MarkdownEditor.tsx b/src/web-ui/src/tools/editor/components/MarkdownEditor.tsx index a50f178bb..920614111 100644 --- a/src/web-ui/src/tools/editor/components/MarkdownEditor.tsx +++ b/src/web-ui/src/tools/editor/components/MarkdownEditor.tsx @@ -12,6 +12,7 @@ import { analyzeMarkdownEditability, type MarkdownEditabilityAnalysis } from '.. import { AlertCircle } from 'lucide-react'; import { createLogger } from '@/shared/utils/logger'; import { sendDebugProbe } from '@/shared/utils/debugProbe'; +import { elapsedMs, nowMs } from '@/shared/utils/timing'; import { globalEventBus } from '@/infrastructure/event-bus'; import { CubeLoading, Button } from '@/component-library'; import { useI18n } from '@/infrastructure/i18n'; @@ -283,7 +284,7 @@ const MarkdownEditor: React.FC = ({ } isCheckingDiskRef.current = true; - const startedAt = typeof performance !== 'undefined' ? performance.now() : Date.now(); + const startedAt = nowMs(); let outcome = 'started'; let probeError: string | null = null; try { @@ -370,10 +371,7 @@ const MarkdownEditor: React.FC = ({ } log.error('Markdown disk sync check failed', e); } finally { - const durationMs = - Math.round( - ((typeof performance !== 'undefined' ? performance.now() : Date.now()) - startedAt) * 10 - ) / 10; + const durationMs = elapsedMs(startedAt); if (probeError || outcome !== 'no-change' || durationMs >= 80) { sendDebugProbe( 'MarkdownEditor.tsx:checkMarkdownDisk', diff --git a/src/web-ui/src/tools/git/services/GitService.ts b/src/web-ui/src/tools/git/services/GitService.ts index 68c9be8f1..c95d480bd 100644 --- a/src/web-ui/src/tools/git/services/GitService.ts +++ b/src/web-ui/src/tools/git/services/GitService.ts @@ -4,6 +4,7 @@ import { gitAPI } from '@/infrastructure/api'; import { createLogger } from '@/shared/utils/logger'; +import { measureAsync } from '@/shared/utils/timing'; import { i18nService } from '@/infrastructure/i18n'; const log = createLogger('GitService'); @@ -187,23 +188,20 @@ export class GitService { return null; } - const startTime = Date.now(); - const timeoutPromise = new Promise((_, reject) => setTimeout(() => reject(new Error('Get repository timeout')), 8000) ); - const result = await Promise.race([ + const result = await measureAsync(() => Promise.race([ gitAPI.getRepository(path), timeoutPromise - ]); + ])); - const duration = Date.now() - startTime; - log.debug('Repository info retrieved', { path, duration: `${duration}ms` }); + log.debug('Repository info retrieved', { path, durationMs: result.durationMs }); this.removeFromNonGitCache(path); - return this.adaptRepository(result); + return this.adaptRepository(result.value); } catch (error) { log.error('Failed to get repository info', error); this.addToNonGitCache(path); @@ -491,4 +489,4 @@ export class GitService { } -export const gitService = GitService.getInstance(); \ No newline at end of file +export const gitService = GitService.getInstance(); diff --git a/src/web-ui/src/tools/git/state/GitStateManager.ts b/src/web-ui/src/tools/git/state/GitStateManager.ts index 2beef1c41..d90c4fde1 100644 --- a/src/web-ui/src/tools/git/state/GitStateManager.ts +++ b/src/web-ui/src/tools/git/state/GitStateManager.ts @@ -33,6 +33,7 @@ import { } from './types'; import { createLogger } from '@/shared/utils/logger'; import { sendDebugProbe } from '@/shared/utils/debugProbe'; +import { elapsedMs, nowMs } from '@/shared/utils/timing'; import { i18nService } from '@/infrastructure/i18n'; const log = createLogger('GitStateManager'); @@ -333,7 +334,7 @@ export class GitStateManager { return; } - const startedAt = typeof performance !== 'undefined' ? performance.now() : Date.now(); + const startedAt = nowMs(); const shouldProbeReason = reason === 'window-focus' || reason === 'visibility' || reason === 'mount'; let probeError: string | null = null; @@ -420,11 +421,7 @@ export class GitStateManager { throw error; } finally { - const durationMs = - Math.round( - ((typeof performance !== 'undefined' ? performance.now() : Date.now()) - startedAt) * - 10 - ) / 10; + const durationMs = elapsedMs(startedAt); if (probeError || shouldProbeReason || durationMs >= 80) { sendDebugProbe('GitStateManager.ts:doRefresh', 'Git refresh completed', { repositoryPath, diff --git a/src/web-ui/src/tools/lsp/services/LspDiagnostics.ts b/src/web-ui/src/tools/lsp/services/LspDiagnostics.ts index b3871cc28..67459a8cc 100644 --- a/src/web-ui/src/tools/lsp/services/LspDiagnostics.ts +++ b/src/web-ui/src/tools/lsp/services/LspDiagnostics.ts @@ -4,6 +4,7 @@ import { invoke } from '@tauri-apps/api/core'; import { createLogger } from '@/shared/utils/logger'; +import { measureAsync } from '@/shared/utils/timing'; const log = createLogger('LspDiagnostics'); @@ -17,12 +18,13 @@ export class LspDiagnostics { /** Check backend LSP status. */ static async checkBackendStatus(workspacePath: string): Promise { try { - const startTime = Date.now(); - await invoke('lsp_get_all_server_states', { - request: { workspacePath } + const result = await measureAsync(() => invoke('lsp_get_all_server_states', { + request: { workspacePath }, + })); + log.debug('Got server states', { + workspacePath, + durationMs: result.durationMs, }); - const elapsed = Date.now() - startTime; - log.debug('Got server states', { workspacePath, elapsed }); return { backendInitialized: true, diff --git a/src/web-ui/src/tools/lsp/services/LspExtensionRegistry.ts b/src/web-ui/src/tools/lsp/services/LspExtensionRegistry.ts index 25e96a9c9..c7bc7d9cc 100644 --- a/src/web-ui/src/tools/lsp/services/LspExtensionRegistry.ts +++ b/src/web-ui/src/tools/lsp/services/LspExtensionRegistry.ts @@ -6,6 +6,7 @@ import { invoke } from '@tauri-apps/api/core'; import { createLogger } from '@/shared/utils/logger'; +import { measureAsync } from '@/shared/utils/timing'; const log = createLogger('LspExtensionRegistry'); @@ -55,10 +56,11 @@ class LspExtensionRegistry { } private async _doInitialize(): Promise { - const startTime = performance.now(); - try { - const response = await invoke('lsp_get_supported_extensions'); + const result = await measureAsync(() => + invoke('lsp_get_supported_extensions') + ); + const response = result.value; this.extensionToLanguage.clear(); this.supportedLanguages.clear(); @@ -73,10 +75,8 @@ class LspExtensionRegistry { } this.initialized = true; - const duration = (performance.now() - startTime).toFixed(2); - log.debug('Initialized successfully', { - duration: `${duration}ms`, + durationMs: result.durationMs, extensionCount: this.extensionToLanguage.size, languageCount: this.supportedLanguages.size }); diff --git a/src/web-ui/src/tools/lsp/services/LspService.ts b/src/web-ui/src/tools/lsp/services/LspService.ts index ca2e3596f..ea80f5f3c 100644 --- a/src/web-ui/src/tools/lsp/services/LspService.ts +++ b/src/web-ui/src/tools/lsp/services/LspService.ts @@ -4,6 +4,7 @@ import { invoke } from '@tauri-apps/api/core'; import { createLogger } from '@/shared/utils/logger'; +import { measureAsync } from '@/shared/utils/timing'; import type { LspPlugin, CompletionItem, TextEdit } from '../types'; const log = createLogger('LspService'); @@ -26,14 +27,11 @@ export class LspService { if (this.initialized) { return; } - - const startTime = performance.now(); try { - await invoke('lsp_initialize'); + const result = await measureAsync(() => invoke('lsp_initialize')); this.initialized = true; - const duration = performance.now() - startTime; - log.info('LSP system initialized', { duration: `${duration.toFixed(2)}ms` }); + log.info('LSP system initialized', { durationMs: result.durationMs }); } catch (error) { log.error('Failed to initialize LSP system', error); throw error; @@ -55,14 +53,11 @@ export class LspService { /** Start a language server for a given file path. */ async startServerForFile(filePath: string): Promise { - const startTime = performance.now(); - try { - await invoke('lsp_start_server_for_file', { + const result = await measureAsync(() => invoke('lsp_start_server_for_file', { request: { filePath } - }); - const duration = performance.now() - startTime; - log.debug('LSP server started for file', { filePath, duration: `${duration.toFixed(2)}ms` }); + })); + log.debug('LSP server started for file', { filePath, durationMs: result.durationMs }); } catch (error) { log.error('Failed to start LSP server for file', error); throw error; @@ -137,18 +132,15 @@ export class LspService { line: number, character: number ): Promise { - const startTime = performance.now(); - try { - const result = await invoke('lsp_get_completions', { + const result = await measureAsync(() => invoke('lsp_get_completions', { request: { language, uri, line, character } - }) as CompletionItem[]; - const duration = performance.now() - startTime; + }) as Promise); log.debug('Got completions', { - count: Array.isArray(result) ? result.length : 0, - duration: `${duration.toFixed(2)}ms` + count: Array.isArray(result.value) ? result.value.length : 0, + durationMs: result.durationMs, }); - return result; + return result.value; } catch (error) { log.error('Failed to get completions', error); throw error; @@ -180,15 +172,12 @@ export class LspService { line: number, character: number ): Promise { - const startTime = performance.now(); - try { - const result = await invoke('lsp_goto_definition', { + const result = await measureAsync(() => invoke('lsp_goto_definition', { request: { language, uri, line, character } - }); - const duration = performance.now() - startTime; - log.debug('Found definition', { duration: `${duration.toFixed(2)}ms` }); - return result; + })); + log.debug('Found definition', { durationMs: result.durationMs }); + return result.value; } catch (error) { log.error('Failed to go to definition', error); throw error; @@ -202,16 +191,13 @@ export class LspService { line: number, character: number ): Promise { - const startTime = performance.now(); - try { - const result = await invoke('lsp_find_references', { + const result = await measureAsync(() => invoke('lsp_find_references', { request: { language, uri, line, character } - }); - const duration = performance.now() - startTime; - const count = Array.isArray(result) ? result.length : 0; - log.debug('Found references', { count, duration: `${duration.toFixed(2)}ms` }); - return result; + })); + const count = Array.isArray(result.value) ? result.value.length : 0; + log.debug('Found references', { count, durationMs: result.durationMs }); + return result.value; } catch (error) { log.error('Failed to find references', error); throw error; @@ -225,16 +211,13 @@ export class LspService { tabSize?: number, insertSpaces?: boolean ): Promise { - const startTime = performance.now(); - try { - const result = await invoke('lsp_format_document', { + const result = await measureAsync(() => invoke('lsp_format_document', { request: { language, uri, tabSize, insertSpaces } - }) as TextEdit[]; - const duration = performance.now() - startTime; - const count = Array.isArray(result) ? result.length : 0; - log.debug('Document formatted', { editCount: count, duration: `${duration.toFixed(2)}ms` }); - return result; + }) as Promise); + const count = Array.isArray(result.value) ? result.value.length : 0; + log.debug('Document formatted', { editCount: count, durationMs: result.durationMs }); + return result.value; } catch (error) { log.error('Failed to format document', error); throw error; @@ -243,15 +226,12 @@ export class LspService { /** Install an LSP plugin package. */ async installPlugin(packagePath: string): Promise { - const startTime = performance.now(); - try { - const pluginId = await invoke('lsp_install_plugin', { + const result = await measureAsync(() => invoke('lsp_install_plugin', { request: { packagePath } - }) as string; - const duration = performance.now() - startTime; - log.info('Plugin installed', { pluginId, duration: `${duration.toFixed(2)}ms` }); - return pluginId; + }) as Promise); + log.info('Plugin installed', { pluginId: result.value, durationMs: result.durationMs }); + return result.value; } catch (error) { log.error('Failed to install plugin', error); throw error; diff --git a/src/web-ui/src/tools/terminal/components/Terminal.tsx b/src/web-ui/src/tools/terminal/components/Terminal.tsx index 675e8f0a8..9b11e65f7 100644 --- a/src/web-ui/src/tools/terminal/components/Terminal.tsx +++ b/src/web-ui/src/tools/terminal/components/Terminal.tsx @@ -19,6 +19,7 @@ import { systemAPI } from '@/infrastructure/api/service-api/SystemAPI'; import { themeService } from '@/infrastructure/theme/core/ThemeService'; import { createLogger } from '@/shared/utils/logger'; import { sendDebugProbe } from '@/shared/utils/debugProbe'; +import { nowMs } from '@/shared/utils/timing'; import '@xterm/xterm/css/xterm.css'; import './Terminal.scss'; @@ -565,7 +566,7 @@ const Terminal = forwardRef(({ isVisibleRef.current = isVisible; if (isVisible && !wasVisibleRef.current) { - const startedAt = typeof performance !== 'undefined' ? performance.now() : Date.now(); + const startedAt = nowMs(); requestAnimationFrame(() => { resizeDebouncerRef.current?.flush(); @@ -588,15 +589,10 @@ const Terminal = forwardRef(({ terminalId: terminalIdRef.current, sessionId: sessionIdRef.current, autoFocus: autoFocusRef.current, - durationMs: - Math.round( - ((typeof performance !== 'undefined' ? performance.now() : Date.now()) - - startedAt) * - 10 - ) / 10, cols: term?.cols ?? null, rows: term?.rows ?? null, - } + }, + { startedAt } ); }); });