diff options
author | bors[bot] <26634292+bors[bot]@users.noreply.github.com> | 2020-01-06 09:41:14 +0000 |
---|---|---|
committer | GitHub <[email protected]> | 2020-01-06 09:41:14 +0000 |
commit | 010d90202102e4e30ecd670e8500170247ef74a6 (patch) | |
tree | dff3314d64d7671a37b577b0f059d0cc0ad966f4 /crates/ra_prof/src/lib.rs | |
parent | b86ab5257e0760c3d563a70447cea01cb41bbf32 (diff) | |
parent | bc91120b7c0da775a81139f91cd778258f2bf80c (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]>
Diffstat (limited to 'crates/ra_prof/src/lib.rs')
-rw-r--r-- | crates/ra_prof/src/lib.rs | 29 |
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 | } |