Merge #2053

2053: show unaccounted for time in profiling r=matklad a=matklad



Co-authored-by: Aleksey Kladov <[email protected]>

1 files changed, 20 insertions, 3 deletions

diff --git a/crates/ra_prof/src/lib.rs b/crates/ra_prof/src/lib.rs
index 885a98750..e5385f51b 100644
--- a/crates/ra_prof/src/lib.rs
+++ b/crates/ra_prof/src/lib.rs
@@ -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.