From c8d44a337460bb0f2c3c1924397fe241cf45e5e2 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?David=20Ml=C3=A1dek?= <david.mladek.cz@gmail.com>
Date: Sat, 20 Apr 2024 21:31:33 +0200
Subject: [PATCH] tracing-subscriber: count numbers of enters in `Timings`

---
 tracing-subscriber/src/fmt/fmt_subscriber.rs | 22 ++++++++++++++------
 1 file changed, 16 insertions(+), 6 deletions(-)

diff --git a/tracing-subscriber/src/fmt/fmt_subscriber.rs b/tracing-subscriber/src/fmt/fmt_subscriber.rs
index 2dd539e6a5..0f37d080c1 100644
--- a/tracing-subscriber/src/fmt/fmt_subscriber.rs
+++ b/tracing-subscriber/src/fmt/fmt_subscriber.rs
@@ -870,9 +870,12 @@ where
             let span = ctx.span(id).expect("Span not found, this is a bug");
             let mut extensions = span.extensions_mut();
             if let Some(timings) = extensions.get_mut::<Timings>() {
-                let now = Instant::now();
-                timings.idle += (now - timings.last).as_nanos() as u64;
-                timings.last = now;
+                if timings.entered_count == 0 {
+                    let now = Instant::now();
+                    timings.idle += (now - timings.last).as_nanos() as u64;
+                    timings.last = now;
+                }
+                timings.entered_count += 1;
             }
 
             if self.fmt_span.trace_enter() {
@@ -890,9 +893,12 @@ where
             let span = ctx.span(id).expect("Span not found, this is a bug");
             let mut extensions = span.extensions_mut();
             if let Some(timings) = extensions.get_mut::<Timings>() {
-                let now = Instant::now();
-                timings.busy += (now - timings.last).as_nanos() as u64;
-                timings.last = now;
+                timings.entered_count -= 1;
+                if timings.entered_count == 0 {
+                    let now = Instant::now();
+                    timings.busy += (now - timings.last).as_nanos() as u64;
+                    timings.last = now;
+                }
             }
 
             if self.fmt_span.trace_exit() {
@@ -914,7 +920,9 @@ where
                     busy,
                     mut idle,
                     last,
+                    entered_count,
                 } = *timing;
+                debug_assert_eq!(entered_count, 0);
                 idle += (Instant::now() - last).as_nanos() as u64;
 
                 let t_idle = field::display(TimingDisplay(idle));
@@ -1204,6 +1212,7 @@ struct Timings {
     idle: u64,
     busy: u64,
     last: Instant,
+    entered_count: u64,
 }
 
 impl Timings {
@@ -1212,6 +1221,7 @@ impl Timings {
             idle: 0,
             busy: 0,
             last: Instant::now(),
+            entered_count: 0,
         }
     }
 }