diff --git a/tracing-subscriber/src/fmt/fmt_layer.rs b/tracing-subscriber/src/fmt/fmt_layer.rs index 747e9444..9dbc0fe8 100644 --- a/tracing-subscriber/src/fmt/fmt_layer.rs +++ b/tracing-subscriber/src/fmt/fmt_layer.rs @@ -890,9 +890,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::() { - 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() { @@ -910,9 +913,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::() { - 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() { @@ -934,7 +940,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)); @@ -1224,6 +1232,7 @@ struct Timings { idle: u64, busy: u64, last: Instant, + entered_count: u64, } impl Timings { @@ -1232,6 +1241,7 @@ impl Timings { idle: 0, busy: 0, last: Instant::now(), + entered_count: 0, } } }