From 7623db11061f70dd654405a0da91bc3ad1abc53a Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sat, 25 Apr 2020 14:52:23 +0200
Subject: [PATCH 1/7] minor clenup
---
crates/ra_prof/src/lib.rs | 25 +++++++++++--------
.../tests/heavy_tests/support.rs | 6 +----
2 files changed, 15 insertions(+), 16 deletions(-)
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
index 2d4f68f5e07..d95ad3107be 100644
--- a/crates/ra_prof/src/lib.rs
+++ b/crates/ra_prof/src/lib.rs
@@ -26,11 +26,18 @@ pub use crate::memory_usage::{Bytes, MemoryUsage};
#[global_allocator]
static ALLOC: jemallocator::Jemalloc = jemallocator::Jemalloc;
+/// 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 init() {
- set_filter(match std::env::var("RA_PROFILE") {
- Ok(spec) => Filter::from_spec(&spec),
- Err(_) => Filter::disabled(),
- });
+ let spec = std::env::var("RA_PROFILE").unwrap_or_default();
+ init_from(&spec);
+}
+
+pub fn init_from(spec: &str) {
+ let filter = if spec.is_empty() { Filter::disabled() } else { Filter::from_spec(spec) };
+ set_filter(filter);
}
/// Set profiling filter. It specifies descriptions allowed to profile.
@@ -43,7 +50,7 @@ pub fn init() {
/// let f = Filter::from_spec("profile1|profile2@2");
/// set_filter(f);
/// ```
-pub fn set_filter(f: Filter) {
+fn set_filter(f: Filter) {
PROFILING_ENABLED.store(f.depth > 0, Ordering::SeqCst);
let set: HashSet<_> = f.allowed.iter().cloned().collect();
let mut old = FILTER.write().unwrap();
@@ -127,18 +134,14 @@ impl Profiler {
}
}
-pub struct Filter {
+struct Filter {
depth: usize,
allowed: Vec<String>,
longer_than: Duration,
}
impl Filter {
- // 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 {
+ 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];
diff --git a/crates/rust-analyzer/tests/heavy_tests/support.rs b/crates/rust-analyzer/tests/heavy_tests/support.rs
index 7eebedff7ad..e4fe3411aa6 100644
--- a/crates/rust-analyzer/tests/heavy_tests/support.rs
+++ b/crates/rust-analyzer/tests/heavy_tests/support.rs
@@ -62,11 +62,7 @@ impl<'a> Project<'a> {
static INIT: Once = Once::new();
INIT.call_once(|| {
env_logger::builder().is_test(true).try_init().unwrap();
- ra_prof::set_filter(if crate::PROFILE.is_empty() {
- ra_prof::Filter::disabled()
- } else {
- ra_prof::Filter::from_spec(&crate::PROFILE)
- });
+ ra_prof::init_from(crate::PROFILE);
});
let mut paths = vec![];
From b3e9f3d143b0fae970449b7c49a2daf6f966a068 Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sat, 25 Apr 2020 15:02:09 +0200
Subject: [PATCH 2/7] Move hprof to a separate file
---
crates/ra_prof/src/hprof.rs | 391 +++++++++++++++++++++++++++++++++++
crates/ra_prof/src/lib.rs | 400 +-----------------------------------
2 files changed, 398 insertions(+), 393 deletions(-)
create mode 100644 crates/ra_prof/src/hprof.rs
diff --git a/crates/ra_prof/src/hprof.rs b/crates/ra_prof/src/hprof.rs
new file mode 100644
index 00000000000..79268513d8a
--- /dev/null
+++ b/crates/ra_prof/src/hprof.rs
@@ -0,0 +1,391 @@
+//! Simple hierarchical profiler
+use std::{
+ cell::RefCell,
+ collections::{BTreeMap, HashSet},
+ io::{stderr, Write},
+ sync::{
+ atomic::{AtomicBool, Ordering},
+ RwLock,
+ },
+ time::{Duration, Instant},
+};
+
+use once_cell::sync::Lazy;
+
+/// 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 init() {
+ let spec = std::env::var("RA_PROFILE").unwrap_or_default();
+ init_from(&spec);
+}
+
+pub fn init_from(spec: &str) {
+ let filter = if spec.is_empty() { Filter::disabled() } else { Filter::from_spec(spec) };
+ set_filter(filter);
+}
+
+pub type Label = &'static str;
+
+/// This function starts a profiling scope in the current execution stack with a given description.
+/// It returns a Profile structure and measure elapsed time between this method invocation and Profile structure drop.
+/// It supports nested profiling scopes in case when this function invoked multiple times at the execution stack. In this case the profiling information will be nested at the output.
+/// Profiling information is being printed in the stderr.
+///
+/// # Example
+/// ```
+/// use ra_prof::{profile, set_filter, Filter};
+///
+/// let f = Filter::from_spec("profile1|profile2@2");
+/// set_filter(f);
+/// profiling_function1();
+///
+/// fn profiling_function1() {
+/// let _p = profile("profile1");
+/// profiling_function2();
+/// }
+///
+/// fn profiling_function2() {
+/// let _p = profile("profile2");
+/// }
+/// ```
+/// This will print in the stderr the following:
+/// ```text
+/// 0ms - profile
+/// 0ms - profile2
+/// ```
+pub fn profile(label: Label) -> Profiler {
+ assert!(!label.is_empty());
+ if !PROFILING_ENABLED.load(Ordering::Relaxed) {
+ return Profiler { label: None, detail: None };
+ }
+
+ PROFILE_STACK.with(|stack| {
+ let mut stack = stack.borrow_mut();
+ if stack.starts.is_empty() {
+ if let Ok(f) = FILTER.try_read() {
+ if f.version > stack.filter_data.version {
+ stack.filter_data = f.clone();
+ }
+ };
+ }
+ if stack.starts.len() > stack.filter_data.depth {
+ return Profiler { label: None, detail: None };
+ }
+ let allowed = &stack.filter_data.allowed;
+ if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) {
+ return Profiler { label: None, detail: None };
+ }
+
+ stack.starts.push(Instant::now());
+ Profiler { label: Some(label), detail: None }
+ })
+}
+
+pub struct Profiler {
+ label: Option<Label>,
+ detail: Option<String>,
+}
+
+impl Profiler {
+ pub fn detail(mut self, detail: impl FnOnce() -> String) -> Profiler {
+ if self.label.is_some() {
+ self.detail = Some(detail())
+ }
+ self
+ }
+}
+
+/// Set profiling filter. It specifies descriptions allowed to profile.
+/// This is helpful when call stack has too many nested profiling scopes.
+/// Additionally filter can specify maximum depth of profiling scopes nesting.
+///
+/// #Example
+/// ```
+/// use ra_prof::{set_filter, Filter};
+/// let f = Filter::from_spec("profile1|profile2@2");
+/// set_filter(f);
+/// ```
+fn set_filter(f: Filter) {
+ PROFILING_ENABLED.store(f.depth > 0, Ordering::SeqCst);
+ let set: HashSet<_> = f.allowed.iter().cloned().collect();
+ let mut old = FILTER.write().unwrap();
+ let filter_data = FilterData {
+ depth: f.depth,
+ allowed: set,
+ longer_than: f.longer_than,
+ version: old.version + 1,
+ };
+ *old = filter_data;
+}
+
+struct Filter {
+ depth: usize,
+ allowed: Vec<String>,
+ longer_than: Duration,
+}
+
+impl Filter {
+ 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 }
+ }
+}
+
+struct ProfileStack {
+ starts: Vec<Instant>,
+ messages: Vec<Message>,
+ filter_data: FilterData,
+}
+
+struct Message {
+ level: usize,
+ duration: Duration,
+ label: Label,
+ detail: Option<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>,
+ longer_than: Duration,
+}
+
+static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false);
+
+static FILTER: Lazy<RwLock<FilterData>> = Lazy::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 { label: Some(label), detail } => {
+ 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();
+ stack.messages.push(Message { level, duration, label, detail: detail.take() });
+ if level == 0 {
+ let stdout = stderr();
+ let longer_than = stack.filter_data.longer_than;
+ // Convert to millis for comparison to avoid problems with rounding
+ // (otherwise we could print `0ms` despite user's `>0` filter when
+ // `duration` is just a few nanos).
+ if duration.as_millis() > longer_than.as_millis() {
+ print(&stack.messages, longer_than, &mut stdout.lock());
+ }
+ stack.messages.clear();
+ }
+ });
+ }
+ Profiler { label: None, .. } => (),
+ }
+ }
+}
+
+fn print(msgs: &[Message], longer_than: Duration, out: &mut impl Write) {
+ if msgs.is_empty() {
+ return;
+ }
+ let children_map = idx_to_children(msgs);
+ let root_idx = msgs.len() - 1;
+ print_for_idx(root_idx, &children_map, msgs, longer_than, out);
+}
+
+fn print_for_idx(
+ current_idx: usize,
+ children_map: &[Vec<usize>],
+ msgs: &[Message],
+ longer_than: Duration,
+ out: &mut impl Write,
+) {
+ let current = &msgs[current_idx];
+ let current_indent = " ".repeat(current.level);
+ let detail = current.detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default();
+ writeln!(
+ out,
+ "{}{:5}ms - {}{}",
+ current_indent,
+ current.duration.as_millis(),
+ current.label,
+ detail,
+ )
+ .expect("printing profiling info");
+
+ let longer_than_millis = longer_than.as_millis();
+ let children_indices = &children_map[current_idx];
+ let mut accounted_for = Duration::default();
+ let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output.
+
+ for child_idx in children_indices.iter() {
+ let child = &msgs[*child_idx];
+ if child.duration.as_millis() > longer_than_millis {
+ print_for_idx(*child_idx, children_map, msgs, longer_than, out);
+ } else {
+ let pair = short_children.entry(child.label).or_insert((Duration::default(), 0));
+ pair.0 += child.duration;
+ pair.1 += 1;
+ }
+ accounted_for += child.duration;
+ }
+
+ for (child_msg, (duration, count)) in short_children.iter() {
+ let millis = duration.as_millis();
+ writeln!(out, " {}{:5}ms - {} ({} calls)", current_indent, millis, child_msg, count)
+ .expect("printing profiling info");
+ }
+
+ let unaccounted_millis = (current.duration - accounted_for).as_millis();
+ if !children_indices.is_empty()
+ && unaccounted_millis > 0
+ && unaccounted_millis > longer_than_millis
+ {
+ writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted_millis)
+ .expect("printing profiling info");
+ }
+}
+
+/// Returns a mapping from an index in the `msgs` to the vector with the indices of its children.
+///
+/// This assumes that the entries in `msgs` are in the order of when the calls to `profile` finish.
+/// In other words, a postorder of the call graph. In particular, the root is the last element of
+/// `msgs`.
+fn idx_to_children(msgs: &[Message]) -> Vec<Vec<usize>> {
+ // Initialize with the index of the root; `msgs` and `ancestors` should be never empty.
+ assert!(!msgs.is_empty());
+ let mut ancestors = vec![msgs.len() - 1];
+ let mut result: Vec<Vec<usize>> = vec![vec![]; msgs.len()];
+ for (idx, msg) in msgs[..msgs.len() - 1].iter().enumerate().rev() {
+ // We need to find the parent of the current message, i.e., the last ancestor that has a
+ // level lower than the current message.
+ while msgs[*ancestors.last().unwrap()].level >= msg.level {
+ ancestors.pop();
+ }
+ result[*ancestors.last().unwrap()].push(idx);
+ ancestors.push(idx);
+ }
+ // Note that above we visited all children from the last to the first one. Let's reverse vectors
+ // to get the more natural order where the first element is the first child.
+ for vec in result.iter_mut() {
+ vec.reverse();
+ }
+ result
+}
+
+#[cfg(test)]
+mod tests {
+ use super::*;
+
+ #[test]
+ fn test_basic_profile() {
+ let s = vec!["profile1".to_string(), "profile2".to_string()];
+ let f = Filter::new(2, s, Duration::new(0, 0));
+ set_filter(f);
+ profiling_function1();
+ }
+
+ fn profiling_function1() {
+ let _p = profile("profile1");
+ profiling_function2();
+ }
+
+ fn profiling_function2() {
+ let _p = profile("profile2");
+ }
+
+ #[test]
+ fn test_longer_than() {
+ let mut result = vec![];
+ let msgs = vec![
+ Message { level: 1, duration: Duration::from_nanos(3), label: "bar", detail: None },
+ Message { level: 1, duration: Duration::from_nanos(2), label: "bar", detail: None },
+ Message { level: 0, duration: Duration::from_millis(1), label: "foo", detail: None },
+ ];
+ print(&msgs, Duration::from_millis(0), &mut result);
+ // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed
+ // when printing.
+ assert_eq!(
+ std::str::from_utf8(&result).unwrap(),
+ " 1ms - foo\n 0ms - bar (2 calls)\n"
+ );
+ }
+
+ #[test]
+ fn test_unaccounted_for_topmost() {
+ let mut result = vec![];
+ let msgs = vec![
+ Message { level: 1, duration: Duration::from_millis(2), label: "bar", detail: None },
+ Message { level: 0, duration: Duration::from_millis(5), label: "foo", detail: None },
+ ];
+ print(&msgs, Duration::from_millis(0), &mut result);
+ assert_eq!(
+ std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
+ vec![
+ " 5ms - foo",
+ " 2ms - bar",
+ " 3ms - ???",
+ // Dummy comment to improve formatting
+ ]
+ );
+ }
+
+ #[test]
+ fn test_unaccounted_for_multiple_levels() {
+ let mut result = vec![];
+ let msgs = vec![
+ Message { level: 2, duration: Duration::from_millis(3), label: "baz", detail: None },
+ Message { level: 1, duration: Duration::from_millis(5), label: "bar", detail: None },
+ Message { level: 2, duration: Duration::from_millis(2), label: "baz", detail: None },
+ Message { level: 1, duration: Duration::from_millis(4), label: "bar", detail: None },
+ Message { level: 0, duration: Duration::from_millis(9), label: "foo", detail: None },
+ ];
+ print(&msgs, Duration::from_millis(0), &mut result);
+ assert_eq!(
+ std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
+ vec![
+ " 9ms - foo",
+ " 5ms - bar",
+ " 3ms - baz",
+ " 2ms - ???",
+ " 4ms - bar",
+ " 2ms - baz",
+ " 2ms - ???",
+ ]
+ );
+ }
+}
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
index d95ad3107be..e6d672ef558 100644
--- a/crates/ra_prof/src/lib.rs
+++ b/crates/ra_prof/src/lib.rs
@@ -1,326 +1,23 @@
-//! FIXME: write short doc here
+//! A collection of tools for profiling rust-analyzer.
mod memory_usage;
#[cfg(feature = "cpu_profiler")]
mod google_cpu_profiler;
+mod hprof;
-use std::{
- cell::RefCell,
- collections::BTreeMap,
- collections::HashSet,
- io::{stderr, Write},
- sync::{
- atomic::{AtomicBool, Ordering},
- RwLock,
- },
- time::{Duration, Instant},
+use std::cell::RefCell;
+
+pub use crate::{
+ hprof::{init, init_from, profile},
+ memory_usage::{Bytes, MemoryUsage},
};
-use once_cell::sync::Lazy;
-
-pub use crate::memory_usage::{Bytes, MemoryUsage};
-
// We use jemalloc mainly to get heap usage statistics, actual performance
// difference is not measures.
#[cfg(all(feature = "jemalloc", not(target_env = "msvc")))]
#[global_allocator]
static ALLOC: jemallocator::Jemalloc = jemallocator::Jemalloc;
-/// 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 init() {
- let spec = std::env::var("RA_PROFILE").unwrap_or_default();
- init_from(&spec);
-}
-
-pub fn init_from(spec: &str) {
- let filter = if spec.is_empty() { Filter::disabled() } else { Filter::from_spec(spec) };
- set_filter(filter);
-}
-
-/// Set profiling filter. It specifies descriptions allowed to profile.
-/// This is helpful when call stack has too many nested profiling scopes.
-/// Additionally filter can specify maximum depth of profiling scopes nesting.
-///
-/// #Example
-/// ```
-/// use ra_prof::{set_filter, Filter};
-/// let f = Filter::from_spec("profile1|profile2@2");
-/// set_filter(f);
-/// ```
-fn set_filter(f: Filter) {
- PROFILING_ENABLED.store(f.depth > 0, Ordering::SeqCst);
- let set: HashSet<_> = f.allowed.iter().cloned().collect();
- let mut old = FILTER.write().unwrap();
- let filter_data = FilterData {
- depth: f.depth,
- allowed: set,
- longer_than: f.longer_than,
- version: old.version + 1,
- };
- *old = filter_data;
-}
-
-pub type Label = &'static str;
-
-/// This function starts a profiling scope in the current execution stack with a given description.
-/// It returns a Profile structure and measure elapsed time between this method invocation and Profile structure drop.
-/// It supports nested profiling scopes in case when this function invoked multiple times at the execution stack. In this case the profiling information will be nested at the output.
-/// Profiling information is being printed in the stderr.
-///
-/// # Example
-/// ```
-/// use ra_prof::{profile, set_filter, Filter};
-///
-/// let f = Filter::from_spec("profile1|profile2@2");
-/// set_filter(f);
-/// profiling_function1();
-///
-/// fn profiling_function1() {
-/// let _p = profile("profile1");
-/// profiling_function2();
-/// }
-///
-/// fn profiling_function2() {
-/// let _p = profile("profile2");
-/// }
-/// ```
-/// This will print in the stderr the following:
-/// ```text
-/// 0ms - profile
-/// 0ms - profile2
-/// ```
-pub fn profile(label: Label) -> Profiler {
- assert!(!label.is_empty());
- if !PROFILING_ENABLED.load(Ordering::Relaxed) {
- return Profiler { label: None, detail: None };
- }
-
- PROFILE_STACK.with(|stack| {
- let mut stack = stack.borrow_mut();
- if stack.starts.is_empty() {
- if let Ok(f) = FILTER.try_read() {
- if f.version > stack.filter_data.version {
- stack.filter_data = f.clone();
- }
- };
- }
- if stack.starts.len() > stack.filter_data.depth {
- return Profiler { label: None, detail: None };
- }
- let allowed = &stack.filter_data.allowed;
- if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) {
- return Profiler { label: None, detail: None };
- }
-
- stack.starts.push(Instant::now());
- Profiler { label: Some(label), detail: None }
- })
-}
-
-pub struct Profiler {
- label: Option<Label>,
- detail: Option<String>,
-}
-
-impl Profiler {
- pub fn detail(mut self, detail: impl FnOnce() -> String) -> Profiler {
- if self.label.is_some() {
- self.detail = Some(detail())
- }
- self
- }
-}
-
-struct Filter {
- depth: usize,
- allowed: Vec<String>,
- longer_than: Duration,
-}
-
-impl Filter {
- 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 }
- }
-}
-
-struct ProfileStack {
- starts: Vec<Instant>,
- messages: Vec<Message>,
- filter_data: FilterData,
-}
-
-struct Message {
- level: usize,
- duration: Duration,
- label: Label,
- detail: Option<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>,
- longer_than: Duration,
-}
-
-static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false);
-
-static FILTER: Lazy<RwLock<FilterData>> = Lazy::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 { label: Some(label), detail } => {
- 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();
- stack.messages.push(Message { level, duration, label, detail: detail.take() });
- if level == 0 {
- let stdout = stderr();
- let longer_than = stack.filter_data.longer_than;
- // Convert to millis for comparison to avoid problems with rounding
- // (otherwise we could print `0ms` despite user's `>0` filter when
- // `duration` is just a few nanos).
- if duration.as_millis() > longer_than.as_millis() {
- print(&stack.messages, longer_than, &mut stdout.lock());
- }
- stack.messages.clear();
- }
- });
- }
- Profiler { label: None, .. } => (),
- }
- }
-}
-
-fn print(msgs: &[Message], longer_than: Duration, out: &mut impl Write) {
- if msgs.is_empty() {
- return;
- }
- let children_map = idx_to_children(msgs);
- let root_idx = msgs.len() - 1;
- print_for_idx(root_idx, &children_map, msgs, longer_than, out);
-}
-
-fn print_for_idx(
- current_idx: usize,
- children_map: &[Vec<usize>],
- msgs: &[Message],
- longer_than: Duration,
- out: &mut impl Write,
-) {
- let current = &msgs[current_idx];
- let current_indent = " ".repeat(current.level);
- let detail = current.detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default();
- writeln!(
- out,
- "{}{:5}ms - {}{}",
- current_indent,
- current.duration.as_millis(),
- current.label,
- detail,
- )
- .expect("printing profiling info");
-
- let longer_than_millis = longer_than.as_millis();
- let children_indices = &children_map[current_idx];
- let mut accounted_for = Duration::default();
- let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output.
-
- for child_idx in children_indices.iter() {
- let child = &msgs[*child_idx];
- if child.duration.as_millis() > longer_than_millis {
- print_for_idx(*child_idx, children_map, msgs, longer_than, out);
- } else {
- let pair = short_children.entry(child.label).or_insert((Duration::default(), 0));
- pair.0 += child.duration;
- pair.1 += 1;
- }
- accounted_for += child.duration;
- }
-
- for (child_msg, (duration, count)) in short_children.iter() {
- let millis = duration.as_millis();
- writeln!(out, " {}{:5}ms - {} ({} calls)", current_indent, millis, child_msg, count)
- .expect("printing profiling info");
- }
-
- let unaccounted_millis = (current.duration - accounted_for).as_millis();
- if !children_indices.is_empty()
- && unaccounted_millis > 0
- && unaccounted_millis > longer_than_millis
- {
- writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted_millis)
- .expect("printing profiling info");
- }
-}
-
-/// Returns a mapping from an index in the `msgs` to the vector with the indices of its children.
-///
-/// This assumes that the entries in `msgs` are in the order of when the calls to `profile` finish.
-/// In other words, a postorder of the call graph. In particular, the root is the last element of
-/// `msgs`.
-fn idx_to_children(msgs: &[Message]) -> Vec<Vec<usize>> {
- // Initialize with the index of the root; `msgs` and `ancestors` should be never empty.
- assert!(!msgs.is_empty());
- let mut ancestors = vec![msgs.len() - 1];
- let mut result: Vec<Vec<usize>> = vec![vec![]; msgs.len()];
- for (idx, msg) in msgs[..msgs.len() - 1].iter().enumerate().rev() {
- // We need to find the parent of the current message, i.e., the last ancestor that has a
- // level lower than the current message.
- while msgs[*ancestors.last().unwrap()].level >= msg.level {
- ancestors.pop();
- }
- result[*ancestors.last().unwrap()].push(idx);
- ancestors.push(idx);
- }
- // Note that above we visited all children from the last to the first one. Let's reverse vectors
- // to get the more natural order where the first element is the first child.
- for vec in result.iter_mut() {
- vec.reverse();
- }
- result
-}
-
/// Prints backtrace to stderr, useful for debugging.
#[cfg(feature = "backtrace")]
pub fn print_backtrace() {
@@ -406,86 +103,3 @@ impl Drop for CpuProfiler {
pub fn memory_usage() -> MemoryUsage {
MemoryUsage::current()
}
-
-#[cfg(test)]
-mod tests {
- use super::*;
-
- #[test]
- fn test_basic_profile() {
- let s = vec!["profile1".to_string(), "profile2".to_string()];
- let f = Filter::new(2, s, Duration::new(0, 0));
- set_filter(f);
- profiling_function1();
- }
-
- fn profiling_function1() {
- let _p = profile("profile1");
- profiling_function2();
- }
-
- fn profiling_function2() {
- let _p = profile("profile2");
- }
-
- #[test]
- fn test_longer_than() {
- let mut result = vec![];
- let msgs = vec![
- Message { level: 1, duration: Duration::from_nanos(3), label: "bar", detail: None },
- Message { level: 1, duration: Duration::from_nanos(2), label: "bar", detail: None },
- Message { level: 0, duration: Duration::from_millis(1), label: "foo", detail: None },
- ];
- print(&msgs, Duration::from_millis(0), &mut result);
- // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed
- // when printing.
- assert_eq!(
- std::str::from_utf8(&result).unwrap(),
- " 1ms - foo\n 0ms - bar (2 calls)\n"
- );
- }
-
- #[test]
- fn test_unaccounted_for_topmost() {
- let mut result = vec![];
- let msgs = vec![
- Message { level: 1, duration: Duration::from_millis(2), label: "bar", detail: None },
- Message { level: 0, duration: Duration::from_millis(5), label: "foo", detail: None },
- ];
- print(&msgs, Duration::from_millis(0), &mut result);
- assert_eq!(
- std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
- vec![
- " 5ms - foo",
- " 2ms - bar",
- " 3ms - ???",
- // Dummy comment to improve formatting
- ]
- );
- }
-
- #[test]
- fn test_unaccounted_for_multiple_levels() {
- let mut result = vec![];
- let msgs = vec![
- Message { level: 2, duration: Duration::from_millis(3), label: "baz", detail: None },
- Message { level: 1, duration: Duration::from_millis(5), label: "bar", detail: None },
- Message { level: 2, duration: Duration::from_millis(2), label: "baz", detail: None },
- Message { level: 1, duration: Duration::from_millis(4), label: "bar", detail: None },
- Message { level: 0, duration: Duration::from_millis(9), label: "foo", detail: None },
- ];
- print(&msgs, Duration::from_millis(0), &mut result);
- assert_eq!(
- std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
- vec![
- " 9ms - foo",
- " 5ms - bar",
- " 3ms - baz",
- " 2ms - ???",
- " 4ms - bar",
- " 2ms - baz",
- " 2ms - ???",
- ]
- );
- }
-}
From 726938f598378f6d88b6b5ee91e1cea8f323029d Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sat, 25 Apr 2020 19:29:41 +0200
Subject: [PATCH 3/7] Simplify hprof
---
crates/ra_prof/src/hprof.rs | 153 ++++++++++++++++--------------------
1 file changed, 66 insertions(+), 87 deletions(-)
diff --git a/crates/ra_prof/src/hprof.rs b/crates/ra_prof/src/hprof.rs
index 79268513d8a..6d91206ae4f 100644
--- a/crates/ra_prof/src/hprof.rs
+++ b/crates/ra_prof/src/hprof.rs
@@ -23,7 +23,7 @@ pub fn init() {
pub fn init_from(spec: &str) {
let filter = if spec.is_empty() { Filter::disabled() } else { Filter::from_spec(spec) };
- set_filter(filter);
+ filter.install();
}
pub type Label = &'static str;
@@ -57,30 +57,10 @@ pub type Label = &'static str;
/// ```
pub fn profile(label: Label) -> Profiler {
assert!(!label.is_empty());
- if !PROFILING_ENABLED.load(Ordering::Relaxed) {
- return Profiler { label: None, detail: None };
- }
-
- PROFILE_STACK.with(|stack| {
- let mut stack = stack.borrow_mut();
- if stack.starts.is_empty() {
- if let Ok(f) = FILTER.try_read() {
- if f.version > stack.filter_data.version {
- stack.filter_data = f.clone();
- }
- };
- }
- if stack.starts.len() > stack.filter_data.depth {
- return Profiler { label: None, detail: None };
- }
- let allowed = &stack.filter_data.allowed;
- if stack.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) {
- return Profiler { label: None, detail: None };
- }
-
- stack.starts.push(Instant::now());
- Profiler { label: Some(label), detail: None }
- })
+ let enabled = PROFILING_ENABLED.load(Ordering::Relaxed)
+ && PROFILE_STACK.with(|stack| stack.borrow_mut().push(label));
+ let label = if enabled { Some(label) } else { None };
+ Profiler { label, detail: None }
}
pub struct Profiler {
@@ -97,36 +77,27 @@ impl Profiler {
}
}
-/// Set profiling filter. It specifies descriptions allowed to profile.
-/// This is helpful when call stack has too many nested profiling scopes.
-/// Additionally filter can specify maximum depth of profiling scopes nesting.
-///
-/// #Example
-/// ```
-/// use ra_prof::{set_filter, Filter};
-/// let f = Filter::from_spec("profile1|profile2@2");
-/// set_filter(f);
-/// ```
-fn set_filter(f: Filter) {
- PROFILING_ENABLED.store(f.depth > 0, Ordering::SeqCst);
- let set: HashSet<_> = f.allowed.iter().cloned().collect();
- let mut old = FILTER.write().unwrap();
- let filter_data = FilterData {
- depth: f.depth,
- allowed: set,
- longer_than: f.longer_than,
- version: old.version + 1,
- };
- *old = filter_data;
-}
+static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false);
+static FILTER: Lazy<RwLock<Filter>> = Lazy::new(Default::default);
+thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(ProfileStack::new()));
+#[derive(Default, Clone, Debug)]
struct Filter {
depth: usize,
- allowed: Vec<String>,
+ allowed: HashSet<String>,
longer_than: Duration,
+ version: usize,
}
impl Filter {
+ fn new(depth: usize, allowed: HashSet<String>, longer_than: Duration) -> Filter {
+ Filter { depth, allowed, longer_than, version: 0 }
+ }
+
+ fn disabled() -> Filter {
+ Filter::default()
+ }
+
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");
@@ -144,23 +115,22 @@ impl Filter {
999
};
let allowed =
- if spec == "*" { Vec::new() } else { spec.split('|').map(String::from).collect() };
+ if spec == "*" { HashSet::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 }
+ fn install(mut self) {
+ PROFILING_ENABLED.store(self.depth > 0, Ordering::SeqCst);
+ let mut old = FILTER.write().unwrap();
+ self.version = old.version + 1;
+ *old = self;
}
}
struct ProfileStack {
starts: Vec<Instant>,
messages: Vec<Message>,
- filter_data: FilterData,
+ filter: Filter,
}
struct Message {
@@ -172,45 +142,54 @@ struct Message {
impl ProfileStack {
fn new() -> ProfileStack {
- ProfileStack { starts: Vec::new(), messages: Vec::new(), filter_data: Default::default() }
+ ProfileStack { starts: Vec::new(), messages: Vec::new(), filter: Default::default() }
+ }
+
+ fn push(&mut self, label: Label) -> bool {
+ if self.starts.is_empty() {
+ if let Ok(f) = FILTER.try_read() {
+ if f.version > self.filter.version {
+ self.filter = f.clone();
+ }
+ };
+ }
+ if self.starts.len() > self.filter.depth {
+ return false;
+ }
+ let allowed = &self.filter.allowed;
+ if self.starts.is_empty() && !allowed.is_empty() && !allowed.contains(label) {
+ return false;
+ }
+
+ self.starts.push(Instant::now());
+ true
+ }
+
+ pub fn pop(&mut self, label: Label, detail: Option<String>) {
+ let start = self.starts.pop().unwrap();
+ let duration = start.elapsed();
+ let level = self.starts.len();
+ self.messages.push(Message { level, duration, label, detail });
+ if level == 0 {
+ let stdout = stderr();
+ let longer_than = self.filter.longer_than;
+ // Convert to millis for comparison to avoid problems with rounding
+ // (otherwise we could print `0ms` despite user's `>0` filter when
+ // `duration` is just a few nanos).
+ if duration.as_millis() > longer_than.as_millis() {
+ print(&self.messages, longer_than, &mut stdout.lock());
+ }
+ self.messages.clear();
+ }
}
}
-#[derive(Default, Clone)]
-struct FilterData {
- depth: usize,
- version: usize,
- allowed: HashSet<String>,
- longer_than: Duration,
-}
-
-static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false);
-
-static FILTER: Lazy<RwLock<FilterData>> = Lazy::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 { label: Some(label), detail } => {
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();
- stack.messages.push(Message { level, duration, label, detail: detail.take() });
- if level == 0 {
- let stdout = stderr();
- let longer_than = stack.filter_data.longer_than;
- // Convert to millis for comparison to avoid problems with rounding
- // (otherwise we could print `0ms` despite user's `>0` filter when
- // `duration` is just a few nanos).
- if duration.as_millis() > longer_than.as_millis() {
- print(&stack.messages, longer_than, &mut stdout.lock());
- }
- stack.messages.clear();
- }
+ stack.borrow_mut().pop(label, detail.take());
});
}
Profiler { label: None, .. } => (),
From 95b989ec3059eca140d9bfffee1bc52e30f9d17b Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sat, 25 Apr 2020 19:50:42 +0200
Subject: [PATCH 4/7] Simplify
---
crates/ra_prof/src/hprof.rs | 37 +++++++++++++++++--------------------
1 file changed, 17 insertions(+), 20 deletions(-)
diff --git a/crates/ra_prof/src/hprof.rs b/crates/ra_prof/src/hprof.rs
index 6d91206ae4f..4bbe5cb12d2 100644
--- a/crates/ra_prof/src/hprof.rs
+++ b/crates/ra_prof/src/hprof.rs
@@ -77,6 +77,19 @@ impl Profiler {
}
}
+impl Drop for Profiler {
+ fn drop(&mut self) {
+ match self {
+ Profiler { label: Some(label), detail } => {
+ PROFILE_STACK.with(|stack| {
+ stack.borrow_mut().pop(label, detail.take());
+ });
+ }
+ Profiler { label: None, .. } => (),
+ }
+ }
+}
+
static PROFILING_ENABLED: AtomicBool = AtomicBool::new(false);
static FILTER: Lazy<RwLock<Filter>> = Lazy::new(Default::default);
thread_local!(static PROFILE_STACK: RefCell<ProfileStack> = RefCell::new(ProfileStack::new()));
@@ -90,10 +103,6 @@ struct Filter {
}
impl Filter {
- fn new(depth: usize, allowed: HashSet<String>, longer_than: Duration) -> Filter {
- Filter { depth, allowed, longer_than, version: 0 }
- }
-
fn disabled() -> Filter {
Filter::default()
}
@@ -116,7 +125,7 @@ impl Filter {
};
let allowed =
if spec == "*" { HashSet::new() } else { spec.split('|').map(String::from).collect() };
- Filter::new(depth, allowed, longer_than)
+ Filter { depth, allowed, longer_than, version: 0 }
}
fn install(mut self) {
@@ -171,28 +180,16 @@ impl ProfileStack {
let level = self.starts.len();
self.messages.push(Message { level, duration, label, detail });
if level == 0 {
- let stdout = stderr();
let longer_than = self.filter.longer_than;
// Convert to millis for comparison to avoid problems with rounding
// (otherwise we could print `0ms` despite user's `>0` filter when
// `duration` is just a few nanos).
if duration.as_millis() > longer_than.as_millis() {
- print(&self.messages, longer_than, &mut stdout.lock());
+ let stderr = stderr();
+ print(&self.messages, longer_than, &mut stderr.lock());
}
self.messages.clear();
- }
- }
-}
-
-impl Drop for Profiler {
- fn drop(&mut self) {
- match self {
- Profiler { label: Some(label), detail } => {
- PROFILE_STACK.with(|stack| {
- stack.borrow_mut().pop(label, detail.take());
- });
- }
- Profiler { label: None, .. } => (),
+ assert!(self.starts.is_empty())
}
}
}
From 0f099ead8893fa9551e385b030a4239ea1338451 Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sat, 25 Apr 2020 20:56:25 +0200
Subject: [PATCH 5/7] Fix panic in NoSuchField diagnostic
---
crates/ra_hir_ty/src/infer.rs | 5 ++---
1 file changed, 2 insertions(+), 3 deletions(-)
diff --git a/crates/ra_hir_ty/src/infer.rs b/crates/ra_hir_ty/src/infer.rs
index 6a53be621d2..bd4ef69a079 100644
--- a/crates/ra_hir_ty/src/infer.rs
+++ b/crates/ra_hir_ty/src/infer.rs
@@ -667,7 +667,7 @@ impl Expectation {
}
mod diagnostics {
- use hir_def::{expr::ExprId, src::HasSource, FunctionId, Lookup};
+ use hir_def::{expr::ExprId, FunctionId};
use hir_expand::diagnostics::DiagnosticSink;
use crate::{db::HirDatabase, diagnostics::NoSuchField};
@@ -686,10 +686,9 @@ mod diagnostics {
) {
match self {
InferenceDiagnostic::NoSuchField { expr, field } => {
- let source = owner.lookup(db.upcast()).source(db.upcast());
let (_, source_map) = db.body_with_source_map(owner.into());
let field = source_map.field_syntax(*expr, *field);
- sink.push(NoSuchField { file: source.file_id, field: field.value })
+ sink.push(NoSuchField { file: field.file_id, field: field.value })
}
}
}
From bd9ede0ec9fb76c8cc0b572ef0405811e1cb666e Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sat, 25 Apr 2020 21:04:04 +0200
Subject: [PATCH 6/7] Extract messy tree handling out of profiling code
---
Cargo.lock | 1 +
crates/ra_arena/src/lib.rs | 3 +
crates/ra_prof/Cargo.toml | 1 +
crates/ra_prof/src/hprof.rs | 179 ++++++------------------------------
crates/ra_prof/src/lib.rs | 1 +
crates/ra_prof/src/tree.rs | 84 +++++++++++++++++
6 files changed, 119 insertions(+), 150 deletions(-)
create mode 100644 crates/ra_prof/src/tree.rs
diff --git a/Cargo.lock b/Cargo.lock
index 20e6cd54030..367ff3f8281 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -1139,6 +1139,7 @@ dependencies = [
"jemalloc-ctl",
"jemallocator",
"once_cell",
+ "ra_arena",
]
[[package]]
diff --git a/crates/ra_arena/src/lib.rs b/crates/ra_arena/src/lib.rs
index ea98d54441a..441fbb3cbef 100644
--- a/crates/ra_arena/src/lib.rs
+++ b/crates/ra_arena/src/lib.rs
@@ -96,6 +96,9 @@ impl<T> Arena<T> {
pub const fn new() -> Arena<T> {
Arena { data: Vec::new() }
}
+ pub fn clear(&mut self) {
+ self.data.clear();
+ }
pub fn len(&self) -> usize {
self.data.len()
diff --git a/crates/ra_prof/Cargo.toml b/crates/ra_prof/Cargo.toml
index d15b089925c..c33b5121ae2 100644
--- a/crates/ra_prof/Cargo.toml
+++ b/crates/ra_prof/Cargo.toml
@@ -9,6 +9,7 @@ publish = false
doctest = false
[dependencies]
+ra_arena = { path = "../ra_arena" }
once_cell = "1.3.1"
backtrace = { version = "0.3.44", optional = true }
diff --git a/crates/ra_prof/src/hprof.rs b/crates/ra_prof/src/hprof.rs
index 4bbe5cb12d2..2b8a903636c 100644
--- a/crates/ra_prof/src/hprof.rs
+++ b/crates/ra_prof/src/hprof.rs
@@ -1,4 +1,5 @@
//! Simple hierarchical profiler
+use once_cell::sync::Lazy;
use std::{
cell::RefCell,
collections::{BTreeMap, HashSet},
@@ -10,7 +11,7 @@ use std::{
time::{Duration, Instant},
};
-use once_cell::sync::Lazy;
+use crate::tree::{Idx, Tree};
/// Filtering syntax
/// env RA_PROFILE=* // dump everything
@@ -138,12 +139,12 @@ impl Filter {
struct ProfileStack {
starts: Vec<Instant>,
- messages: Vec<Message>,
filter: Filter,
+ messages: Tree<Message>,
}
+#[derive(Default)]
struct Message {
- level: usize,
duration: Duration,
label: Label,
detail: Option<String>,
@@ -151,7 +152,7 @@ struct Message {
impl ProfileStack {
fn new() -> ProfileStack {
- ProfileStack { starts: Vec::new(), messages: Vec::new(), filter: Default::default() }
+ ProfileStack { starts: Vec::new(), messages: Tree::default(), filter: Default::default() }
}
fn push(&mut self, label: Label) -> bool {
@@ -171,6 +172,7 @@ impl ProfileStack {
}
self.starts.push(Instant::now());
+ self.messages.start();
true
}
@@ -178,7 +180,7 @@ impl ProfileStack {
let start = self.starts.pop().unwrap();
let duration = start.elapsed();
let level = self.starts.len();
- self.messages.push(Message { level, duration, label, detail });
+ self.messages.finish(Message { duration, label, detail });
if level == 0 {
let longer_than = self.filter.longer_than;
// Convert to millis for comparison to avoid problems with rounding
@@ -186,7 +188,9 @@ impl ProfileStack {
// `duration` is just a few nanos).
if duration.as_millis() > longer_than.as_millis() {
let stderr = stderr();
- print(&self.messages, longer_than, &mut stderr.lock());
+ if let Some(root) = self.messages.root() {
+ print(&self.messages, root, 0, longer_than, &mut stderr.lock());
+ }
}
self.messages.clear();
assert!(self.starts.is_empty())
@@ -194,50 +198,38 @@ impl ProfileStack {
}
}
-fn print(msgs: &[Message], longer_than: Duration, out: &mut impl Write) {
- if msgs.is_empty() {
- return;
- }
- let children_map = idx_to_children(msgs);
- let root_idx = msgs.len() - 1;
- print_for_idx(root_idx, &children_map, msgs, longer_than, out);
-}
-
-fn print_for_idx(
- current_idx: usize,
- children_map: &[Vec<usize>],
- msgs: &[Message],
+fn print(
+ tree: &Tree<Message>,
+ curr: Idx<Message>,
+ level: u32,
longer_than: Duration,
out: &mut impl Write,
) {
- let current = &msgs[current_idx];
- let current_indent = " ".repeat(current.level);
- let detail = current.detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default();
+ let current_indent = " ".repeat(level as usize);
+ let detail = tree[curr].detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default();
writeln!(
out,
"{}{:5}ms - {}{}",
current_indent,
- current.duration.as_millis(),
- current.label,
+ tree[curr].duration.as_millis(),
+ tree[curr].label,
detail,
)
.expect("printing profiling info");
- let longer_than_millis = longer_than.as_millis();
- let children_indices = &children_map[current_idx];
let mut accounted_for = Duration::default();
let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output.
+ for child in tree.children(curr) {
+ accounted_for += tree[child].duration;
- for child_idx in children_indices.iter() {
- let child = &msgs[*child_idx];
- if child.duration.as_millis() > longer_than_millis {
- print_for_idx(*child_idx, children_map, msgs, longer_than, out);
+ if tree[child].duration.as_millis() > longer_than.as_millis() {
+ print(tree, child, level + 1, longer_than, out)
} else {
- let pair = short_children.entry(child.label).or_insert((Duration::default(), 0));
- pair.0 += child.duration;
- pair.1 += 1;
+ let (total_duration, cnt) =
+ short_children.entry(tree[child].label).or_insert((Duration::default(), 0));
+ *total_duration += tree[child].duration;
+ *cnt += 1;
}
- accounted_for += child.duration;
}
for (child_msg, (duration, count)) in short_children.iter() {
@@ -246,122 +238,9 @@ fn print_for_idx(
.expect("printing profiling info");
}
- let unaccounted_millis = (current.duration - accounted_for).as_millis();
- if !children_indices.is_empty()
- && unaccounted_millis > 0
- && unaccounted_millis > longer_than_millis
- {
- writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted_millis)
+ let unaccounted = tree[curr].duration - accounted_for;
+ if tree.children(curr).next().is_some() && unaccounted > longer_than {
+ writeln!(out, " {}{:5}ms - ???", current_indent, unaccounted.as_millis())
.expect("printing profiling info");
}
}
-
-/// Returns a mapping from an index in the `msgs` to the vector with the indices of its children.
-///
-/// This assumes that the entries in `msgs` are in the order of when the calls to `profile` finish.
-/// In other words, a postorder of the call graph. In particular, the root is the last element of
-/// `msgs`.
-fn idx_to_children(msgs: &[Message]) -> Vec<Vec<usize>> {
- // Initialize with the index of the root; `msgs` and `ancestors` should be never empty.
- assert!(!msgs.is_empty());
- let mut ancestors = vec![msgs.len() - 1];
- let mut result: Vec<Vec<usize>> = vec![vec![]; msgs.len()];
- for (idx, msg) in msgs[..msgs.len() - 1].iter().enumerate().rev() {
- // We need to find the parent of the current message, i.e., the last ancestor that has a
- // level lower than the current message.
- while msgs[*ancestors.last().unwrap()].level >= msg.level {
- ancestors.pop();
- }
- result[*ancestors.last().unwrap()].push(idx);
- ancestors.push(idx);
- }
- // Note that above we visited all children from the last to the first one. Let's reverse vectors
- // to get the more natural order where the first element is the first child.
- for vec in result.iter_mut() {
- vec.reverse();
- }
- result
-}
-
-#[cfg(test)]
-mod tests {
- use super::*;
-
- #[test]
- fn test_basic_profile() {
- let s = vec!["profile1".to_string(), "profile2".to_string()];
- let f = Filter::new(2, s, Duration::new(0, 0));
- set_filter(f);
- profiling_function1();
- }
-
- fn profiling_function1() {
- let _p = profile("profile1");
- profiling_function2();
- }
-
- fn profiling_function2() {
- let _p = profile("profile2");
- }
-
- #[test]
- fn test_longer_than() {
- let mut result = vec![];
- let msgs = vec![
- Message { level: 1, duration: Duration::from_nanos(3), label: "bar", detail: None },
- Message { level: 1, duration: Duration::from_nanos(2), label: "bar", detail: None },
- Message { level: 0, duration: Duration::from_millis(1), label: "foo", detail: None },
- ];
- print(&msgs, Duration::from_millis(0), &mut result);
- // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed
- // when printing.
- assert_eq!(
- std::str::from_utf8(&result).unwrap(),
- " 1ms - foo\n 0ms - bar (2 calls)\n"
- );
- }
-
- #[test]
- fn test_unaccounted_for_topmost() {
- let mut result = vec![];
- let msgs = vec![
- Message { level: 1, duration: Duration::from_millis(2), label: "bar", detail: None },
- Message { level: 0, duration: Duration::from_millis(5), label: "foo", detail: None },
- ];
- print(&msgs, Duration::from_millis(0), &mut result);
- assert_eq!(
- std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
- vec![
- " 5ms - foo",
- " 2ms - bar",
- " 3ms - ???",
- // Dummy comment to improve formatting
- ]
- );
- }
-
- #[test]
- fn test_unaccounted_for_multiple_levels() {
- let mut result = vec![];
- let msgs = vec![
- Message { level: 2, duration: Duration::from_millis(3), label: "baz", detail: None },
- Message { level: 1, duration: Duration::from_millis(5), label: "bar", detail: None },
- Message { level: 2, duration: Duration::from_millis(2), label: "baz", detail: None },
- Message { level: 1, duration: Duration::from_millis(4), label: "bar", detail: None },
- Message { level: 0, duration: Duration::from_millis(9), label: "foo", detail: None },
- ];
- print(&msgs, Duration::from_millis(0), &mut result);
- assert_eq!(
- std::str::from_utf8(&result).unwrap().lines().collect::<Vec<_>>(),
- vec![
- " 9ms - foo",
- " 5ms - bar",
- " 3ms - baz",
- " 2ms - ???",
- " 4ms - bar",
- " 2ms - baz",
- " 2ms - ???",
- ]
- );
- }
-}
diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
index e6d672ef558..89df7f04b7f 100644
--- a/crates/ra_prof/src/lib.rs
+++ b/crates/ra_prof/src/lib.rs
@@ -4,6 +4,7 @@ mod memory_usage;
#[cfg(feature = "cpu_profiler")]
mod google_cpu_profiler;
mod hprof;
+mod tree;
use std::cell::RefCell;
diff --git a/crates/ra_prof/src/tree.rs b/crates/ra_prof/src/tree.rs
new file mode 100644
index 00000000000..9ea5b5db8e1
--- /dev/null
+++ b/crates/ra_prof/src/tree.rs
@@ -0,0 +1,84 @@
+//! A simple tree implementation which tries to not allocate all over the place.
+use std::ops;
+
+use ra_arena::Arena;
+
+#[derive(Default)]
+pub struct Tree<T> {
+ nodes: Arena<Node<T>>,
+ current_path: Vec<(Idx<T>, Option<Idx<T>>)>,
+}
+
+pub type Idx<T> = ra_arena::Idx<Node<T>>;
+
+impl<T> Tree<T> {
+ pub fn start(&mut self)
+ where
+ T: Default,
+ {
+ let me = self.nodes.alloc(Node::new(T::default()));
+ if let Some((parent, last_child)) = self.current_path.last_mut() {
+ let slot = match *last_child {
+ Some(last_child) => &mut self.nodes[last_child].next_sibling,
+ None => &mut self.nodes[*parent].first_child,
+ };
+ let prev = slot.replace(me);
+ assert!(prev.is_none());
+ *last_child = Some(me);
+ }
+
+ self.current_path.push((me, None));
+ }
+
+ pub fn finish(&mut self, data: T) {
+ let (me, _last_child) = self.current_path.pop().unwrap();
+ self.nodes[me].data = data;
+ }
+
+ pub fn root(&self) -> Option<Idx<T>> {
+ self.nodes.iter().next().map(|(idx, _)| idx)
+ }
+
+ pub fn children(&self, idx: Idx<T>) -> impl Iterator<Item = Idx<T>> + '_ {
+ NodeIter { nodes: &self.nodes, next: self.nodes[idx].first_child }
+ }
+ pub fn clear(&mut self) {
+ self.nodes.clear();
+ self.current_path.clear();
+ }
+}
+
+impl<T> ops::Index<Idx<T>> for Tree<T> {
+ type Output = T;
+ fn index(&self, index: Idx<T>) -> &T {
+ &self.nodes[index].data
+ }
+}
+
+pub struct Node<T> {
+ data: T,
+ first_child: Option<Idx<T>>,
+ next_sibling: Option<Idx<T>>,
+}
+
+impl<T> Node<T> {
+ fn new(data: T) -> Node<T> {
+ Node { data, first_child: None, next_sibling: None }
+ }
+}
+
+struct NodeIter<'a, T> {
+ nodes: &'a Arena<Node<T>>,
+ next: Option<Idx<T>>,
+}
+
+impl<'a, T> Iterator for NodeIter<'a, T> {
+ type Item = Idx<T>;
+
+ fn next(&mut self) -> Option<Idx<T>> {
+ self.next.map(|next| {
+ self.next = self.nodes[next].next_sibling;
+ next
+ })
+ }
+}
From 0ac5ed5a84799e52770cdd5edf0b8c099c3c0421 Mon Sep 17 00:00:00 2001
From: Aleksey Kladov <aleksey.kladov@gmail.com>
Date: Sat, 25 Apr 2020 21:11:18 +0200
Subject: [PATCH 7/7] Remove dead code
---
editors/code/src/client.ts | 29 -----------------------------
1 file changed, 29 deletions(-)
diff --git a/editors/code/src/client.ts b/editors/code/src/client.ts
index 0ad4b63aeb1..f702829cdf2 100644
--- a/editors/code/src/client.ts
+++ b/editors/code/src/client.ts
@@ -42,35 +42,6 @@ export async function createClient(serverPath: string, cwd: string): Promise<lc.
clientOptions,
);
- // HACK: This is an awful way of filtering out the decorations notifications
- // However, pending proper support, this is the most effecitve approach
- // Proper support for this would entail a change to vscode-languageclient to allow not notifying on certain messages
- // Or the ability to disable the serverside component of highlighting (but this means that to do tracing we need to disable hihlighting)
- // This also requires considering our settings strategy, which is work which needs doing
- // @ts-ignore The tracer is private to vscode-languageclient, but we need access to it to not log publishDecorations requests
- res._tracer = {
- log: (messageOrDataObject: string | unknown, data?: string) => {
- if (typeof messageOrDataObject === 'string') {
- if (
- messageOrDataObject.includes(
- 'rust-analyzer/publishDecorations',
- ) ||
- messageOrDataObject.includes(
- 'rust-analyzer/decorationsRequest',
- )
- ) {
- // Don't log publish decorations requests
- } else {
- // @ts-ignore This is just a utility function
- res.logTrace(messageOrDataObject, data);
- }
- } else {
- // @ts-ignore
- res.logObjectTrace(messageOrDataObject);
- }
- },
- };
-
// To turn on all proposed features use: res.registerProposedFeatures();
// Here we want to enable CallHierarchyFeature and SemanticTokensFeature
// since they are available on stable.