aboutsummaryrefslogtreecommitdiff
path: root/crates
diff options
context:
space:
mode:
authorbors[bot] <26634292+bors[bot]@users.noreply.github.com>2020-07-30 09:44:31 +0100
committerGitHub <[email protected]>2020-07-30 09:44:31 +0100
commit72ffd851dd5b0fcdf3aa072131ba11009878b4ae (patch)
tree4b35f683a6bfb70fa9e1db3b22371ebcde0e7d99 /crates
parentc8573c418cb5240e0b60e93b15978b00e3ff0683 (diff)
parentf22af66c3763c4b2a9d16621473cb6979fb2f36d (diff)
Merge #5581
5581: Measure instructions in addition to time r=matklad a=matklad bors r+ 🤖 Co-authored-by: Aleksey Kladov <[email protected]>
Diffstat (limited to 'crates')
-rw-r--r--crates/ra_prof/Cargo.toml3
-rw-r--r--crates/ra_prof/src/lib.rs2
-rw-r--r--crates/ra_prof/src/stop_watch.rs79
-rw-r--r--crates/rust-analyzer/src/cli/analysis_stats.rs41
4 files changed, 105 insertions, 20 deletions
diff --git a/crates/ra_prof/Cargo.toml b/crates/ra_prof/Cargo.toml
index 6c214501e..c82b9f76d 100644
--- a/crates/ra_prof/Cargo.toml
+++ b/crates/ra_prof/Cargo.toml
@@ -16,6 +16,9 @@ backtrace = { version = "0.3.44", optional = true }
16cfg-if = "0.1.10" 16cfg-if = "0.1.10"
17libc = "0.2.73" 17libc = "0.2.73"
18 18
19[target.'cfg(target_os = "linux")'.dependencies]
20perf-event = "0.4"
21
19[features] 22[features]
20cpu_profiler = [] 23cpu_profiler = []
21 24
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
index ba5609703..eb50965ae 100644
--- a/crates/ra_prof/src/lib.rs
+++ b/crates/ra_prof/src/lib.rs
@@ -1,5 +1,6 @@
1//! A collection of tools for profiling rust-analyzer. 1//! A collection of tools for profiling rust-analyzer.
2 2
3mod stop_watch;
3mod memory_usage; 4mod memory_usage;
4#[cfg(feature = "cpu_profiler")] 5#[cfg(feature = "cpu_profiler")]
5mod google_cpu_profiler; 6mod google_cpu_profiler;
@@ -11,6 +12,7 @@ use std::cell::RefCell;
11pub use crate::{ 12pub use crate::{
12 hprof::{init, init_from, profile}, 13 hprof::{init, init_from, profile},
13 memory_usage::{Bytes, MemoryUsage}, 14 memory_usage::{Bytes, MemoryUsage},
15 stop_watch::{StopWatch, StopWatchSpan},
14}; 16};
15 17
16/// Prints backtrace to stderr, useful for debugging. 18/// 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 000000000..8b8ec25a5
--- /dev/null
+++ b/crates/ra_prof/src/stop_watch.rs
@@ -0,0 +1,79 @@
1//! Like `std::time::Instant`, but also measures memory & CPU cycles.
2use std::{
3 fmt,
4 time::{Duration, Instant},
5};
6
7use crate::MemoryUsage;
8
9pub struct StopWatch {
10 time: Instant,
11 #[cfg(target_os = "linux")]
12 counter: Option<perf_event::Counter>,
13 memory: Option<MemoryUsage>,
14}
15
16pub struct StopWatchSpan {
17 pub time: Duration,
18 pub instructions: Option<u64>,
19 pub memory: Option<MemoryUsage>,
20}
21
22impl StopWatch {
23 pub fn start() -> StopWatch {
24 #[cfg(target_os = "linux")]
25 let counter = {
26 let mut counter = perf_event::Builder::new().build().ok();
27 if let Some(counter) = &mut counter {
28 let _ = counter.enable();
29 }
30 counter
31 };
32 let time = Instant::now();
33 StopWatch {
34 time,
35 #[cfg(target_os = "linux")]
36 counter,
37 memory: None,
38 }
39 }
40 pub fn memory(mut self, yes: bool) -> StopWatch {
41 if yes {
42 self.memory = Some(MemoryUsage::current());
43 }
44 self
45 }
46 pub fn elapsed(&mut self) -> StopWatchSpan {
47 let time = self.time.elapsed();
48
49 #[cfg(target_os = "linux")]
50 let instructions = self.counter.as_mut().and_then(|it| it.read().ok());
51 #[cfg(not(target_os = "linux"))]
52 let instructions = None;
53
54 let memory = self.memory.map(|it| MemoryUsage::current() - it);
55 StopWatchSpan { time, instructions, memory }
56 }
57}
58
59impl fmt::Display for StopWatchSpan {
60 fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
61 write!(f, "{:.2?}", self.time)?;
62 if let Some(mut instructions) = self.instructions {
63 let mut prefix = "";
64 if instructions > 10000 {
65 instructions /= 1000;
66 prefix = "k"
67 }
68 if instructions > 10000 {
69 instructions /= 1000;
70 prefix = "m"
71 }
72 write!(f, ", {}{}i", instructions, prefix)?;
73 }
74 if let Some(memory) = self.memory {
75 write!(f, ", {}", memory)?;
76 }
77 Ok(())
78 }
79}
diff --git a/crates/rust-analyzer/src/cli/analysis_stats.rs b/crates/rust-analyzer/src/cli/analysis_stats.rs
index cf0d82b62..73ec3204b 100644
--- a/crates/rust-analyzer/src/cli/analysis_stats.rs
+++ b/crates/rust-analyzer/src/cli/analysis_stats.rs
@@ -3,7 +3,7 @@
3 3
4use std::{ 4use std::{
5 path::Path, 5 path::Path,
6 time::{Instant, SystemTime, UNIX_EPOCH}, 6 time::{SystemTime, UNIX_EPOCH},
7}; 7};
8 8
9use hir::{ 9use hir::{
@@ -29,6 +29,7 @@ use crate::{
29 }, 29 },
30 print_memory_usage, 30 print_memory_usage,
31}; 31};
32use ra_prof::StopWatch;
32 33
33/// Need to wrap Snapshot to provide `Clone` impl for `map_with` 34/// Need to wrap Snapshot to provide `Clone` impl for `map_with`
34struct Snap<DB>(DB); 35struct Snap<DB>(DB);
@@ -54,11 +55,12 @@ pub fn analysis_stats(
54 Rand32::new(seed) 55 Rand32::new(seed)
55 }; 56 };
56 57
57 let db_load_time = Instant::now(); 58 let mut db_load_sw = StopWatch::start().memory(memory_usage);
58 let (host, vfs) = load_cargo(path, load_output_dirs, with_proc_macro)?; 59 let (host, vfs) = load_cargo(path, load_output_dirs, with_proc_macro)?;
59 let db = host.raw_database(); 60 let db = host.raw_database();
60 eprintln!("Database loaded {:?}", db_load_time.elapsed()); 61 eprintln!("Database loaded {}", db_load_sw.elapsed());
61 let analysis_time = Instant::now(); 62
63 let mut analysis_sw = StopWatch::start().memory(memory_usage);
62 let mut num_crates = 0; 64 let mut num_crates = 0;
63 let mut visited_modules = FxHashSet::default(); 65 let mut visited_modules = FxHashSet::default();
64 let mut visit_queue = Vec::new(); 66 let mut visit_queue = Vec::new();
@@ -110,8 +112,7 @@ pub fn analysis_stats(
110 eprintln!("Total modules found: {}", visited_modules.len()); 112 eprintln!("Total modules found: {}", visited_modules.len());
111 eprintln!("Total declarations: {}", num_decls); 113 eprintln!("Total declarations: {}", num_decls);
112 eprintln!("Total functions: {}", funcs.len()); 114 eprintln!("Total functions: {}", funcs.len());
113 let item_collection_memory = ra_prof::memory_usage(); 115 eprintln!("Item Collection: {}", analysis_sw.elapsed());
114 eprintln!("Item Collection: {:?}, {}", analysis_time.elapsed(), item_collection_memory);
115 116
116 if randomize { 117 if randomize {
117 shuffle(&mut rng, &mut funcs); 118 shuffle(&mut rng, &mut funcs);
@@ -119,11 +120,12 @@ pub fn analysis_stats(
119 120
120 let mut bar = match verbosity { 121 let mut bar = match verbosity {
121 Verbosity::Quiet | Verbosity::Spammy => ProgressReport::hidden(), 122 Verbosity::Quiet | Verbosity::Spammy => ProgressReport::hidden(),
123 _ if parallel => ProgressReport::hidden(),
122 _ => ProgressReport::new(funcs.len() as u64), 124 _ => ProgressReport::new(funcs.len() as u64),
123 }; 125 };
124 126
125 if parallel { 127 if parallel {
126 let inference_time = Instant::now(); 128 let mut inference_sw = StopWatch::start().memory(memory_usage);
127 let snap = Snap(db.snapshot()); 129 let snap = Snap(db.snapshot());
128 funcs 130 funcs
129 .par_iter() 131 .par_iter()
@@ -133,14 +135,10 @@ pub fn analysis_stats(
133 snap.0.infer(f_id.into()); 135 snap.0.infer(f_id.into());
134 }) 136 })
135 .count(); 137 .count();
136 eprintln!( 138 eprintln!("Parallel Inference: {}", inference_sw.elapsed());
137 "Parallel Inference: {:?}, {}",
138 inference_time.elapsed(),
139 ra_prof::memory_usage()
140 );
141 } 139 }
142 140
143 let inference_time = Instant::now(); 141 let mut inference_sw = StopWatch::start().memory(memory_usage);
144 bar.tick(); 142 bar.tick();
145 let mut num_exprs = 0; 143 let mut num_exprs = 0;
146 let mut num_exprs_unknown = 0; 144 let mut num_exprs_unknown = 0;
@@ -291,14 +289,17 @@ pub fn analysis_stats(
291 eprintln!("Type mismatches: {}", num_type_mismatches); 289 eprintln!("Type mismatches: {}", num_type_mismatches);
292 report_metric("type mismatches", num_type_mismatches, "#"); 290 report_metric("type mismatches", num_type_mismatches, "#");
293 291
294 let inference_time = inference_time.elapsed(); 292 eprintln!("Inference: {}", inference_sw.elapsed());
295 let total_memory = ra_prof::memory_usage();
296 eprintln!("Inference: {:?}, {}", inference_time, total_memory - item_collection_memory);
297 293
298 let analysis_time = analysis_time.elapsed(); 294 let total_span = analysis_sw.elapsed();
299 eprintln!("Total: {:?}, {}", analysis_time, total_memory); 295 eprintln!("Total: {}", total_span);
300 report_metric("total time", analysis_time.as_millis() as u64, "ms"); 296 report_metric("total time", total_span.time.as_millis() as u64, "ms");
301 report_metric("total memory", total_memory.allocated.megabytes() as u64, "MB"); 297 if let Some(instructions) = total_span.instructions {
298 report_metric("total time", instructions, "#instr");
299 }
300 if let Some(memory) = total_span.memory {
301 report_metric("total memory", memory.allocated.megabytes() as u64, "MB");
302 }
302 303
303 if memory_usage { 304 if memory_usage {
304 print_memory_usage(host, vfs); 305 print_memory_usage(host, vfs);