show unaccounted for time in profiling

This commit is contained in:
Aleksey Kladov 2019-10-24 09:05:11 +03:00
parent 2197205885
commit baa968e71c

View file

@ -198,7 +198,7 @@ impl Drop for Profiler {
let stdout = stderr();
let longer_than = stack.filter_data.longer_than;
if duration >= longer_than {
print(0, &stack.messages, &mut stdout.lock(), longer_than);
print(0, &stack.messages, &mut stdout.lock(), longer_than, None);
}
stack.messages.clear();
}
@ -209,20 +209,28 @@ impl Drop for Profiler {
}
}
fn print(lvl: usize, msgs: &[Message], out: &mut impl Write, longer_than: Duration) {
fn print(
lvl: usize,
msgs: &[Message],
out: &mut impl Write,
longer_than: Duration,
total: Option<Duration>,
) {
let mut last = 0;
let indent = repeat(" ").take(lvl + 1).collect::<String>();
// We output hierarchy for long calls, but sum up all short calls
let mut short = Vec::new();
let mut accounted_for = Duration::default();
for (i, &Message { level, duration, message: ref msg }) in msgs.iter().enumerate() {
if level != lvl {
continue;
}
accounted_for += duration;
if duration >= longer_than {
writeln!(out, "{} {:6}ms - {}", indent, duration.as_millis(), msg)
.expect("printing profiling info to stdout");
print(lvl + 1, &msgs[last..i], out, longer_than);
print(lvl + 1, &msgs[last..i], out, longer_than, Some(duration));
} else {
short.push((msg, duration))
}
@ -240,6 +248,15 @@ fn print(lvl: usize, msgs: &[Message], out: &mut impl Write, longer_than: Durati
writeln!(out, "{} {:6}ms - {} ({} calls)", indent, total_duration.as_millis(), msg, count)
.expect("printing profiling info to stdout");
}
if let Some(total) = total {
if let Some(unaccounted) = total.checked_sub(accounted_for) {
if unaccounted >= longer_than && last > 0 {
writeln!(out, "{} {:6}ms - ???", indent, unaccounted.as_millis())
.expect("printing profiling info to stdout");
}
}
}
}
/// Prints backtrace to stderr, useful for debugging.