10 files changed, 193 insertions, 10 deletions

diff --git a/Cargo.lock b/Cargo.lock
index ddd508b0a..06117ceaf 100644
--- a/Cargo.lock
+++ b/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",
@@ -1051,6 +1054,13 @@ dependencies = [
 ]
 
 [[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"
 dependencies = [
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");
+    }
+}