diff --git a/Cargo.lock b/Cargo.lock index ddd508b0ad..06117ceaf8 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", @@ -1050,6 +1053,13 @@ dependencies = [ "drop_bomb 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", ] +[[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" diff --git a/crates/ra_cli/Cargo.toml b/crates/ra_cli/Cargo.toml index 467628236a..328b2436f6 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 1f2750d895..45555be6e1 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 = ::std::result::Result; @@ -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 501308accc..a2858dad9d 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 6f049acfc3..4ae04514a3 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 { - 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 = 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 d824107004..bc181e4eb6 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 5a29052071..eb4091a3d8 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 eecf278a8e..82410bee30 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 0000000000..19ce217831 --- /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 0000000000..abddff960a --- /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, +} + +pub struct Filter { + depth: usize, + allowed: Vec, +} + +impl Filter { + pub fn new(depth: usize, allowed: Vec) -> Filter { + Filter { depth, allowed } + } +} + +struct ProfileStack { + starts: Vec, + messages: Vec, + 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, +} + +lazy_static! { + static ref FILTER: RwLock = RwLock::new(Default::default()); +} + +thread_local!(static PROFILE_STACK: RefCell = 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::(); + 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"); + } +}