From 64a8887a94da223de6858090ceddc8079a01aa35 Mon Sep 17 00:00:00 2001 From: Lukas Wirth Date: Sat, 17 Jun 2023 09:55:48 +0200 Subject: [PATCH 1/2] Add body lowering step, track time of each step separtely --- .../rust-analyzer/src/cli/analysis_stats.rs | 91 ++++++++++++++++++- crates/rust-analyzer/src/cli/flags.rs | 3 + 2 files changed, 89 insertions(+), 5 deletions(-) diff --git a/crates/rust-analyzer/src/cli/analysis_stats.rs b/crates/rust-analyzer/src/cli/analysis_stats.rs index e0767b39ef4..f384b7840c8 100644 --- a/crates/rust-analyzer/src/cli/analysis_stats.rs +++ b/crates/rust-analyzer/src/cli/analysis_stats.rs @@ -176,8 +176,11 @@ impl flags::AnalysisStats { shuffle(&mut rng, &mut bodies); } + if !self.skip_lowering { + self.run_body_lowering(db, &vfs, &bodies, verbosity); + } + if !self.skip_inference { - // FIXME: Consider running inference on all body kinds? self.run_inference(db, &vfs, &bodies, verbosity); } @@ -255,9 +258,11 @@ impl flags::AnalysisStats { } fail += 1; } - eprintln!("{:<20} {}", "Data layouts:", sw.elapsed()); + let data_layout_time = sw.elapsed(); + eprintln!("{:<20} {}", "Data layouts:", data_layout_time); eprintln!("Failed data layouts: {fail} ({}%)", percentage(fail, all)); report_metric("failed data layouts", fail, "#"); + report_metric("data layout time", data_layout_time.time.as_millis() as u64, "ms"); } fn run_const_eval(&self, db: &RootDatabase, consts: &[hir::Const], verbosity: Verbosity) { @@ -283,9 +288,11 @@ impl flags::AnalysisStats { } fail += 1; } - eprintln!("{:<20} {}", "Const evaluation:", sw.elapsed()); + let const_eval_time = sw.elapsed(); + eprintln!("{:<20} {}", "Const evaluation:", const_eval_time); eprintln!("Failed const evals: {fail} ({}%)", percentage(fail, all)); report_metric("failed const evals", fail, "#"); + report_metric("const eval time", const_eval_time.time.as_millis() as u64, "ms"); } fn run_mir_lowering(&self, db: &RootDatabase, bodies: &[DefWithBody], verbosity: Verbosity) { @@ -310,9 +317,11 @@ impl flags::AnalysisStats { } fail += 1; } - eprintln!("{:<20} {}", "MIR lowering:", sw.elapsed()); + let mir_lowering_time = sw.elapsed(); + eprintln!("{:<20} {}", "MIR lowering:", mir_lowering_time); eprintln!("Mir failed bodies: {fail} ({}%)", percentage(fail, all)); report_metric("mir failed bodies", fail, "#"); + report_metric("mir lowering time", mir_lowering_time.time.as_millis() as u64, "ms"); } fn run_inference( @@ -596,6 +605,7 @@ impl flags::AnalysisStats { } bar.finish_and_clear(); + let inference_time = inference_sw.elapsed(); eprintln!( " exprs: {}, ??ty: {} ({}%), ?ty: {} ({}%), !ty: {}", num_exprs, @@ -614,12 +624,83 @@ impl flags::AnalysisStats { percentage(num_pats_partially_unknown, num_pats), num_pat_type_mismatches ); + eprintln!("{:<20} {}", "Inference:", inference_time); report_metric("unknown type", num_exprs_unknown, "#"); report_metric("type mismatches", num_expr_type_mismatches, "#"); report_metric("pattern unknown type", num_pats_unknown, "#"); report_metric("pattern type mismatches", num_pat_type_mismatches, "#"); + report_metric("inference time", inference_time.time.as_millis() as u64, "ms"); + } - eprintln!("{:<20} {}", "Inference:", inference_sw.elapsed()); + fn run_body_lowering( + &self, + db: &RootDatabase, + vfs: &Vfs, + bodies: &[DefWithBody], + verbosity: Verbosity, + ) { + let mut bar = match verbosity { + Verbosity::Quiet | Verbosity::Spammy => ProgressReport::hidden(), + _ if self.parallel || self.output.is_some() => ProgressReport::hidden(), + _ => ProgressReport::new(bodies.len() as u64), + }; + + let mut sw = self.stop_watch(); + bar.tick(); + for &body_id in bodies { + let name = body_id.name(db).unwrap_or_else(Name::missing); + let module = body_id.module(db); + let full_name = || { + module + .krate() + .display_name(db) + .map(|it| it.canonical_name().to_string()) + .into_iter() + .chain( + module + .path_to_root(db) + .into_iter() + .filter_map(|it| it.name(db)) + .rev() + .chain(Some(name.clone())) + .map(|it| it.display(db).to_string()), + ) + .join("::") + }; + if let Some(only_name) = self.only.as_deref() { + if name.display(db).to_string() != only_name && full_name() != only_name { + continue; + } + } + let mut msg = format!("processing: {}", full_name()); + if verbosity.is_verbose() { + let source = match body_id { + DefWithBody::Function(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Static(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Const(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Variant(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::InTypeConst(_) => unimplemented!(), + }; + if let Some(src) = source { + let original_file = src.file_id.original_file(db); + let path = vfs.file_path(original_file); + let syntax_range = src.value.text_range(); + format_to!(msg, " ({} {:?})", path, syntax_range); + } + } + if verbosity.is_spammy() { + bar.println(msg.to_string()); + } + bar.set_message(&msg); + let (body, sm) = db.body_with_source_map(body_id.into()); + // endregion:patterns + bar.inc(1); + } + + bar.finish_and_clear(); + let body_lowering_time = sw.elapsed(); + eprintln!("{:<20} {}", "Body lowering:", body_lowering_time); + report_metric("body lowering time", body_lowering_time.time.as_millis() as u64, "ms"); } fn stop_watch(&self) -> StopWatch { diff --git a/crates/rust-analyzer/src/cli/flags.rs b/crates/rust-analyzer/src/cli/flags.rs index 923be8b0728..208a4e6ecd9 100644 --- a/crates/rust-analyzer/src/cli/flags.rs +++ b/crates/rust-analyzer/src/cli/flags.rs @@ -78,6 +78,8 @@ xflags::xflags! { optional --disable-build-scripts /// Don't use expand proc macros. optional --disable-proc-macros + /// Skip body lowering. + optional --skip-lowering /// Skip type inference. optional --skip-inference /// Skip lowering to mir @@ -180,6 +182,7 @@ pub struct AnalysisStats { pub parallel: bool, pub memory_usage: bool, pub source_stats: bool, + pub skip_lowering: bool, pub skip_inference: bool, pub skip_mir_stats: bool, pub skip_data_layout: bool, From b5e0452c71807d5c270e21534a03ce3d7ef66b61 Mon Sep 17 00:00:00 2001 From: Lukas Wirth Date: Sat, 17 Jun 2023 10:34:44 +0200 Subject: [PATCH 2/2] Lazy progress reporting --- .../rust-analyzer/src/cli/analysis_stats.rs | 104 ++++++++++-------- .../rust-analyzer/src/cli/progress_report.rs | 41 +++---- 2 files changed, 75 insertions(+), 70 deletions(-) diff --git a/crates/rust-analyzer/src/cli/analysis_stats.rs b/crates/rust-analyzer/src/cli/analysis_stats.rs index f384b7840c8..01bc0d77dd5 100644 --- a/crates/rust-analyzer/src/cli/analysis_stats.rs +++ b/crates/rust-analyzer/src/cli/analysis_stats.rs @@ -29,7 +29,6 @@ use profile::{Bytes, StopWatch}; use project_model::{CargoConfig, ProjectManifest, ProjectWorkspace, RustLibSource}; use rayon::prelude::*; use rustc_hash::FxHashSet; -use stdx::format_to; use syntax::{AstNode, SyntaxNode}; use vfs::{AbsPathBuf, Vfs, VfsPath}; @@ -241,8 +240,10 @@ impl flags::AnalysisStats { continue; } all += 1; - let Err(e) = db.layout_of_adt(hir_def::AdtId::from(a).into(), Substitution::empty(Interner), a.krate(db).into()) else { - continue; + let Err(e) + = db.layout_of_adt(hir_def::AdtId::from(a).into(), Substitution::empty(Interner), a.krate(db).into()) + else { + continue }; if verbosity.is_spammy() { let full_name = a @@ -363,7 +364,7 @@ impl flags::AnalysisStats { for &body_id in bodies { let name = body_id.name(db).unwrap_or_else(Name::missing); let module = body_id.module(db); - let full_name = || { + let full_name = move || { module .krate() .display_name(db) @@ -375,7 +376,7 @@ impl flags::AnalysisStats { .into_iter() .filter_map(|it| it.name(db)) .rev() - .chain(Some(name.clone())) + .chain(Some(body_id.name(db).unwrap_or_else(Name::missing))) .map(|it| it.display(db).to_string()), ) .join("::") @@ -385,26 +386,31 @@ impl flags::AnalysisStats { continue; } } - let mut msg = format!("processing: {}", full_name()); - if verbosity.is_verbose() { - let source = match body_id { - DefWithBody::Function(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::Static(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::Const(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::Variant(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::InTypeConst(_) => unimplemented!(), - }; - if let Some(src) = source { - let original_file = src.file_id.original_file(db); - let path = vfs.file_path(original_file); - let syntax_range = src.value.text_range(); - format_to!(msg, " ({} {:?})", path, syntax_range); + let msg = move || { + if verbosity.is_verbose() { + let source = match body_id { + DefWithBody::Function(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Static(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Const(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Variant(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::InTypeConst(_) => unimplemented!(), + }; + if let Some(src) = source { + let original_file = src.file_id.original_file(db); + let path = vfs.file_path(original_file); + let syntax_range = src.value.text_range(); + format!("processing: {} ({} {:?})", full_name(), path, syntax_range) + } else { + format!("processing: {}", full_name()) + } + } else { + format!("processing: {}", full_name()) } - } + }; if verbosity.is_spammy() { - bar.println(msg.to_string()); + bar.println(msg()); } - bar.set_message(&msg); + bar.set_message(msg); let (body, sm) = db.body_with_source_map(body_id.into()); let inference_result = db.infer(body_id.into()); @@ -641,16 +647,15 @@ impl flags::AnalysisStats { ) { let mut bar = match verbosity { Verbosity::Quiet | Verbosity::Spammy => ProgressReport::hidden(), - _ if self.parallel || self.output.is_some() => ProgressReport::hidden(), + _ if self.output.is_some() => ProgressReport::hidden(), _ => ProgressReport::new(bodies.len() as u64), }; let mut sw = self.stop_watch(); bar.tick(); for &body_id in bodies { - let name = body_id.name(db).unwrap_or_else(Name::missing); let module = body_id.module(db); - let full_name = || { + let full_name = move || { module .krate() .display_name(db) @@ -662,38 +667,45 @@ impl flags::AnalysisStats { .into_iter() .filter_map(|it| it.name(db)) .rev() - .chain(Some(name.clone())) + .chain(Some(body_id.name(db).unwrap_or_else(Name::missing))) .map(|it| it.display(db).to_string()), ) .join("::") }; if let Some(only_name) = self.only.as_deref() { - if name.display(db).to_string() != only_name && full_name() != only_name { + if body_id.name(db).unwrap_or_else(Name::missing).display(db).to_string() + != only_name + && full_name() != only_name + { continue; } } - let mut msg = format!("processing: {}", full_name()); - if verbosity.is_verbose() { - let source = match body_id { - DefWithBody::Function(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::Static(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::Const(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::Variant(it) => it.source(db).map(|it| it.syntax().cloned()), - DefWithBody::InTypeConst(_) => unimplemented!(), - }; - if let Some(src) = source { - let original_file = src.file_id.original_file(db); - let path = vfs.file_path(original_file); - let syntax_range = src.value.text_range(); - format_to!(msg, " ({} {:?})", path, syntax_range); + let msg = move || { + if verbosity.is_verbose() { + let source = match body_id { + DefWithBody::Function(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Static(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Const(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::Variant(it) => it.source(db).map(|it| it.syntax().cloned()), + DefWithBody::InTypeConst(_) => unimplemented!(), + }; + if let Some(src) = source { + let original_file = src.file_id.original_file(db); + let path = vfs.file_path(original_file); + let syntax_range = src.value.text_range(); + format!("processing: {} ({} {:?})", full_name(), path, syntax_range) + } else { + format!("processing: {}", full_name()) + } + } else { + format!("processing: {}", full_name()) } - } + }; if verbosity.is_spammy() { - bar.println(msg.to_string()); + bar.println(msg()); } - bar.set_message(&msg); - let (body, sm) = db.body_with_source_map(body_id.into()); - // endregion:patterns + bar.set_message(msg); + db.body_with_source_map(body_id.into()); bar.inc(1); } diff --git a/crates/rust-analyzer/src/cli/progress_report.rs b/crates/rust-analyzer/src/cli/progress_report.rs index d459dd115ce..c236f9c7fe1 100644 --- a/crates/rust-analyzer/src/cli/progress_report.rs +++ b/crates/rust-analyzer/src/cli/progress_report.rs @@ -4,41 +4,29 @@ use std::io::{self, Write}; /// A Simple ASCII Progress Bar -pub(crate) struct ProgressReport { +pub(crate) struct ProgressReport<'a> { curr: f32, text: String, hidden: bool, len: u64, pos: u64, - msg: String, + msg: Option String + 'a>>, } -impl ProgressReport { - pub(crate) fn new(len: u64) -> ProgressReport { - ProgressReport { - curr: 0.0, - text: String::new(), - hidden: false, - len, - pos: 0, - msg: String::new(), - } +impl<'a> ProgressReport<'a> { + pub(crate) fn new(len: u64) -> ProgressReport<'a> { + ProgressReport { curr: 0.0, text: String::new(), hidden: false, len, pos: 0, msg: None } } - pub(crate) fn hidden() -> ProgressReport { - ProgressReport { - curr: 0.0, - text: String::new(), - hidden: true, - len: 0, - pos: 0, - msg: String::new(), - } + pub(crate) fn hidden() -> ProgressReport<'a> { + ProgressReport { curr: 0.0, text: String::new(), hidden: true, len: 0, pos: 0, msg: None } } - pub(crate) fn set_message(&mut self, msg: &str) { - self.msg = msg.to_string(); + pub(crate) fn set_message(&mut self, msg: impl Fn() -> String + 'a) { + if !self.hidden { + self.msg = Some(Box::new(msg)); + } self.tick(); } @@ -67,7 +55,12 @@ impl ProgressReport { return; } let percent = (self.curr * 100.0) as u32; - let text = format!("{}/{} {percent:3>}% {}", self.pos, self.len, self.msg); + let text = format!( + "{}/{} {percent:3>}% {}", + self.pos, + self.len, + self.msg.as_ref().map_or_else(|| String::new(), |it| it()) + ); self.update_text(&text); }