Merge #1068

1068: profiling crate first draft r=matklad a=pasa

I've made this first draft for #961 
Could you look at it? Is this something what you are looking for?
It has lack of tests. I can't figure out how to test stderr output in rust right now. Do you have some clues?
Additionally I'm thinking about to implement procedural  macros to annotate methods with this profiler. Will it be helpful?



Co-authored-by: Sergey Parilin <sergey.parilin@fxdd.com>

Cargo.lock

@@ -931,6 +931,7 @@ dependencies = [
  "ra_db 0.1.0",
  "ra_hir 0.1.0",
  "ra_ide_api 0.1.0",
+ "ra_prof 0.1.0",
  "ra_syntax 0.1.0",
  "tools 0.1.0",
 ]
@@ -970,6 +971,7 @@ dependencies = [
  "ra_arena 0.1.0",
  "ra_db 0.1.0",
  "ra_mbe 0.1.0",
+ "ra_prof 0.1.0",
  "ra_syntax 0.1.0",
  "ra_tt 0.1.0",
  "relative-path 0.4.0 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -1018,6 +1020,7 @@ dependencies = [
  "parking_lot 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "ra_arena 0.1.0",
  "ra_ide_api 0.1.0",
+ "ra_prof 0.1.0",
  "ra_project_model 0.1.0",
  "ra_syntax 0.1.0",
  "ra_text_edit 0.1.0",
@@ -1050,6 +1053,13 @@ dependencies = [
  "drop_bomb 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)",
 ]
 
+[[package]]
+name = "ra_prof"
+version = "0.1.0"
+dependencies = [
+ "lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)",
+]
+
 [[package]]
 name = "ra_project_model"
 version = "0.1.0"

crates/ra_cli/Cargo.toml

@@ -18,3 +18,4 @@ tools = { path = "../tools" }
 ra_batch = { path = "../ra_batch" }
 ra_hir = { path = "../ra_hir" }
 ra_db = { path = "../ra_db" }
+ra_prof = { path = "../ra_prof" }

crates/ra_cli/src/main.rs

@@ -1,12 +1,13 @@
 mod analysis_stats;
 
-use std::{fs, io::Read, path::Path, time::Instant};
+use std::{fs, io::Read, path::Path};
 
 use clap::{App, Arg, SubCommand};
 use ra_ide_api::file_structure;
 use ra_syntax::{SourceFile, TreeArc, AstNode};
 use tools::collect_tests;
 use flexi_logger::Logger;
+use ra_prof::profile;
 
 type Result<T> = ::std::result::Result<T, failure::Error>;
 
@@ -27,13 +28,11 @@ fn main() -> Result<()> {
         .get_matches();
     match matches.subcommand() {
         ("parse", Some(matches)) => {
-            let start = Instant::now();
+            let _p = profile("parsing");
             let file = file()?;
-            let elapsed = start.elapsed();
             if !matches.is_present("no-dump") {
                 println!("{}", file.syntax().debug_dump());
             }
-            eprintln!("parsing: {:?}", elapsed);
             ::std::mem::forget(file);
         }
         ("symbols", _) => {

crates/ra_hir/Cargo.toml

@@ -19,6 +19,7 @@ ra_db = { path = "../ra_db" }
 mbe = { path = "../ra_mbe", package = "ra_mbe" }
 tt = { path = "../ra_tt", package = "ra_tt" }
 test_utils = { path = "../test_utils" }
+ra_prof = {path = "../ra_prof" }
 
 [dev-dependencies]
 flexi_logger = "0.11.0"

crates/ra_hir/src/nameres.rs

@@ -60,6 +60,7 @@ use ra_arena::{Arena, RawId, impl_arena_id};
 use ra_db::{FileId, Edition};
 use test_utils::tested_by;
 use ra_syntax::ast;
+use ra_prof::profile;
 
 use crate::{
     ModuleDef, Name, Crate, Module,
@@ -181,7 +182,7 @@ enum ReachedFixedPoint {
 
 impl CrateDefMap {
     pub(crate) fn crate_def_map_query(db: &impl DefDatabase, krate: Crate) -> Arc<CrateDefMap> {
-        let start = std::time::Instant::now();
+        let _p = profile("crate_def_map_query");
         let def_map = {
             let edition = krate.edition(db);
             let mut modules: Arena<CrateModuleId, ModuleData> = Arena::default();
@@ -198,7 +199,6 @@ impl CrateDefMap {
             }
         };
         let def_map = collector::collect_defs(db, def_map);
-        log::info!("crate_def_map_query: {:?}", start.elapsed());
         Arc::new(def_map)
     }
 

crates/ra_lsp_server/Cargo.toml

@@ -27,6 +27,7 @@ ra_ide_api = { path = "../ra_ide_api" }
 ra_arena = { path = "../ra_arena" }
 gen_lsp_server = { path = "../gen_lsp_server" }
 ra_project_model = { path = "../ra_project_model" }
+ra_prof = { path = "../ra_prof" }
 
 [dev-dependencies]
 tempfile = "3"

crates/ra_lsp_server/src/main.rs

@@ -3,6 +3,7 @@ use flexi_logger::{Duplicate, Logger};
 use gen_lsp_server::{run_server, stdio_transport};
 
 use ra_lsp_server::{Result, InitializationOptions};
+use ra_prof;
 
 fn main() -> Result<()> {
     ::std::env::set_var("RUST_BACKTRACE", "short");
@@ -11,6 +12,15 @@ fn main() -> Result<()> {
         Ok(ref v) if v == "1" => logger.log_to_file().directory("log").start()?,
         _ => logger.start()?,
     };
+    let prof_depth = match ::std::env::var("RA_PROFILE_DEPTH") {
+        Ok(ref d) => d.parse()?,
+        _ => 0,
+    };
+    let profile_allowed = match ::std::env::var("RA_PROFILE") {
+        Ok(ref p) => p.split(";").map(String::from).collect(),
+        _ => Vec::new(),
+    };
+    ra_prof::set_filter(ra_prof::Filter::new(prof_depth, profile_allowed));
     log::info!("lifecycle: server started");
     match ::std::panic::catch_unwind(main_inner) {
         Ok(res) => {

crates/ra_lsp_server/src/main_loop.rs

@@ -24,6 +24,7 @@ use crate::{
     Result,
     InitializationOptions,
 };
+use ra_prof::profile;
 
 #[derive(Debug, Fail)]
 #[fail(display = "Language Server request failed with {}. ({})", code, message)]
@@ -181,7 +182,7 @@ fn main_loop_inner(
             recv(libdata_receiver) -> data => Event::Lib(data.unwrap())
         };
         log::info!("loop_turn = {:?}", event);
-        let start = std::time::Instant::now();
+        let _p = profile("loop_turn");
         let mut state_changed = false;
         match event {
             Event::Task(task) => on_task(task, msg_sender, pending_requests),
@@ -235,10 +236,9 @@ fn main_loop_inner(
             in_flight_libraries += 1;
             let sender = libdata_sender.clone();
             pool.execute(move || {
-                let start = ::std::time::Instant::now();
                 log::info!("indexing {:?} ... ", root);
+                let _p = profile(&format!("indexed {:?}", root));
                 let data = LibraryData::prepare(root, files);
-                log::info!("indexed {:?} {:?}", start.elapsed(), root);
                 sender.send(data).unwrap();
             });
         }
@@ -266,7 +266,6 @@ fn main_loop_inner(
                 subs.subscriptions(),
             )
         }
-        log::info!("loop_turn = {:?}", start.elapsed());
     }
 }
 

crates/ra_prof/Cargo.toml

@@ -0,0 +1,9 @@
+[package]
+edition = "2018"
+name = "ra_prof"
+version = "0.1.0"
+authors = ["rust-analyzer developers"]
+publish = false
+
+[dependencies]
+lazy_static = "1.3.0"

crates/ra_prof/src/lib.rs

@@ -0,0 +1,153 @@
+use std::cell::RefCell;
+use std::time::{Duration, Instant};
+use std::mem;
+use std::io::{stderr, Write};
+use std::iter::repeat;
+use std::collections::{HashSet};
+use std::default::Default;
+use std::iter::FromIterator;
+use std::sync::RwLock;
+use lazy_static::lazy_static;
+
+pub fn set_filter(f: Filter) {
+    let set = HashSet::from_iter(f.allowed.iter().cloned());
+    let mut old = FILTER.write().unwrap();
+    let filter_data = FilterData { depth: f.depth, allowed: set, version: old.version + 1 };
+    *old = filter_data;
+}
+
+pub fn profile(desc: &str) -> Profiler {
+    PROFILE_STACK.with(|stack| {
+        let mut stack = stack.borrow_mut();
+        if stack.starts.len() == 0 {
+            match FILTER.try_read() {
+                Ok(f) => {
+                    if f.version > stack.filter_data.version {
+                        stack.filter_data = f.clone();
+                    }
+                }
+                Err(_) => (),
+            };
+        }
+        let desc_str = desc.to_string();
+        if desc_str.is_empty() {
+            Profiler { desc: None }
+        } else if stack.starts.len() < stack.filter_data.depth
+            && stack.filter_data.allowed.contains(&desc_str)
+        {
+            stack.starts.push(Instant::now());
+            Profiler { desc: Some(desc_str) }
+        } else {
+            Profiler { desc: None }
+        }
+    })
+}
+
+pub struct Profiler {
+    desc: Option<String>,
+}
+
+pub struct Filter {
+    depth: usize,
+    allowed: Vec<String>,
+}
+
+impl Filter {
+    pub fn new(depth: usize, allowed: Vec<String>) -> Filter {
+        Filter { depth, allowed }
+    }
+}
+
+struct ProfileStack {
+    starts: Vec<Instant>,
+    messages: Vec<Message>,
+    filter_data: FilterData,
+}
+
+struct Message {
+    level: usize,
+    duration: Duration,
+    message: String,
+}
+
+impl ProfileStack {
+    fn new() -> ProfileStack {
+        ProfileStack { starts: Vec::new(), messages: Vec::new(), filter_data: Default::default() }
+    }
+}
+
+#[derive(Default, Clone)]
+struct FilterData {
+    depth: usize,
+    version: usize,
+    allowed: HashSet<String>,
+}
+
+lazy_static! {
+    static ref FILTER: RwLock<FilterData> = RwLock::new(Default::default());
+}
+
+thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(ProfileStack::new()));
+
+impl Drop for Profiler {
+    fn drop(&mut self) {
+        match self {
+            Profiler { desc: Some(desc) } => {
+                PROFILE_STACK.with(|stack| {
+                    let mut stack = stack.borrow_mut();
+                    let start = stack.starts.pop().unwrap();
+                    let duration = start.elapsed();
+                    let level = stack.starts.len();
+                    let message = mem::replace(desc, String::new());
+                    stack.messages.push(Message { level, duration, message });
+                    if level == 0 {
+                        let stdout = stderr();
+                        print(0, &stack.messages, &mut stdout.lock());
+                        stack.messages.clear();
+                    }
+                });
+            }
+            Profiler { desc: None } => (),
+        }
+    }
+}
+
+fn print(lvl: usize, msgs: &[Message], out: &mut impl Write) {
+    let mut last = 0;
+    let indent = repeat("    ").take(lvl + 1).collect::<String>();
+    for (i, &Message { level: l, duration: dur, message: ref msg }) in msgs.iter().enumerate() {
+        if l != lvl {
+            continue;
+        }
+        writeln!(out, "{} {:6}ms - {}", indent, dur.as_millis(), msg)
+            .expect("printing profiling info to stdout");
+
+        print(lvl + 1, &msgs[last..i], out);
+        last = i;
+    }
+}
+
+#[cfg(test)]
+mod tests {
+
+    use super::profile;
+    use super::set_filter;
+    use super::Filter;
+
+    #[test]
+    fn test_basic_profile() {
+        let s = vec!["profile1".to_string(), "profile2".to_string()];
+        let f = Filter { depth: 2, allowed: s };
+        set_filter(f);
+        profiling_function1();
+    }
+
+    fn profiling_function1() {
+        let _p = profile("profile1");
+        profiling_function2();
+    }
+
+    fn profiling_function2() {
+        let _p = profile("profile2");
+    }
+}