filter by time

crates/ra_lsp_server/src/main.rs

@@ -8,31 +8,14 @@ use ra_prof;
 fn main() -> Result<()> {
     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()?,
     };
-    // Filtering syntax
-    // env RA_PROFILE=*             // dump everything
-    // env RA_PROFILE=foo|bar|baz   // enabled only selected entries
-    // env RA_PROFILE=*@3           // dump everything, up to depth 3
-    let filter = match std::env::var("RA_PROFILE") {
-        Ok(p) => {
-            let mut p = p.as_str();
-            let depth = if let Some(idx) = p.rfind("@") {
-                let depth: usize = p[idx + 1..].parse().expect("invalid profile depth");
-                p = &p[..idx];
-                depth
-            } else {
-                999
-            };
-            let allowed =
-                if p == "*" { Vec::new() } else { p.split(";").map(String::from).collect() };
-            ra_prof::Filter::new(depth, allowed)
-        }
+    ra_prof::set_filter(match std::env::var("RA_PROFILE") {
+        Ok(spec) => ra_prof::Filter::from_spec(&spec),
         Err(_) => ra_prof::Filter::disabled(),
-    };
-    ra_prof::set_filter(filter);
+    });
     log::info!("lifecycle: server started");
     match ::std::panic::catch_unwind(main_inner) {
         Ok(res) => {

crates/ra_prof/src/lib.rs

@@ -27,7 +27,8 @@ 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, cutoff: f.cutoff, version: old.version + 1 };
     *old = filter_data;
 }
 
@@ -101,15 +102,41 @@ pub struct Profiler {
 pub struct Filter {
     depth: usize,
     allowed: Vec<String>,
+    cutoff: Duration,
 }
 
 impl Filter {
-    pub fn disabled() -> Filter {
-        Filter::new(0, Vec::new())
+    // 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 cutoff = if let Some(idx) = spec.rfind(">") {
+            let cutoff = spec[idx + 1..].parse().expect("invalid profile cutoff");
+            spec = &spec[..idx];
+            Duration::from_millis(cutoff)
+        } 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, cutoff)
     }
 
-    pub fn new(depth: usize, allowed: Vec<String>) -> Filter {
-        Filter { depth, allowed }
+    pub fn disabled() -> Filter {
+        Filter::new(0, Vec::new(), Duration::new(0, 0))
+    }
+
+    pub fn new(depth: usize, allowed: Vec<String>, cutoff: Duration) -> Filter {
+        Filter { depth, allowed, cutoff }
     }
 }
 
@@ -136,6 +163,7 @@ struct FilterData {
     depth: usize,
     version: usize,
     allowed: HashSet<String>,
+    cutoff: Duration,
 }
 
 static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false);
@@ -159,7 +187,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.cutoff {
+                            print(0, &stack.messages, &mut stdout.lock());
+                        }
                         stack.messages.clear();
                     }
                 });

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
@@ -143,5 +143,7 @@ We have a built-in hierarchical profiler, you can enable it by using `RA_PROF` e
 ```
 RA_PROFILE=*             // dump everything
 RA_PROFILE=foo|bar|baz   // enabled only selected entries
-RA_PROFILE=*@3           // dump everything, up to depth 3
+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.