Merge #1146

1146: Moar profiling r=matklad a=matklad



Co-authored-by: Aleksey Kladov <[email protected]>

7 files changed, 91 insertions, 42 deletions

diff --git a/Cargo.lock b/Cargo.lock
index 5a5edc3e2..779580762 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -996,6 +996,7 @@ dependencies = [
  "ra_db 0.1.0",
  "ra_fmt 0.1.0",
  "ra_hir 0.1.0",
+ "ra_prof 0.1.0",
  "ra_syntax 0.1.0",
  "ra_text_edit 0.1.0",
  "rayon 1.0.3 (registry+https://github.com/rust-lang/crates.io-index)",
diff --git a/crates/ra_ide_api/Cargo.toml b/crates/ra_ide_api/Cargo.toml
index 45bab4e28..333706c1a 100644
--- a/crates/ra_ide_api/Cargo.toml
+++ b/crates/ra_ide_api/Cargo.toml
@@ -23,6 +23,7 @@ ra_syntax = { path = "../ra_syntax" }
 ra_text_edit = { path = "../ra_text_edit" }
 ra_db = { path = "../ra_db" }
 ra_fmt = { path = "../ra_fmt" }
+ra_prof = { path = "../ra_prof" }
 hir = { path = "../ra_hir", package = "ra_hir" }
 test_utils = { path = "../test_utils" }
 ra_assists = { path = "../ra_assists" }
diff --git a/crates/ra_ide_api/src/change.rs b/crates/ra_ide_api/src/change.rs
index a4a086931..5bfdbe7e9 100644
--- a/crates/ra_ide_api/src/change.rs
+++ b/crates/ra_ide_api/src/change.rs
@@ -9,6 +9,7 @@ use ra_db::{
     salsa::{Database, SweepStrategy},
 };
 use ra_syntax::SourceFile;
+use ra_prof::profile;
 use relative_path::RelativePathBuf;
 use rayon::prelude::*;
 
@@ -153,6 +154,7 @@ const GC_COOLDOWN: time::Duration = time::Duration::from_millis(100);
 
 impl RootDatabase {
     pub(crate) fn apply_change(&mut self, change: AnalysisChange) {
+        let _p = profile("RootDatabase::apply_change");
         log::info!("apply_change {:?}", change);
         if !change.new_roots.is_empty() {
             let mut local_roots = Vec::clone(&self.local_roots());
diff --git a/crates/ra_lsp_server/src/main.rs b/crates/ra_lsp_server/src/main.rs
index 82f52a6e8..b0b70df5c 100644
--- a/crates/ra_lsp_server/src/main.rs
+++ b/crates/ra_lsp_server/src/main.rs
@@ -6,21 +6,16 @@ use ra_lsp_server::{Result, InitializationOptions};
 use ra_prof;
 
 fn main() -> Result<()> {
-    ::std::env::set_var("RUST_BACKTRACE", "short");
+    std::env::set_var("RUST_BACKTRACE", "short");
     let logger = Logger::with_env_or_str("error").duplicate_to_stderr(Duplicate::All);
-    match ::std::env::var("RA_INTERNAL_MODE") {
+    match std::env::var("RA_LOG_DIR") {
         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));
+    ra_prof::set_filter(match std::env::var("RA_PROFILE") {
+        Ok(spec) => ra_prof::Filter::from_spec(&spec),
+        Err(_) => ra_prof::Filter::disabled(),
+    });
     log::info!("lifecycle: server started");
     match ::std::panic::catch_unwind(main_inner) {
         Ok(res) => {
@@ -36,7 +31,7 @@ fn main() -> Result<()> {
 
 fn main_inner() -> Result<()> {
     let (receiver, sender, threads) = stdio_transport();
-    let cwd = ::std::env::current_dir()?;
+    let cwd = std::env::current_dir()?;
     run_server(ra_lsp_server::server_capabilities(), receiver, sender, |params, r, s| {
         let root = params.root_uri.and_then(|it| it.to_file_path().ok()).unwrap_or(cwd);
 
diff --git a/crates/ra_lsp_server/src/main_loop/handlers.rs b/crates/ra_lsp_server/src/main_loop/handlers.rs
index 41d1f759f..eb8a53545 100644
--- a/crates/ra_lsp_server/src/main_loop/handlers.rs
+++ b/crates/ra_lsp_server/src/main_loop/handlers.rs
@@ -12,6 +12,7 @@ use ra_ide_api::{
     AssistId,
 };
 use ra_syntax::{AstNode, SyntaxKind, TextUnit};
+use ra_prof::profile;
 use rustc_hash::FxHashMap;
 use serde::{Serialize, Deserialize};
 use serde_json::to_value;
@@ -328,6 +329,7 @@ pub fn handle_completion(
     world: ServerWorld,
     params: req::CompletionParams,
 ) -> Result<Option<req::CompletionResponse>> {
+    let _p = profile("handle_completion");
     let position = {
         let file_id = params.text_document.try_conv_with(&world)?;
         let line_index = world.analysis().file_line_index(file_id);
@@ -564,6 +566,7 @@ pub fn handle_code_action(
     world: ServerWorld,
     params: req::CodeActionParams,
 ) -> Result<Option<CodeActionResponse>> {
+    let _p = profile("handle_code_action");
     let file_id = params.text_document.try_conv_with(&world)?;
     let line_index = world.analysis().file_line_index(file_id);
     let range = params.range.conv_with(&line_index);
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
index 1cc8e361d..402c719b1 100644
--- a/crates/ra_prof/src/lib.rs
+++ b/crates/ra_prof/src/lib.rs
@@ -6,7 +6,7 @@ use std::iter::repeat;
 use std::collections::{HashSet};
 use std::default::Default;
 use std::iter::FromIterator;
-use std::sync::RwLock;
+use std::sync::{RwLock, atomic::{AtomicBool, Ordering}};
 use lazy_static::lazy_static;
 
 /// Set profiling filter. It specifies descriptions allowed to profile.
@@ -15,18 +15,20 @@ use lazy_static::lazy_static;
 ///
 /// #Example
 /// ```
-/// use ra_prof::set_filter;
-/// use ra_prof::Filter;
-/// let max_depth = 2;
-/// let allowed = vec!["profile1".to_string(), "profile2".to_string()];
-/// let f = Filter::new( max_depth, allowed );
+/// use ra_prof::{set_filter, Filter};
+/// let f = Filter::from_spec("profile1|profile2@2");
 /// set_filter(f);
 /// ```
-///
 pub fn set_filter(f: Filter) {
+    PROFILING_ENABLED.store(f.depth > 0, Ordering::SeqCst);
     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 };
+    let filter_data = FilterData {
+        depth: f.depth,
+        allowed: set,
+        longer_than: f.longer_than,
+        version: old.version + 1,
+    };
     *old = filter_data;
 }
 
@@ -37,12 +39,9 @@ pub fn set_filter(f: Filter) {
 ///
 /// #Example
 /// ```
-/// use ra_prof::profile;
-/// use ra_prof::set_filter;
-/// use ra_prof::Filter;
+/// use ra_prof::{profile, set_filter, Filter};
 ///
-/// let allowed = vec!["profile1".to_string(), "profile2".to_string()];
-/// let f = Filter::new(2, allowed);
+/// let f = Filter::from_spec("profile1|profile2@2");
 /// set_filter(f);
 /// profiling_function1();
 ///
@@ -60,8 +59,12 @@ pub fn set_filter(f: Filter) {
 ///  0ms - profile
 ///      0ms - profile2
 /// ```
-///
 pub fn profile(desc: &str) -> Profiler {
+    assert!(!desc.is_empty());
+    if !PROFILING_ENABLED.load(Ordering::Relaxed) {
+        return Profiler { desc: None };
+    }
+
     PROFILE_STACK.with(|stack| {
         let mut stack = stack.borrow_mut();
         if stack.starts.len() == 0 {
@@ -74,14 +77,14 @@ pub fn profile(desc: &str) -> Profiler {
                 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)
-        {
+
+        if stack.starts.len() > stack.filter_data.depth {
+            return Profiler { desc: None };
+        }
+
+        if stack.filter_data.allowed.is_empty() || stack.filter_data.allowed.contains(desc) {
             stack.starts.push(Instant::now());
-            Profiler { desc: Some(desc_str) }
+            Profiler { desc: Some(desc.to_string()) }
         } else {
             Profiler { desc: None }
         }
@@ -95,11 +98,41 @@ pub struct Profiler {
 pub struct Filter {
     depth: usize,
     allowed: Vec<String>,
+    longer_than: Duration,
 }
 
 impl Filter {
-    pub fn new(depth: usize, allowed: Vec<String>) -> Filter {
-        Filter { depth, allowed }
+    // Filtering syntax
+    // env RA_PROFILE=*             // dump everything
+    // env RA_PROFILE=foo|bar|baz   // enabled only selected entries
+    // env RA_PROFILE=*@3>10        // dump everything, up to depth 3, if it takes more than 10 ms
+    pub fn from_spec(mut spec: &str) -> Filter {
+        let longer_than = if let Some(idx) = spec.rfind(">") {
+            let longer_than = spec[idx + 1..].parse().expect("invalid profile longer_than");
+            spec = &spec[..idx];
+            Duration::from_millis(longer_than)
+        } else {
+            Duration::new(0, 0)
+        };
+
+        let depth = if let Some(idx) = spec.rfind("@") {
+            let depth: usize = spec[idx + 1..].parse().expect("invalid profile depth");
+            spec = &spec[..idx];
+            depth
+        } else {
+            999
+        };
+        let allowed =
+            if spec == "*" { Vec::new() } else { spec.split("|").map(String::from).collect() };
+        Filter::new(depth, allowed, longer_than)
+    }
+
+    pub fn disabled() -> Filter {
+        Filter::new(0, Vec::new(), Duration::new(0, 0))
+    }
+
+    pub fn new(depth: usize, allowed: Vec<String>, longer_than: Duration) -> Filter {
+        Filter { depth, allowed, longer_than }
     }
 }
 
@@ -126,8 +159,11 @@ struct FilterData {
     depth: usize,
     version: usize,
     allowed: HashSet<String>,
+    longer_than: Duration,
 }
 
+static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false);
+
 lazy_static! {
     static ref FILTER: RwLock<FilterData> = RwLock::new(Default::default());
 }
@@ -147,7 +183,9 @@ impl Drop for Profiler {
                     stack.messages.push(Message { level, duration, message });
                     if level == 0 {
                         let stdout = stderr();
-                        print(0, &stack.messages, &mut stdout.lock());
+                        if duration >= stack.filter_data.longer_than {
+                            print(0, &stack.messages, &mut stdout.lock());
+                        }
                         stack.messages.clear();
                     }
                 });
@@ -174,15 +212,12 @@ fn print(lvl: usize, msgs: &[Message], out: &mut impl Write) {
 
 #[cfg(test)]
 mod tests {
-
-    use super::profile;
-    use super::set_filter;
-    use super::Filter;
+    use super::*;
 
     #[test]
     fn test_basic_profile() {
         let s = vec!["profile1".to_string(), "profile2".to_string()];
-        let f = Filter::new(2, s);
+        let f = Filter::new(2, s, Duration::new(0, 0));
         set_filter(f);
         profiling_function1();
     }
diff --git a/docs/dev/README.md b/docs/dev/README.md
index 7bb323f3f..d34ff96c8 100644
--- a/docs/dev/README.md
+++ b/docs/dev/README.md
@@ -105,7 +105,7 @@ figure out where logs go.
 Inside rust-analyzer, we use the standard `log` crate for logging, and
 `flexi_logger` for logging frotend. By default, log goes to stderr (the same as
 with `env_logger`), but the stderr itself is processed by VS Code. To mirror
-logs to a `./log` directory, set `RA_INTERNAL_MODE=1` environmental variable.
+logs to a `./log` directory, set `RA_LOG_DIR=1` environmental variable.
 
 To see stderr in the running VS Code instance, go to the "Output" tab of the
 panel and select `rust-analyzer`. This shows `eprintln!` as well. Note that
@@ -135,3 +135,15 @@ There's also two VS Code commands which might be of interest:
   There's an alias for this: `cargo jinstall-lsp`.
 
 * `Rust Analyzer: Syntax Tree` shows syntax tree of the current file/selection.
+
+# Profiling
+
+We have a built-in hierarchical profiler, you can enable it by using `RA_PROF` env-var:
+
+```
+RA_PROFILE=*             // dump everything
+RA_PROFILE=foo|bar|baz   // enabled only selected entries
+RA_PROFILE=*@3>10        // dump everything, up to depth 3, if it takes more than 10 ms
+```
+
+In particular, I have `export RA_PROFILE='*>10' in my shell profile.