Report instructions in addition to time

They hopefully will be more stable on CI
This commit is contained in:
Aleksey Kladov 2020-07-30 09:44:21 +02:00
parent 4bab553029
commit 7204374719
5 changed files with 115 additions and 20 deletions

20
Cargo.lock generated
View file

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

View file

@ -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 = []

View file

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

View file

@ -0,0 +1,72 @@
use crate::MemoryUsage;
use std::{
fmt,
time::{Duration, Instant},
};
pub struct StopWatch {
time: Instant,
counter: Option<perf_event::Counter>,
memory: Option<MemoryUsage>,
}
pub struct StopWatchSpan {
pub time: Duration,
pub instructions: Option<u64>,
pub memory: Option<MemoryUsage>,
}
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();
}
}
}

View file

@ -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>(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);