diff --git a/Cargo.lock b/Cargo.lock index 1e4f2420b9..f10c2e1d13 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -20817,7 +20817,6 @@ version = "0.1.0" dependencies = [ "anyhow", "async-lock 2.8.0", - "chrono", "clock", "collections", "fs", diff --git a/crates/gpui/src/app.rs b/crates/gpui/src/app.rs index 083a2c7fa3..c042d85a12 100644 --- a/crates/gpui/src/app.rs +++ b/crates/gpui/src/app.rs @@ -6,7 +6,7 @@ use std::{ ops::{Deref, DerefMut}, path::{Path, PathBuf}, rc::{Rc, Weak}, - sync::{Arc, OnceLock, atomic::Ordering::SeqCst}, + sync::{Arc, atomic::Ordering::SeqCst}, time::{Duration, Instant}, }; @@ -120,9 +120,6 @@ impl Drop for AppRefMut<'_> { } } -/// TEST -pub static STARTUP_TIME: OnceLock = OnceLock::new(); - /// A reference to a GPUI application, typically constructed in the `main` function of your app. /// You won't interact with this type much outside of initial configuration and startup. pub struct Application(Rc); @@ -133,8 +130,6 @@ impl Application { /// Builds an app with the given asset source. #[allow(clippy::new_without_default)] pub fn new() -> Self { - STARTUP_TIME.get_or_init(|| Instant::now()); - #[cfg(any(test, feature = "test-support"))] log::info!("GPUI was compiled in test mode"); diff --git a/crates/project/src/buffer_store.rs b/crates/project/src/buffer_store.rs index e9ed754856..7129f66462 100644 --- a/crates/project/src/buffer_store.rs +++ b/crates/project/src/buffer_store.rs @@ -298,11 +298,6 @@ impl RemoteBufferStore { let project_id = self.project_id; let client = self.upstream_client.clone(); cx.spawn(async move |this, cx| { - log::info!( - "sending open buffer by path: {}", - path.display(PathStyle::Posix) - ); - let st = Instant::now(); let response = client .request(proto::OpenBufferByPath { project_id, @@ -310,8 +305,6 @@ impl RemoteBufferStore { path: path.to_proto(), }) .await?; - let end = Instant::now(); - log::info!("open buffer by path took: {:?}s", (end - st).as_secs_f64()); let buffer_id = BufferId::new(response.buffer_id)?; let buffer = this @@ -626,35 +619,24 @@ impl LocalBufferStore { ) -> Task>> { let load_file = worktree.update(cx, |worktree, cx| worktree.load_file(path.as_ref(), cx)); cx.spawn(async move |this, cx| { - let total_start = Instant::now(); let path = path.clone(); - let load_file_start = Instant::now(); let buffer = match load_file.await.with_context(|| { format!("Could not open path: {}", path.display(PathStyle::local())) }) { Ok(loaded) => { - let load_file_elapsed = load_file_start.elapsed(); - - let reserve_entity_start = Instant::now(); let reservation = cx.reserve_entity::()?; - let reserve_entity_elapsed = reserve_entity_start.elapsed(); let buffer_id = BufferId::from(reservation.entity_id().as_non_zero_u64()); - let text_buffer_start = Instant::now(); let text_buffer = cx .background_spawn(async move { text::Buffer::new(ReplicaId::LOCAL, buffer_id, loaded.text) }) .await; - let text_buffer_elapsed = text_buffer_start.elapsed(); - let insert_entity_start = Instant::now(); let buffer = cx.insert_entity(reservation, |_| { Buffer::build(text_buffer, Some(loaded.file), Capability::ReadWrite) })?; - let insert_entity_elapsed = insert_entity_start.elapsed(); - let add_buffer_start = Instant::now(); this.update(cx, |this, cx| { this.add_buffer(buffer.clone(), cx)?; let buffer_id = buffer.read(cx).remote_id(); @@ -675,26 +657,10 @@ impl LocalBufferStore { anyhow::Ok(()) })??; - let add_buffer_elapsed = add_buffer_start.elapsed(); - let total_elapsed = total_start.elapsed(); - - log::info!( - "{:?} LocalBufferStore::open_buffer timings: load file took: {}s, reserve entity took: {}s, text buffer new took: {}s, insert entity took: {}s, add buffer took: {}s, total took: {}s", - path.display(PathStyle::Posix), - load_file_elapsed.as_secs_f64(), - reserve_entity_elapsed.as_secs_f64(), - text_buffer_elapsed.as_secs_f64(), - insert_entity_elapsed.as_secs_f64(), - add_buffer_elapsed.as_secs_f64(), - total_elapsed.as_secs_f64() - ); buffer } Err(error) if is_not_found_error(&error) => { - let load_file_elapsed = load_file_start.elapsed(); - - let new_buffer_start = Instant::now(); let buffer = cx.new(|cx| { let buffer_id = BufferId::from(cx.entity_id().as_non_zero_u64()); let text_buffer = text::Buffer::new(ReplicaId::LOCAL, buffer_id, ""); @@ -711,9 +677,7 @@ impl LocalBufferStore { Capability::ReadWrite, ) })?; - let new_buffer_elapsed = new_buffer_start.elapsed(); - let add_buffer_start = Instant::now(); this.update(cx, |this, cx| { this.add_buffer(buffer.clone(), cx)?; let buffer_id = buffer.read(cx).remote_id(); @@ -734,17 +698,6 @@ impl LocalBufferStore { anyhow::Ok(()) })??; - let add_buffer_elapsed = add_buffer_start.elapsed(); - let total_elapsed = total_start.elapsed(); - - log::info!( - "{:?} LocalBufferStore::open_buffer (not found) timings: load file took: {}s, new buffer took: {}s, add buffer took: {}s, total took: {}s", - path.display(PathStyle::Posix), - load_file_elapsed.as_secs_f64(), - new_buffer_elapsed.as_secs_f64(), - add_buffer_elapsed.as_secs_f64(), - total_elapsed.as_secs_f64() - ); buffer } @@ -896,11 +849,6 @@ impl BufferStore { hash_map::Entry::Occupied(e) => e.get().clone(), hash_map::Entry::Vacant(entry) => { let path = project_path.path.clone(); - log::info!( - "[-] opening buffer for path {}", - path.display(PathStyle::Posix) - ); - let total_start = Instant::now(); let Some(worktree) = self .worktree_store .read(cx) @@ -908,31 +856,16 @@ impl BufferStore { else { return Task::ready(Err(anyhow!("no such worktree"))); }; - let worktree_lookup_elapsed = total_start.elapsed(); - let load_buffer_start = Instant::now(); let load_buffer = match &self.state { BufferStoreState::Local(this) => this.open_buffer(path.clone(), worktree, cx), BufferStoreState::Remote(this) => this.open_buffer(path.clone(), worktree, cx), }; - let load_buffer_task_elapsed = load_buffer_start.elapsed(); - let setup_elapsed = total_start.elapsed(); - log::info!( - "{:?} open_buffer setup timings: worktree lookup took: {}s, load buffer task creation took: {}s, total setup took: {}s", - path.display(PathStyle::Posix), - worktree_lookup_elapsed.as_secs_f64(), - load_buffer_task_elapsed.as_secs_f64(), - setup_elapsed.as_secs_f64() - ); entry .insert( // todo(lw): hot foreground spawn cx.spawn(async move |this, cx| { - let spawn_start = Instant::now(); let load_result = load_buffer.await; - let load_buffer_await_elapsed = spawn_start.elapsed(); - - let update_start = Instant::now(); let result = this.update(cx, |this, cx| { // Record the fact that the buffer is no longer loading. this.loading_buffers.remove(&project_path); @@ -945,16 +878,6 @@ impl BufferStore { Ok(buffer) })?; - let update_elapsed = update_start.elapsed(); - let total_spawn_elapsed = spawn_start.elapsed(); - - log::info!( - "{:?} open_buffer async timings: load buffer await took: {}s, update took: {}s, total async took: {}s", - path.display(PathStyle::Posix), - load_buffer_await_elapsed.as_secs_f64(), - update_elapsed.as_secs_f64(), - total_spawn_elapsed.as_secs_f64() - ); result }) diff --git a/crates/remote_server/src/headless_project.rs b/crates/remote_server/src/headless_project.rs index df4fd9569e..8ae4700ef0 100644 --- a/crates/remote_server/src/headless_project.rs +++ b/crates/remote_server/src/headless_project.rs @@ -37,7 +37,6 @@ use std::{ Arc, atomic::{AtomicU64, AtomicUsize, Ordering}, }, - time::Instant, }; use sysinfo::{ProcessRefreshKind, RefreshKind, System, UpdateKind}; use util::{ResultExt, paths::PathStyle, rel_path::RelPath}; @@ -507,36 +506,19 @@ impl HeadlessProject { message: TypedEnvelope, mut cx: AsyncApp, ) -> Result { - log::info!("received open buffer by path: {}", message.payload.path); - - let st = Instant::now(); - let worktree_id = WorktreeId::from_proto(message.payload.worktree_id); - let st1 = Instant::now(); let path = RelPath::from_proto(&message.payload.path)?; - let path1 = path.clone(); - let st2 = Instant::now(); - let (buffer_store, buffer, returning_at) = this.update(&mut cx, |this, cx| { + let (buffer_store, buffer) = this.update(&mut cx, |this, cx| { let buffer_store = this.buffer_store.clone(); - let upd_st = Instant::now(); let buffer = this.buffer_store.update(cx, |buffer_store, cx| { - let open_st = Instant::now(); - let ret = buffer_store.open_buffer(ProjectPath { worktree_id, path }, cx); - let open_end = Instant::now(); - log::info!("open buffer took {:?}", (open_end - open_st).as_secs_f64()); - ret + buffer_store.open_buffer(ProjectPath { worktree_id, path }, cx) }); - let upd_end = Instant::now(); - log::info!("update buffer took {:?}", (upd_end - upd_st).as_secs_f64()); - let returning_at = Instant::now(); - anyhow::Ok((buffer_store, buffer, returning_at)) + anyhow::Ok((buffer_store, buffer)) })??; - let st3 = Instant::now(); - let buffer = buffer.await?; - let st4 = Instant::now(); + let buffer_id = buffer.read_with(&cx, |b, _| b.remote_id())?; buffer_store.update(&mut cx, |buffer_store, cx| { buffer_store @@ -544,18 +526,6 @@ impl HeadlessProject { .detach_and_log_err(cx); })?; - let end = Instant::now(); - - log::info!( - "created buffer for path {}, st1 {:?}, st2 {:?}, st3 {:?}, st4 {:?} responding after {:?}", - path1.display(PathStyle::Posix), - (st2 - st1).as_secs_f64(), - (st3 - st2).as_secs_f64(), - (st4 - st3).as_secs_f64(), - (end - st4).as_secs_f64(), - (end - st).as_secs_f64() - ); - Ok(proto::OpenBufferResponse { buffer_id: buffer_id.to_proto(), }) diff --git a/crates/remote_server/src/main.rs b/crates/remote_server/src/main.rs index 9166dc3187..368c7cb639 100644 --- a/crates/remote_server/src/main.rs +++ b/crates/remote_server/src/main.rs @@ -29,8 +29,6 @@ fn main() { #[cfg(not(windows))] fn main() -> anyhow::Result<()> { - gpui::STARTUP_TIME.get_or_init(|| std::time::Instant::now()); - let cli = Cli::parse(); if let Some(socket_path) = &cli.askpass { diff --git a/crates/worktree/Cargo.toml b/crates/worktree/Cargo.toml index e64d323bbc..6d132fbd2c 100644 --- a/crates/worktree/Cargo.toml +++ b/crates/worktree/Cargo.toml @@ -47,7 +47,6 @@ smol.workspace = true sum_tree.workspace = true text.workspace = true util.workspace = true -chrono.workspace = true [dev-dependencies] clock = { workspace = true, features = ["test-support"] } diff --git a/crates/worktree/src/worktree.rs b/crates/worktree/src/worktree.rs index fe63e8c6b1..208bcdce60 100644 --- a/crates/worktree/src/worktree.rs +++ b/crates/worktree/src/worktree.rs @@ -23,7 +23,7 @@ use git::{ }; use gpui::{ App, AppContext as _, AsyncApp, BackgroundExecutor, Context, Entity, EventEmitter, FutureExt, - Priority, STARTUP_TIME, SerializedThreadTaskTimings, Task, + Priority, Task, }; use ignore::IgnoreStack; use language::DiskState; @@ -60,7 +60,7 @@ use std::{ Arc, atomic::{AtomicUsize, Ordering::SeqCst}, }, - time::{Duration, Instant}, + time::Duration, }; use sum_tree::{Bias, Dimensions, Edit, KeyedItem, SeekTarget, SumTree, Summary, TreeMap, TreeSet}; use text::{LineEnding, Rope}; @@ -1320,76 +1320,58 @@ impl LocalWorktree { let this = cx.weak_entity(); let bg_executor = cx.background_executor().clone(); - cx.background_executor().spawn_with_priority(Priority::High, async move { - let total_start = std::time::Instant::now(); - // WARN: Temporary workaround for #27283. - // We are not efficient with our memory usage per file, and use in excess of 64GB for a 10GB file - // Therefore, as a temporary workaround to prevent system freezes, we just bail before opening a file - // if it is too large - // 5GB seems to be more reasonable, peaking at ~16GB, while 6GB jumps up to >24GB which seems like a - // reasonable limit - { - const FILE_SIZE_MAX: u64 = 6 * 1024 * 1024 * 1024; // 6GB - if let Ok(Some(metadata)) = fs.metadata(&abs_path).await - && metadata.len >= FILE_SIZE_MAX + cx.background_executor() + .spawn_with_priority(Priority::High, async move { + // WARN: Temporary workaround for #27283. + // We are not efficient with our memory usage per file, and use in excess of 64GB for a 10GB file + // Therefore, as a temporary workaround to prevent system freezes, we just bail before opening a file + // if it is too large + // 5GB seems to be more reasonable, peaking at ~16GB, while 6GB jumps up to >24GB which seems like a + // reasonable limit { - anyhow::bail!("File is too large to load"); + const FILE_SIZE_MAX: u64 = 6 * 1024 * 1024 * 1024; // 6GB + if let Ok(Some(metadata)) = fs.metadata(&abs_path).await + && metadata.len >= FILE_SIZE_MAX + { + anyhow::bail!("File is too large to load"); + } } - } - let metadata_check_elapsed = total_start.elapsed(); - let load_start = std::time::Instant::now(); - let text = fs.load(&abs_path).await?; - let load_elapsed = load_start.elapsed(); + let text = fs.load(&abs_path).await?; - let worktree = this.upgrade().context("worktree was dropped")?; - let entry_await_start = std::time::Instant::now(); - let entry_result = entry.with_timeout(Duration::from_millis(5), &bg_executor).await; - let entry_await_elapsed = entry_await_start.elapsed(); + let worktree = this.upgrade().context("worktree was dropped")?; + let entry_result = entry + .with_timeout(Duration::from_millis(5), &bg_executor) + .await; - let entry_analyze_start = std::time::Instant::now(); - let file = match entry_result { - Ok(Ok(Some(entry))) => File::for_entry(entry, worktree), - Ok(Ok(None)) | Err(_) => { - let metadata = fs - .metadata(&abs_path) - .await - .with_context(|| { - format!("Loading metadata for excluded file {abs_path:?}") - })? - .with_context(|| { - format!("Excluded file {abs_path:?} got removed during loading") - })?; - Arc::new(File { - entry_id: None, - worktree, - path, - disk_state: DiskState::Present { - mtime: metadata.mtime, - }, - is_local: true, - is_private, - }) - }, - Ok(Err(e)) => Err(e)?, - }; - let entry_analyze_elapsed = entry_analyze_start.elapsed(); - let total_elapsed = total_start.elapsed(); + let file = match entry_result { + Ok(Ok(Some(entry))) => File::for_entry(entry, worktree), + Ok(Ok(None)) | Err(_) => { + let metadata = fs + .metadata(&abs_path) + .await + .with_context(|| { + format!("Loading metadata for excluded file {abs_path:?}") + })? + .with_context(|| { + format!("Excluded file {abs_path:?} got removed during loading") + })?; + Arc::new(File { + entry_id: None, + worktree, + path, + disk_state: DiskState::Present { + mtime: metadata.mtime, + }, + is_local: true, + is_private, + }) + } + Ok(Err(e)) => Err(e)?, + }; - log::info!( - "{:?} load_file timings: metadata check took: {}s, file load took: {}s, entry await took: {}s, entry analyze took: {}s, total took: {}s", - abs_path, - metadata_check_elapsed.as_secs_f64(), - load_elapsed.as_secs_f64(), - entry_await_elapsed.as_secs_f64(), - entry_analyze_elapsed.as_secs_f64(), - total_elapsed.as_secs_f64() - ); - - // save_hang_trace(&abs_path.file_name().map(|e| e.to_string_lossy().to_string()).unwrap_or("unknown".to_string()), &bg_executor); - - Ok(LoadedFile { file, text }) - }) + Ok(LoadedFile { file, text }) + }) } /// Find the lowest path in the worktree's datastructures that is an ancestor @@ -1727,30 +1709,16 @@ impl LocalWorktree { } else { vec![path.clone()] }; - let total_start = Instant::now(); let mut refresh = self.refresh_entries_for_paths(paths); // todo(lw): Hot foreground spawn cx.spawn(async move |this, cx| { - let refresh_start = Instant::now(); refresh.recv().await; - let refresh_elapsed = refresh_start.elapsed(); - let read_start = Instant::now(); let new_entry = this.read_with(cx, |this, _| { this.entry_for_path(&path).cloned().with_context(|| { format!("Could not find entry in worktree for {path:?} after refresh") }) })??; - let read_elapsed = read_start.elapsed(); - let total_elapsed = total_start.elapsed(); - - log::info!( - "{:?} refresh_entry timings: refresh await took: {}s, read entry took: {}s, total took: {}s", - path, - refresh_elapsed.as_secs_f64(), - read_elapsed.as_secs_f64(), - total_elapsed.as_secs_f64() - ); Ok(Some(new_entry)) }) @@ -3826,18 +3794,11 @@ impl BackgroundScanner { } async fn process_scan_request(&self, mut request: ScanRequest, scanning: bool) -> bool { - let total_start = std::time::Instant::now(); - log::debug!("rescanning paths {:?}", request.relative_paths); - request.relative_paths.sort_unstable(); - let load_paths_start = std::time::Instant::now(); self.forcibly_load_paths(&request.relative_paths).await; - let load_paths_elapsed = load_paths_start.elapsed(); - let canonicalize_start = std::time::Instant::now(); let root_path = self.state.lock().await.snapshot.abs_path.clone(); let root_canonical_path = self.fs.canonicalize(root_path.as_path()).await; - let canonicalize_elapsed = canonicalize_start.elapsed(); let root_canonical_path = match &root_canonical_path { Ok(path) => SanitizedPath::new(path), Err(err) => { @@ -3857,21 +3818,15 @@ impl BackgroundScanner { }) .collect::>(); - let update_scan_id_start = std::time::Instant::now(); - let scan_id_lock_elapsed; { - let lock_start = std::time::Instant::now(); let mut state = self.state.lock().await; - scan_id_lock_elapsed = lock_start.elapsed(); let is_idle = state.snapshot.completed_scan_id == state.snapshot.scan_id; state.snapshot.scan_id += 1; if is_idle { state.snapshot.completed_scan_id = state.snapshot.scan_id; } } - let update_scan_id_elapsed = update_scan_id_start.elapsed(); - let reload_entries_start = std::time::Instant::now(); self.reload_entries_for_paths( &root_path, &root_canonical_path, @@ -3880,26 +3835,8 @@ impl BackgroundScanner { None, ) .await; - let reload_entries_elapsed = reload_entries_start.elapsed(); - let send_status_start = std::time::Instant::now(); - let result = self.send_status_update(scanning, request.done).await; - let send_status_elapsed = send_status_start.elapsed(); - let total_elapsed = total_start.elapsed(); - - log::info!( - "{:?} process_scan_request timings: load paths took: {}s, canonicalize took: {}s, scan id lock took: {}s, update scan id took: {}s, reload entries took: {}s, send status took: {}s, total took: {}s", - request.relative_paths, - load_paths_elapsed.as_secs_f64(), - canonicalize_elapsed.as_secs_f64(), - scan_id_lock_elapsed.as_secs_f64(), - update_scan_id_elapsed.as_secs_f64(), - reload_entries_elapsed.as_secs_f64(), - send_status_elapsed.as_secs_f64(), - total_elapsed.as_secs_f64() - ); - - result + self.send_status_update(scanning, request.done).await } async fn process_events(&self, mut abs_paths: Vec) { @@ -4113,9 +4050,7 @@ impl BackgroundScanner { } async fn forcibly_load_paths(&self, paths: &[Arc]) -> bool { - let total_start = std::time::Instant::now(); let (scan_job_tx, scan_job_rx) = channel::unbounded(); - let enqueue_start = std::time::Instant::now(); { let mut state = self.state.lock().await; let root_path = state.snapshot.abs_path.clone(); @@ -4140,29 +4075,12 @@ impl BackgroundScanner { } drop(scan_job_tx); } - let enqueue_elapsed = enqueue_start.elapsed(); - let scan_dirs_start = std::time::Instant::now(); while let Ok(job) = scan_job_rx.recv().await { self.scan_dir(&job).await.log_err(); } - let scan_dirs_elapsed = scan_dirs_start.elapsed(); - let finalize_start = std::time::Instant::now(); - let result = !mem::take(&mut self.state.lock().await.paths_to_scan).is_empty(); - let finalize_elapsed = finalize_start.elapsed(); - let total_elapsed = total_start.elapsed(); - - log::info!( - "{:?} forcibly_load_paths timings: enqueue scan dirs took: {}s, scan dirs took: {}s, finalize took: {}s, total took: {}s", - paths, - enqueue_elapsed.as_secs_f64(), - scan_dirs_elapsed.as_secs_f64(), - finalize_elapsed.as_secs_f64(), - total_elapsed.as_secs_f64() - ); - - result + !mem::take(&mut self.state.lock().await.paths_to_scan).is_empty() } async fn scan_dirs( @@ -5697,37 +5615,3 @@ async fn discover_git_paths(dot_git_abs_path: &Arc, fs: &dyn Fs) -> (Arc

>(); - - let trace_path = paths::hang_traces_dir().join(&format!( - "hang-{}-{}.miniprof", - hang_time.format("%Y-%m-%d_%H-%M-%S"), - name - )); - - let Some(timings) = serde_json::to_string(&thread_timings) - .context("hang timings serialization") - .log_err() - else { - return; - }; - - std::fs::write(&trace_path, timings) - .context("hang trace file writing") - .log_err(); - - log::info!( - "hang detected, trace file saved at: {}", - trace_path.display() - ); -}