Extend analysis-stats a bit

This adds some tools helpful when debugging nondeterminism in analysis-stats:
 - a `--randomize` option that analyses everything in random order
 - a `-vv` option that prints even more detail

Also add a debug log if Chalk fuel is exhausted (which would be a source of
nondeterminism, but didn't happen in my tests).

I found one source of nondeterminism (rust-lang/chalk#331), but there are still
other cases remaining.

Author: flodiebold

Cargo.lock

@@ -31,3 +31,8 @@ opt-level = 0
 
 [patch.'crates-io']
 # rowan = { path = "../rowan" }
+
+[patch.'https://github.com/rust-lang/chalk.git']
+# chalk-solve = { path = "../chalk/chalk-solve" }
+# chalk-rust-ir = { path = "../chalk/chalk-rust-ir" }
+# chalk-ir = { path = "../chalk/chalk-ir" }

Cargo.toml

@@ -6,8 +6,10 @@ authors = ["rust-analyzer developers"]
 publish = false
 
 [dependencies]
+itertools = "0.8.0"
 pico-args = "0.3.0"
 env_logger = { version = "0.7.1", default-features = false }
+rand = { version = "0.7.0", features = ["small_rng"] }
 
 ra_syntax = { path = "../ra_syntax" }
 ra_ide = { path = "../ra_ide" }

crates/ra_cli/Cargo.toml

@@ -2,6 +2,9 @@
 
 use std::{collections::HashSet, fmt::Write, path::Path, time::Instant};
 
+use itertools::Itertools;
+use rand::{seq::SliceRandom, thread_rng};
+
 use hir::{
     db::{DefDatabase, HirDatabase},
     AssocItem, Crate, HasSource, HirDisplay, ModuleDef,
@@ -19,6 +22,7 @@ pub fn run(
     path: &Path,
     only: Option<&str>,
     with_deps: bool,
+    randomize: bool,
 ) -> Result<()> {
     let db_load_time = Instant::now();
     let (mut host, roots) = ra_batch::load_cargo(path)?;
@@ -41,7 +45,11 @@ pub fn run(
             })
             .collect::<HashSet<_>>();
 
-    for krate in Crate::all(db) {
+    let mut krates = Crate::all(db);
+    if randomize {
+        krates.shuffle(&mut thread_rng());
+    }
+    for krate in krates {
         let module = krate.root_module(db).expect("crate without root module");
         let file_id = module.definition_source(db).file_id;
         if members.contains(&db.file_source_root(file_id.original_file(db))) {
@@ -50,6 +58,10 @@ pub fn run(
         }
     }
 
+    if randomize {
+        visit_queue.shuffle(&mut thread_rng());
+    }
+
     println!("Crates in this dir: {}", num_crates);
     let mut num_decls = 0;
     let mut funcs = Vec::new();
@@ -79,10 +91,14 @@ pub fn run(
     println!("Total functions: {}", funcs.len());
     println!("Item Collection: {:?}, {}", analysis_time.elapsed(), ra_prof::memory_usage());
 
+    if randomize {
+        funcs.shuffle(&mut thread_rng());
+    }
+
     let inference_time = Instant::now();
     let mut bar = match verbosity {
-        Verbosity::Verbose | Verbosity::Normal => ProgressReport::new(funcs.len() as u64),
-        Verbosity::Quiet => ProgressReport::hidden(),
+        Verbosity::Quiet | Verbosity::Spammy => ProgressReport::hidden(),
+        _ => ProgressReport::new(funcs.len() as u64),
     };
 
     bar.tick();
@@ -92,23 +108,36 @@ pub fn run(
     let mut num_type_mismatches = 0;
     for f in funcs {
         let name = f.name(db);
-        let mut msg = format!("processing: {}", name);
+        let full_name = f
+            .module(db)
+            .path_to_root(db)
+            .into_iter()
+            .rev()
+            .filter_map(|it| it.name(db))
+            .chain(Some(f.name(db)))
+            .join("::");
+        if let Some(only_name) = only {
+            if name.to_string() != only_name && full_name != only_name {
+                continue;
+            }
+        }
+        let mut msg = format!("processing: {}", full_name);
         if verbosity.is_verbose() {
             let src = f.source(db);
             let original_file = src.file_id.original_file(db);
             let path = db.file_relative_path(original_file);
             let syntax_range = src.value.syntax().text_range();
             write!(msg, " ({:?} {})", path, syntax_range).unwrap();
         }
-        bar.set_message(&msg);
-        if let Some(only_name) = only {
-            if name.to_string() != only_name {
-                continue;
-            }
+        if verbosity.is_spammy() {
+            bar.println(format!("{}", msg));
         }
+        bar.set_message(&msg);
         let f_id = FunctionId::from(f);
         let body = db.body(f_id.into());
         let inference_result = db.infer(f_id.into());
+        let (previous_exprs, previous_unknown, previous_partially_unknown) =
+            (num_exprs, num_exprs_unknown, num_exprs_partially_unknown);
         for (expr_id, _) in body.exprs.iter() {
             let ty = &inference_result[expr_id];
             num_exprs += 1;
@@ -125,6 +154,33 @@ pub fn run(
                     num_exprs_partially_unknown += 1;
                 }
             }
+            if only.is_some() && verbosity.is_spammy() {
+                // in super-verbose mode for just one function, we print every single expression
+                let (_, sm) = db.body_with_source_map(f_id.into());
+                let src = sm.expr_syntax(expr_id);
+                if let Some(src) = src {
+                    let original_file = src.file_id.original_file(db);
+                    let line_index = host.analysis().file_line_index(original_file).unwrap();
+                    let text_range = src.value.either(
+                        |it| it.syntax_node_ptr().range(),
+                        |it| it.syntax_node_ptr().range(),
+                    );
+                    let (start, end) = (
+                        line_index.line_col(text_range.start()),
+                        line_index.line_col(text_range.end()),
+                    );
+                    bar.println(format!(
+                        "{}:{}-{}:{}: {}",
+                        start.line + 1,
+                        start.col_utf16,
+                        end.line + 1,
+                        end.col_utf16,
+                        ty.display(db)
+                    ));
+                } else {
+                    bar.println(format!("unknown location: {}", ty.display(db)));
+                }
+            }
             if let Some(mismatch) = inference_result.type_mismatch_for_expr(expr_id) {
                 num_type_mismatches += 1;
                 if verbosity.is_verbose() {
@@ -164,6 +220,15 @@ pub fn run(
                 }
             }
         }
+        if verbosity.is_spammy() {
+            bar.println(format!(
+                "In {}: {} exprs, {} unknown, {} partial",
+                full_name,
+                num_exprs - previous_exprs,
+                num_exprs_unknown - previous_unknown,
+                num_exprs_partially_unknown - previous_partially_unknown
+            ));
+        }
         bar.inc(1);
     }
     bar.finish_and_clear();

crates/ra_cli/src/analysis_stats.rs

@@ -16,6 +16,7 @@ type Result<T> = std::result::Result<T, Box<dyn Error + Send + Sync>>;
 
 #[derive(Clone, Copy)]
 pub enum Verbosity {
+    Spammy,
     Verbose,
     Normal,
     Quiet,
@@ -24,7 +25,13 @@ pub enum Verbosity {
 impl Verbosity {
     fn is_verbose(self) -> bool {
         match self {
-            Verbosity::Verbose => true,
+            Verbosity::Verbose | Verbosity::Spammy => true,
+            _ => false,
+        }
+    }
+    fn is_spammy(self) -> bool {
+        match self {
+            Verbosity::Spammy => true,
             _ => false,
         }
     }
@@ -86,14 +93,18 @@ fn main() -> Result<()> {
                 return Ok(());
             }
             let verbosity = match (
+                matches.contains(["-vv", "--spammy"]),
                 matches.contains(["-v", "--verbose"]),
                 matches.contains(["-q", "--quiet"]),
             ) {
-                (false, false) => Verbosity::Normal,
-                (false, true) => Verbosity::Quiet,
-                (true, false) => Verbosity::Verbose,
-                (true, true) => Err("Invalid flags: -q conflicts with -v")?,
+                (true, _, true) => Err("Invalid flags: -q conflicts with -vv")?,
+                (true, _, false) => Verbosity::Spammy,
+                (false, false, false) => Verbosity::Normal,
+                (false, false, true) => Verbosity::Quiet,
+                (false, true, false) => Verbosity::Verbose,
+                (false, true, true) => Err("Invalid flags: -q conflicts with -v")?,
             };
+            let randomize = matches.contains("--randomize");
             let memory_usage = matches.contains("--memory-usage");
             let only: Option<String> = matches.opt_value_from_str(["-o", "--only"])?;
             let with_deps: bool = matches.contains("--with-deps");
@@ -111,6 +122,7 @@ fn main() -> Result<()> {
                 path.as_ref(),
                 only.as_ref().map(String::as_ref),
                 with_deps,
+                randomize,
             )?;
         }
         "analysis-bench" => {

crates/ra_cli/src/main.rs

@@ -60,6 +60,9 @@ impl TraitSolver {
                     context.0.db.check_canceled();
                     let remaining = fuel.get();
                     fuel.set(remaining - 1);
+                    if remaining == 0 {
+                        log::debug!("fuel exhausted");
+                    }
                     remaining > 0
                 })
             }