From 7204374719f4021ce06c25e7dd72b09a56923954 Mon Sep 17 00:00:00 2001 From: Aleksey Kladov Date: Thu, 30 Jul 2020 09:44:21 +0200 Subject: [PATCH] Report instructions in addition to time They hopefully will be more stable on CI --- Cargo.lock | 20 ++++++ crates/ra_prof/Cargo.toml | 1 + crates/ra_prof/src/lib.rs | 2 + crates/ra_prof/src/stop_watch.rs | 72 +++++++++++++++++++ .../rust-analyzer/src/cli/analysis_stats.rs | 40 +++++------ 5 files changed, 115 insertions(+), 20 deletions(-) create mode 100644 crates/ra_prof/src/stop_watch.rs diff --git a/Cargo.lock b/Cargo.lock index 3e685b7f17..e63dcc530f 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 6c214501e4..e41cb5f527 100644 --- a/crates/ra_prof/Cargo.toml +++ b/crates/ra_prof/Cargo.toml @@ -15,6 +15,7 @@ once_cell = "1.3.1" backtrace = { version = "0.3.44", optional = true } cfg-if = "0.1.10" libc = "0.2.73" +perf-event = "0.4" [features] cpu_profiler = [] diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs index ba5609703a..eb50965ae6 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 0000000000..54bfb05594 --- /dev/null +++ b/crates/ra_prof/src/stop_watch.rs @@ -0,0 +1,72 @@ +use crate::MemoryUsage; +use std::{ + fmt, + time::{Duration, Instant}, +}; + +pub struct StopWatch { + time: Instant, + counter: Option, + memory: Option, +} + +pub struct StopWatchSpan { + pub time: Duration, + pub instructions: Option, + pub memory: Option, +} + +impl StopWatch { + pub fn start() -> StopWatch { + let mut counter = perf_event::Builder::new().build().ok(); + if let Some(counter) = &mut counter { + let _ = counter.enable(); + } + let time = Instant::now(); + StopWatch { time, 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(); + let instructions = self.counter.as_mut().and_then(|it| it.read().ok()); + 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(()) + } +} + +// Unclear if we need this: +// https://github.com/jimblandy/perf-event/issues/8 +impl Drop for StopWatch { + fn drop(&mut self) { + if let Some(mut counter) = self.counter.take() { + let _ = counter.disable(); + } + } +} diff --git a/crates/rust-analyzer/src/cli/analysis_stats.rs b/crates/rust-analyzer/src/cli/analysis_stats.rs index cf0d82b62c..37b8337ef8 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); @@ -123,7 +124,7 @@ pub fn analysis_stats( }; 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 +134,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 +288,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);