diff --git a/Cargo.lock b/Cargo.lock index 3e685b7f1799..e63dcc530fad 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -840,6 +840,25 @@ version = "2.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d4fd5641d01c8f18a23da7b6fe29298ff4b55afcccdf78973b24cf3175fee32e" +[[package]] +name = "perf-event" +version = "0.4.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0cb38a2f363560fb3cfcb47f28848b245a41c7e0d63e0b190918b712b6bf6803" +dependencies = [ + "libc", + "perf-event-open-sys", +] + +[[package]] +name = "perf-event-open-sys" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "95db63e37862bc1b842135d2234ef9418f222cc660c6752f45e7cf9ddfb97f96" +dependencies = [ + "libc", +] + [[package]] name = "petgraph" version = "0.5.1" @@ -1126,6 +1145,7 @@ dependencies = [ "cfg-if", "libc", "once_cell", + "perf-event", "ra_arena", ] diff --git a/crates/ra_prof/Cargo.toml b/crates/ra_prof/Cargo.toml index 6c214501e4aa..c82b9f76d481 100644 --- a/crates/ra_prof/Cargo.toml +++ b/crates/ra_prof/Cargo.toml @@ -16,6 +16,9 @@ backtrace = { version = "0.3.44", optional = true } cfg-if = "0.1.10" libc = "0.2.73" +[target.'cfg(target_os = "linux")'.dependencies] +perf-event = "0.4" + [features] cpu_profiler = [] diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs index ba5609703a6e..eb50965ae6f0 100644 --- a/crates/ra_prof/src/lib.rs +++ b/crates/ra_prof/src/lib.rs @@ -1,5 +1,6 @@ //! A collection of tools for profiling rust-analyzer. +mod stop_watch; mod memory_usage; #[cfg(feature = "cpu_profiler")] mod google_cpu_profiler; @@ -11,6 +12,7 @@ use std::cell::RefCell; pub use crate::{ hprof::{init, init_from, profile}, memory_usage::{Bytes, MemoryUsage}, + stop_watch::{StopWatch, StopWatchSpan}, }; /// Prints backtrace to stderr, useful for debugging. diff --git a/crates/ra_prof/src/stop_watch.rs b/crates/ra_prof/src/stop_watch.rs new file mode 100644 index 000000000000..8b8ec25a5fe0 --- /dev/null +++ b/crates/ra_prof/src/stop_watch.rs @@ -0,0 +1,79 @@ +//! Like `std::time::Instant`, but also measures memory & CPU cycles. +use std::{ + fmt, + time::{Duration, Instant}, +}; + +use crate::MemoryUsage; + +pub struct StopWatch { + time: Instant, + #[cfg(target_os = "linux")] + counter: Option, + memory: Option, +} + +pub struct StopWatchSpan { + pub time: Duration, + pub instructions: Option, + pub memory: Option, +} + +impl StopWatch { + pub fn start() -> StopWatch { + #[cfg(target_os = "linux")] + let counter = { + let mut counter = perf_event::Builder::new().build().ok(); + if let Some(counter) = &mut counter { + let _ = counter.enable(); + } + counter + }; + let time = Instant::now(); + StopWatch { + time, + #[cfg(target_os = "linux")] + counter, + memory: None, + } + } + pub fn memory(mut self, yes: bool) -> StopWatch { + if yes { + self.memory = Some(MemoryUsage::current()); + } + self + } + pub fn elapsed(&mut self) -> StopWatchSpan { + let time = self.time.elapsed(); + + #[cfg(target_os = "linux")] + let instructions = self.counter.as_mut().and_then(|it| it.read().ok()); + #[cfg(not(target_os = "linux"))] + let instructions = None; + + let memory = self.memory.map(|it| MemoryUsage::current() - it); + StopWatchSpan { time, instructions, memory } + } +} + +impl fmt::Display for StopWatchSpan { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{:.2?}", self.time)?; + if let Some(mut instructions) = self.instructions { + let mut prefix = ""; + if instructions > 10000 { + instructions /= 1000; + prefix = "k" + } + if instructions > 10000 { + instructions /= 1000; + prefix = "m" + } + write!(f, ", {}{}i", instructions, prefix)?; + } + if let Some(memory) = self.memory { + write!(f, ", {}", memory)?; + } + Ok(()) + } +} diff --git a/crates/rust-analyzer/src/cli/analysis_stats.rs b/crates/rust-analyzer/src/cli/analysis_stats.rs index cf0d82b62c1f..73ec3204b79c 100644 --- a/crates/rust-analyzer/src/cli/analysis_stats.rs +++ b/crates/rust-analyzer/src/cli/analysis_stats.rs @@ -3,7 +3,7 @@ use std::{ path::Path, - time::{Instant, SystemTime, UNIX_EPOCH}, + time::{SystemTime, UNIX_EPOCH}, }; use hir::{ @@ -29,6 +29,7 @@ use crate::{ }, print_memory_usage, }; +use ra_prof::StopWatch; /// Need to wrap Snapshot to provide `Clone` impl for `map_with` struct Snap(DB); @@ -54,11 +55,12 @@ pub fn analysis_stats( Rand32::new(seed) }; - let db_load_time = Instant::now(); + let mut db_load_sw = StopWatch::start().memory(memory_usage); let (host, vfs) = load_cargo(path, load_output_dirs, with_proc_macro)?; let db = host.raw_database(); - eprintln!("Database loaded {:?}", db_load_time.elapsed()); - let analysis_time = Instant::now(); + eprintln!("Database loaded {}", db_load_sw.elapsed()); + + let mut analysis_sw = StopWatch::start().memory(memory_usage); let mut num_crates = 0; let mut visited_modules = FxHashSet::default(); let mut visit_queue = Vec::new(); @@ -110,8 +112,7 @@ pub fn analysis_stats( eprintln!("Total modules found: {}", visited_modules.len()); eprintln!("Total declarations: {}", num_decls); eprintln!("Total functions: {}", funcs.len()); - let item_collection_memory = ra_prof::memory_usage(); - eprintln!("Item Collection: {:?}, {}", analysis_time.elapsed(), item_collection_memory); + eprintln!("Item Collection: {}", analysis_sw.elapsed()); if randomize { shuffle(&mut rng, &mut funcs); @@ -119,11 +120,12 @@ pub fn analysis_stats( let mut bar = match verbosity { Verbosity::Quiet | Verbosity::Spammy => ProgressReport::hidden(), + _ if parallel => ProgressReport::hidden(), _ => ProgressReport::new(funcs.len() as u64), }; if parallel { - let inference_time = Instant::now(); + let mut inference_sw = StopWatch::start().memory(memory_usage); let snap = Snap(db.snapshot()); funcs .par_iter() @@ -133,14 +135,10 @@ pub fn analysis_stats( snap.0.infer(f_id.into()); }) .count(); - eprintln!( - "Parallel Inference: {:?}, {}", - inference_time.elapsed(), - ra_prof::memory_usage() - ); + eprintln!("Parallel Inference: {}", inference_sw.elapsed()); } - let inference_time = Instant::now(); + let mut inference_sw = StopWatch::start().memory(memory_usage); bar.tick(); let mut num_exprs = 0; let mut num_exprs_unknown = 0; @@ -291,14 +289,17 @@ pub fn analysis_stats( eprintln!("Type mismatches: {}", num_type_mismatches); report_metric("type mismatches", num_type_mismatches, "#"); - let inference_time = inference_time.elapsed(); - let total_memory = ra_prof::memory_usage(); - eprintln!("Inference: {:?}, {}", inference_time, total_memory - item_collection_memory); + eprintln!("Inference: {}", inference_sw.elapsed()); - let analysis_time = analysis_time.elapsed(); - eprintln!("Total: {:?}, {}", analysis_time, total_memory); - report_metric("total time", analysis_time.as_millis() as u64, "ms"); - report_metric("total memory", total_memory.allocated.megabytes() as u64, "MB"); + let total_span = analysis_sw.elapsed(); + eprintln!("Total: {}", total_span); + report_metric("total time", total_span.time.as_millis() as u64, "ms"); + if let Some(instructions) = total_span.instructions { + report_metric("total time", instructions, "#instr"); + } + if let Some(memory) = total_span.memory { + report_metric("total memory", memory.allocated.megabytes() as u64, "MB"); + } if memory_usage { print_memory_usage(host, vfs);