aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorbors[bot] <26634292+bors[bot]@users.noreply.github.com>2020-01-06 09:41:14 +0000
committerGitHub <[email protected]>2020-01-06 09:41:14 +0000
commit010d90202102e4e30ecd670e8500170247ef74a6 (patch)
treedff3314d64d7671a37b577b0f059d0cc0ad966f4
parentb86ab5257e0760c3d563a70447cea01cb41bbf32 (diff)
parentbc91120b7c0da775a81139f91cd778258f2bf80c (diff)
Merge #2726
2726: Improve profiling output when duration filter is specified r=matklad a=michalt 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 <[email protected]> Co-authored-by: Michal Terepeta <[email protected]>
-rw-r--r--crates/ra_prof/src/lib.rs29
1 files changed, 25 insertions, 4 deletions
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 {
197 if level == 0 { 197 if level == 0 {
198 let stdout = stderr(); 198 let stdout = stderr();
199 let longer_than = stack.filter_data.longer_than; 199 let longer_than = stack.filter_data.longer_than;
200 if duration >= longer_than { 200 // Convert to millis for comparison to avoid problems with rounding
201 // (otherwise we could print `0ms` despite user's `>0` filter when
202 // `duration` is just a few nanos).
203 if duration.as_millis() > longer_than.as_millis() {
201 print(0, &stack.messages, &mut stdout.lock(), longer_than, None); 204 print(0, &stack.messages, &mut stdout.lock(), longer_than, None);
202 } 205 }
203 stack.messages.clear(); 206 stack.messages.clear();
@@ -226,7 +229,7 @@ fn print(
226 continue; 229 continue;
227 } 230 }
228 accounted_for += duration; 231 accounted_for += duration;
229 if duration >= longer_than { 232 if duration.as_millis() > longer_than.as_millis() {
230 writeln!(out, "{}{:5}ms - {}", indent, duration.as_millis(), msg) 233 writeln!(out, "{}{:5}ms - {}", indent, duration.as_millis(), msg)
231 .expect("printing profiling info to stdout"); 234 .expect("printing profiling info to stdout");
232 235
@@ -251,8 +254,9 @@ fn print(
251 254
252 if let Some(total) = total { 255 if let Some(total) = total {
253 if let Some(unaccounted) = total.checked_sub(accounted_for) { 256 if let Some(unaccounted) = total.checked_sub(accounted_for) {
254 if unaccounted >= longer_than && last > 0 { 257 let unaccounted_millis = unaccounted.as_millis();
255 writeln!(out, "{}{:5}ms - ???", indent, unaccounted.as_millis()) 258 if unaccounted_millis > longer_than.as_millis() && unaccounted_millis > 0 && last > 0 {
259 writeln!(out, "{}{:5}ms - ???", indent, unaccounted_millis)
256 .expect("printing profiling info to stdout"); 260 .expect("printing profiling info to stdout");
257 } 261 }
258 } 262 }
@@ -356,4 +360,21 @@ mod tests {
356 fn profiling_function2() { 360 fn profiling_function2() {
357 let _p = profile("profile2"); 361 let _p = profile("profile2");
358 } 362 }
363
364 #[test]
365 fn test_longer_than() {
366 let mut result = vec![];
367 let msgs = vec![
368 Message { level: 1, duration: Duration::from_nanos(3), message: "bar".to_owned() },
369 Message { level: 1, duration: Duration::from_nanos(2), message: "bar".to_owned() },
370 Message { level: 0, duration: Duration::from_millis(1), message: "foo".to_owned() },
371 ];
372 print(0, &msgs, &mut result, Duration::from_millis(0), Some(Duration::from_millis(1)));
373 // The calls to `bar` are so short that they'll be rounded to 0ms and should get collapsed
374 // when printing.
375 assert_eq!(
376 std::str::from_utf8(&result).unwrap(),
377 " 1ms - foo\n 0ms - bar (2 calls)\n"
378 );
379 }
359} 380}