Merge #5581

5581: Measure instructions in addition to time r=matklad a=matklad

bors r+
🤖

Co-authored-by: Aleksey Kladov <aleksey.kladov@gmail.com>

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

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

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.

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<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 {
+        #[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(())
+    }
+}

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>(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());
+    eprintln!("Database loaded {}", db_load_sw.elapsed());
-    let analysis_time = Instant::now();
+
+    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_sw.elapsed());
-    eprintln!("Item Collection: {:?}, {}", analysis_time.elapsed(), item_collection_memory);
 
     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!(
+        eprintln!("Parallel Inference: {}", inference_sw.elapsed());
-            "Parallel Inference: {:?}, {}",
-            inference_time.elapsed(),
-            ra_prof::memory_usage()
-        );
     }
 
-    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();
+    eprintln!("Inference: {}", inference_sw.elapsed());
-    let total_memory = ra_prof::memory_usage();
-    eprintln!("Inference: {:?}, {}", inference_time, total_memory - item_collection_memory);
 
-    let analysis_time = analysis_time.elapsed();
+    let total_span = analysis_sw.elapsed();
-    eprintln!("Total: {:?}, {}", analysis_time, total_memory);
+    eprintln!("Total: {}", total_span);
-    report_metric("total time", analysis_time.as_millis() as u64, "ms");
+    report_metric("total time", total_span.time.as_millis() as u64, "ms");
-    report_metric("total memory", total_memory.allocated.megabytes() as u64, "MB");
+    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);