2020-04-25 08:02:09 -05:00
|
|
|
//! Simple hierarchical profiler
|
2020-04-25 14:04:04 -05:00
|
|
|
use once_cell::sync::Lazy;
|
2020-04-25 08:02:09 -05:00
|
|
|
use std::{
|
|
|
|
cell::RefCell,
|
|
|
|
collections::{BTreeMap, HashSet},
|
2021-01-21 10:04:50 -06:00
|
|
|
env,
|
2020-04-25 08:02:09 -05:00
|
|
|
io::{stderr, Write},
|
|
|
|
sync::{
|
|
|
|
atomic::{AtomicBool, Ordering},
|
|
|
|
RwLock,
|
|
|
|
},
|
|
|
|
time::{Duration, Instant},
|
|
|
|
};
|
|
|
|
|
2020-04-25 14:04:04 -05:00
|
|
|
use crate::tree::{Idx, Tree};
|
2020-04-25 08:02:09 -05:00
|
|
|
|
|
|
|
/// 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() {
|
2021-01-21 10:04:50 -06:00
|
|
|
countme::enable(env::var("RA_COUNT").is_ok());
|
|
|
|
let spec = env::var("RA_PROFILE").unwrap_or_default();
|
2020-04-25 08:02:09 -05:00
|
|
|
init_from(&spec);
|
|
|
|
}
|
|
|
|
|
|
|
|
pub fn init_from(spec: &str) {
|
|
|
|
let filter = if spec.is_empty() { Filter::disabled() } else { Filter::from_spec(spec) };
|
2020-04-25 12:29:41 -05:00
|
|
|
filter.install();
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
|
2020-11-02 06:13:32 -06:00
|
|
|
type Label = &'static str;
|
2020-04-25 08:02:09 -05:00
|
|
|
|
|
|
|
/// This function starts a profiling scope in the current execution stack with a given description.
|
2020-04-25 16:10:44 -05:00
|
|
|
/// It returns a `Profile` struct that measures elapsed time between this method invocation and `Profile` struct drop.
|
|
|
|
/// It supports nested profiling scopes in case when this function is invoked multiple times at the execution stack.
|
|
|
|
/// In this case the profiling information will be nested at the output.
|
2020-04-25 08:02:09 -05:00
|
|
|
/// Profiling information is being printed in the stderr.
|
|
|
|
///
|
|
|
|
/// # Example
|
|
|
|
/// ```
|
2020-08-12 09:32:36 -05:00
|
|
|
/// profile::init_from("profile1|profile2@2");
|
2020-04-25 08:02:09 -05:00
|
|
|
/// profiling_function1();
|
|
|
|
///
|
|
|
|
/// fn profiling_function1() {
|
2020-08-12 09:32:36 -05:00
|
|
|
/// let _p = profile::span("profile1");
|
2020-04-25 08:02:09 -05:00
|
|
|
/// profiling_function2();
|
|
|
|
/// }
|
|
|
|
///
|
|
|
|
/// fn profiling_function2() {
|
2020-08-12 09:32:36 -05:00
|
|
|
/// let _p = profile::span("profile2");
|
2020-04-25 08:02:09 -05:00
|
|
|
/// }
|
|
|
|
/// ```
|
|
|
|
/// This will print in the stderr the following:
|
|
|
|
/// ```text
|
|
|
|
/// 0ms - profile
|
|
|
|
/// 0ms - profile2
|
|
|
|
/// ```
|
2020-08-12 09:32:36 -05:00
|
|
|
pub fn span(label: Label) -> ProfileSpan {
|
2020-04-25 08:02:09 -05:00
|
|
|
assert!(!label.is_empty());
|
2020-04-25 16:10:44 -05:00
|
|
|
|
|
|
|
if PROFILING_ENABLED.load(Ordering::Relaxed)
|
|
|
|
&& PROFILE_STACK.with(|stack| stack.borrow_mut().push(label))
|
|
|
|
{
|
2020-08-12 09:32:36 -05:00
|
|
|
ProfileSpan(Some(ProfilerImpl { label, detail: None }))
|
2020-04-25 16:10:44 -05:00
|
|
|
} else {
|
2020-08-12 09:32:36 -05:00
|
|
|
ProfileSpan(None)
|
2020-04-25 16:10:44 -05:00
|
|
|
}
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
|
2020-08-12 09:32:36 -05:00
|
|
|
pub struct ProfileSpan(Option<ProfilerImpl>);
|
2020-04-25 16:10:44 -05:00
|
|
|
|
|
|
|
struct ProfilerImpl {
|
|
|
|
label: Label,
|
2020-04-25 08:02:09 -05:00
|
|
|
detail: Option<String>,
|
|
|
|
}
|
|
|
|
|
2020-08-12 09:32:36 -05:00
|
|
|
impl ProfileSpan {
|
|
|
|
pub fn detail(mut self, detail: impl FnOnce() -> String) -> ProfileSpan {
|
2020-04-25 16:10:44 -05:00
|
|
|
if let Some(profiler) = &mut self.0 {
|
|
|
|
profiler.detail = Some(detail())
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
self
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-04-25 16:10:44 -05:00
|
|
|
impl Drop for ProfilerImpl {
|
2020-04-25 12:50:42 -05:00
|
|
|
fn drop(&mut self) {
|
2020-04-25 16:10:44 -05:00
|
|
|
PROFILE_STACK.with(|it| it.borrow_mut().pop(self.label, self.detail.take()));
|
2020-04-25 12:50:42 -05:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-04-25 12:29:41 -05:00
|
|
|
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()));
|
2020-04-25 08:02:09 -05:00
|
|
|
|
2020-04-25 12:29:41 -05:00
|
|
|
#[derive(Default, Clone, Debug)]
|
2020-04-25 08:02:09 -05:00
|
|
|
struct Filter {
|
|
|
|
depth: usize,
|
2020-04-25 12:29:41 -05:00
|
|
|
allowed: HashSet<String>,
|
2020-04-25 08:02:09 -05:00
|
|
|
longer_than: Duration,
|
2020-04-25 12:29:41 -05:00
|
|
|
version: usize,
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
|
|
|
|
impl Filter {
|
2020-04-25 12:29:41 -05:00
|
|
|
fn disabled() -> Filter {
|
|
|
|
Filter::default()
|
|
|
|
}
|
|
|
|
|
2020-04-25 08:02:09 -05:00
|
|
|
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 =
|
2020-04-25 12:29:41 -05:00
|
|
|
if spec == "*" { HashSet::new() } else { spec.split('|').map(String::from).collect() };
|
2020-04-25 12:50:42 -05:00
|
|
|
Filter { depth, allowed, longer_than, version: 0 }
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
|
2020-04-25 12:29:41 -05:00
|
|
|
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;
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
struct ProfileStack {
|
|
|
|
starts: Vec<Instant>,
|
2020-04-25 12:29:41 -05:00
|
|
|
filter: Filter,
|
2020-04-25 14:04:04 -05:00
|
|
|
messages: Tree<Message>,
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
|
2020-04-25 14:04:04 -05:00
|
|
|
#[derive(Default)]
|
2020-04-25 08:02:09 -05:00
|
|
|
struct Message {
|
|
|
|
duration: Duration,
|
|
|
|
label: Label,
|
|
|
|
detail: Option<String>,
|
|
|
|
}
|
|
|
|
|
|
|
|
impl ProfileStack {
|
|
|
|
fn new() -> ProfileStack {
|
2020-04-25 14:04:04 -05:00
|
|
|
ProfileStack { starts: Vec::new(), messages: Tree::default(), filter: Default::default() }
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
|
2020-04-25 12:29:41 -05:00
|
|
|
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;
|
|
|
|
}
|
2020-04-25 08:02:09 -05:00
|
|
|
|
2020-04-25 12:29:41 -05:00
|
|
|
self.starts.push(Instant::now());
|
2020-04-25 14:04:04 -05:00
|
|
|
self.messages.start();
|
2020-04-25 12:29:41 -05:00
|
|
|
true
|
|
|
|
}
|
2020-04-25 08:02:09 -05:00
|
|
|
|
2020-11-02 06:13:32 -06:00
|
|
|
fn pop(&mut self, label: Label, detail: Option<String>) {
|
2020-04-25 12:29:41 -05:00
|
|
|
let start = self.starts.pop().unwrap();
|
|
|
|
let duration = start.elapsed();
|
2020-04-25 14:04:04 -05:00
|
|
|
self.messages.finish(Message { duration, label, detail });
|
2020-04-25 16:10:44 -05:00
|
|
|
if self.starts.is_empty() {
|
2020-04-25 12:29:41 -05:00
|
|
|
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() {
|
2020-04-25 14:04:04 -05:00
|
|
|
if let Some(root) = self.messages.root() {
|
2020-04-25 16:10:44 -05:00
|
|
|
print(&self.messages, root, 0, longer_than, &mut stderr().lock());
|
2020-04-25 14:04:04 -05:00
|
|
|
}
|
2020-04-25 12:29:41 -05:00
|
|
|
}
|
|
|
|
self.messages.clear();
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-04-25 14:04:04 -05:00
|
|
|
fn print(
|
|
|
|
tree: &Tree<Message>,
|
|
|
|
curr: Idx<Message>,
|
|
|
|
level: u32,
|
2020-04-25 08:02:09 -05:00
|
|
|
longer_than: Duration,
|
|
|
|
out: &mut impl Write,
|
|
|
|
) {
|
2020-04-25 14:04:04 -05:00
|
|
|
let current_indent = " ".repeat(level as usize);
|
|
|
|
let detail = tree[curr].detail.as_ref().map(|it| format!(" @ {}", it)).unwrap_or_default();
|
2020-04-25 08:02:09 -05:00
|
|
|
writeln!(
|
|
|
|
out,
|
|
|
|
"{}{:5}ms - {}{}",
|
|
|
|
current_indent,
|
2020-04-25 14:04:04 -05:00
|
|
|
tree[curr].duration.as_millis(),
|
|
|
|
tree[curr].label,
|
2020-04-25 08:02:09 -05:00
|
|
|
detail,
|
|
|
|
)
|
|
|
|
.expect("printing profiling info");
|
|
|
|
|
|
|
|
let mut accounted_for = Duration::default();
|
|
|
|
let mut short_children = BTreeMap::new(); // Use `BTreeMap` to get deterministic output.
|
2020-04-25 14:04:04 -05:00
|
|
|
for child in tree.children(curr) {
|
|
|
|
accounted_for += tree[child].duration;
|
2020-04-25 08:02:09 -05:00
|
|
|
|
2020-04-25 14:04:04 -05:00
|
|
|
if tree[child].duration.as_millis() > longer_than.as_millis() {
|
|
|
|
print(tree, child, level + 1, longer_than, out)
|
2020-04-25 08:02:09 -05:00
|
|
|
} else {
|
2020-04-25 14:04:04 -05:00
|
|
|
let (total_duration, cnt) =
|
|
|
|
short_children.entry(tree[child].label).or_insert((Duration::default(), 0));
|
|
|
|
*total_duration += tree[child].duration;
|
|
|
|
*cnt += 1;
|
2020-04-25 08:02:09 -05:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
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");
|
|
|
|
}
|
|
|
|
|
2020-04-25 14:04:04 -05:00
|
|
|
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())
|
2020-04-25 08:02:09 -05:00
|
|
|
.expect("printing profiling info");
|
|
|
|
}
|
|
|
|
}
|