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 <[email protected]>

9 files changed, 183 insertions, 10 deletions

diff --git a/crates/ra_cli/Cargo.toml b/crates/ra_cli/Cargo.toml
index 467628236..328b2436f 100644
--- a/crates/ra_cli/Cargo.toml
+++ b/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" }
diff --git a/crates/ra_cli/src/main.rs b/crates/ra_cli/src/main.rs
index 1f2750d89..45555be6e 100644
--- a/crates/ra_cli/src/main.rs
+++ b/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", _) => {
diff --git a/crates/ra_hir/Cargo.toml b/crates/ra_hir/Cargo.toml
index 501308acc..a2858dad9 100644
--- a/crates/ra_hir/Cargo.toml
+++ b/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"
diff --git a/crates/ra_hir/src/nameres.rs b/crates/ra_hir/src/nameres.rs
index 6f049acfc..4ae04514a 100644
--- a/crates/ra_hir/src/nameres.rs
+++ b/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)
     }
 
diff --git a/crates/ra_lsp_server/Cargo.toml b/crates/ra_lsp_server/Cargo.toml
index d82410700..bc181e4eb 100644
--- a/crates/ra_lsp_server/Cargo.toml
+++ b/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"
diff --git a/crates/ra_lsp_server/src/main.rs b/crates/ra_lsp_server/src/main.rs
index 5a2905207..eb4091a3d 100644
--- a/crates/ra_lsp_server/src/main.rs
+++ b/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) => {
diff --git a/crates/ra_lsp_server/src/main_loop.rs b/crates/ra_lsp_server/src/main_loop.rs
index eecf278a8..82410bee3 100644
--- a/crates/ra_lsp_server/src/main_loop.rs
+++ b/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());
     }
 }
 
diff --git a/crates/ra_prof/Cargo.toml b/crates/ra_prof/Cargo.toml
new file mode 100644
index 000000000..19ce21783
--- /dev/null
+++ b/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"
\ No newline at end of file
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
new file mode 100644
index 000000000..abddff960
--- /dev/null
+++ b/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");
+    }
+}