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]>

2 files changed, 13 insertions, 4 deletions

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());
     }
 }