remove logs

This commit is contained in:
kate
2025-12-08 17:11:54 +01:00
parent 22f37e27fe
commit d495f4f5a1
7 changed files with 55 additions and 287 deletions

1
Cargo.lock generated
View File

@@ -20817,7 +20817,6 @@ version = "0.1.0"
dependencies = [
"anyhow",
"async-lock 2.8.0",
"chrono",
"clock",
"collections",
"fs",

View File

@@ -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<Instant> = 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<AppCell>);
@@ -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");

View File

@@ -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<Result<Entity<Buffer>>> {
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::<Buffer>()?;
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
})

View File

@@ -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<proto::OpenBufferByPath>,
mut cx: AsyncApp,
) -> Result<proto::OpenBufferResponse> {
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(),
})

View File

@@ -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 {

View File

@@ -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"] }

View File

@@ -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::<Vec<_>>();
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<PathBuf>) {
@@ -4113,9 +4050,7 @@ impl BackgroundScanner {
}
async fn forcibly_load_paths(&self, paths: &[Arc<RelPath>]) -> 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<Path>, fs: &dyn Fs) -> (Arc<P
};
(repository_dir_abs_path, common_dir_abs_path)
}
fn save_hang_trace(name: &str, background_executor: &gpui::BackgroundExecutor) {
let hang_time = chrono::Local::now();
let thread_timings = background_executor.dispatcher.get_all_timings();
let thread_timings = thread_timings
.into_iter()
.map(|mut timings| {
SerializedThreadTaskTimings::convert(*STARTUP_TIME.get().unwrap(), timings)
})
.collect::<Vec<_>>();
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()
);
}