From bc91120b7c0da775a81139f91cd778258f2bf80c Mon Sep 17 00:00:00 2001 From: Michal Terepeta Date: Thu, 2 Jan 2020 17:21:40 +0100 Subject: Improve profiling output when duration filter is specified In particular: - Use strict inequality for comparisons, since that's what the filter syntax supports. - Convert to millis for comparisons, since that's the unit used both for the filter and when printing. Now something like `RA_PROFILE='*>0'` will only print things that took at least 1ms (when rounded to millis). Signed-off-by: Michal Terepeta --- crates/ra_prof/src/lib.rs | 29 +++++++++++++++++++++++++---- 1 file changed, 25 insertions(+), 4 deletions(-) (limited to 'crates/ra_prof/src') diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs index f260c40a3..6dde304b1 100644 --- a/crates/ra_prof/src/lib.rs +++ b/crates/ra_prof/src/lib.rs @@ -197,7 +197,10 @@ impl Drop for Profiler { if level == 0 { let stdout = stderr(); let longer_than = stack.filter_data.longer_than; - if duration >= 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(0, &stack.messages, &mut stdout.lock(), longer_than, None); } stack.messages.clear(); @@ -226,7 +229,7 @@ fn print( continue; } accounted_for += duration; - if duration >= longer_than { + if duration.as_millis() > longer_than.as_millis() { writeln!(out, "{}{:5}ms - {}", indent, duration.as_millis(), msg) .expect("printing profiling info to stdout"); @@ -251,8 +254,9 @@ fn print( if let Some(total) = total { if let Some(unaccounted) = total.checked_sub(accounted_for) { - if unaccounted >= longer_than && last > 0 { - writeln!(out, "{}{:5}ms - ???", indent, unaccounted.as_millis()) + let unaccounted_millis = unaccounted.as_millis(); + if unaccounted_millis > longer_than.as_millis() && unaccounted_millis > 0 && last > 0 { + writeln!(out, "{}{:5}ms - ???", indent, unaccounted_millis) .expect("printing profiling info to stdout"); } } @@ -356,4 +360,21 @@ mod tests { 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), message: "bar".to_owned() }, + Message { level: 1, duration: Duration::from_nanos(2), message: "bar".to_owned() }, + Message { level: 0, duration: Duration::from_millis(1), message: "foo".to_owned() }, + ]; + print(0, &msgs, &mut result, Duration::from_millis(0), Some(Duration::from_millis(1))); + // 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" + ); + } } -- cgit v1.2.3