fix(subscriber): do not report excessive polling (#378) (#440)

When entering and exiting a span the old code was also updating the parent
stats. This was causing excessive polling being reported for the parent tasks.
See issue #378 for more details. The regression was introduced by the refactor
in #238.
This fixes the issue by limiting updates to the current span.

Closes #378

Co-authored-by: Hayden Stainsby <[email protected]>
Co-authored-by: Eliza Weisman <[email protected]>

Author: 3 people

console-subscriber/src/lib.rs

@@ -25,7 +25,7 @@ use tracing_core::{
 };
 use tracing_subscriber::{
     layer::Context,
-    registry::{Extensions, LookupSpan, SpanRef},
+    registry::{Extensions, LookupSpan},
     Layer,
 };
 
@@ -789,87 +789,59 @@ where
     }
 
     fn on_enter(&self, id: &span::Id, cx: Context<'_, S>) {
-        fn update<S: Subscriber + for<'a> LookupSpan<'a>>(
-            span: &SpanRef<S>,
-            at: Option<Instant>,
-        ) -> Option<Instant> {
+        if let Some(span) = cx.span(id) {
+            let now = Instant::now();
             let exts = span.extensions();
             // if the span we are entering is a task or async op, record the
             // poll stats.
             if let Some(stats) = exts.get::<Arc<stats::TaskStats>>() {
-                let at = at.unwrap_or_else(Instant::now);
-                stats.start_poll(at);
-                Some(at)
+                stats.start_poll(now);
             } else if let Some(stats) = exts.get::<Arc<stats::AsyncOpStats>>() {
-                let at = at.unwrap_or_else(Instant::now);
-                stats.start_poll(at);
-                Some(at)
-            // otherwise, is the span a resource? in that case, we also want
-            // to enter it, although we don't care about recording poll
-            // stats.
+                stats.start_poll(now);
             } else if exts.get::<Arc<stats::ResourceStats>>().is_some() {
-                Some(at.unwrap_or_else(Instant::now))
+                // otherwise, is the span a resource? in that case, we also want
+                // to enter it, although we don't care about recording poll
+                // stats.
             } else {
-                None
-            }
-        }
+                return;
+            };
 
-        if let Some(span) = cx.span(id) {
-            if let Some(now) = update(&span, None) {
-                if let Some(parent) = span.parent() {
-                    update(&parent, Some(now));
-                }
-                self.current_spans
-                    .get_or_default()
-                    .borrow_mut()
-                    .push(id.clone());
-
-                self.record(|| record::Event::Enter {
-                    id: id.into_u64(),
-                    at: self.base_time.to_system_time(now),
-                });
-            }
+            self.current_spans
+                .get_or_default()
+                .borrow_mut()
+                .push(id.clone());
+
+            self.record(|| record::Event::Enter {
+                id: id.into_u64(),
+                at: self.base_time.to_system_time(now),
+            });
         }
     }
 
     fn on_exit(&self, id: &span::Id, cx: Context<'_, S>) {
-        fn update<S: Subscriber + for<'a> LookupSpan<'a>>(
-            span: &SpanRef<S>,
-            at: Option<Instant>,
-        ) -> Option<Instant> {
+        if let Some(span) = cx.span(id) {
             let exts = span.extensions();
+            let now = Instant::now();
             // if the span we are entering is a task or async op, record the
             // poll stats.
             if let Some(stats) = exts.get::<Arc<stats::TaskStats>>() {
-                let at = at.unwrap_or_else(Instant::now);
-                stats.end_poll(at);
-                Some(at)
+                stats.end_poll(now);
             } else if let Some(stats) = exts.get::<Arc<stats::AsyncOpStats>>() {
-                let at = at.unwrap_or_else(Instant::now);
-                stats.end_poll(at);
-                Some(at)
+                stats.end_poll(now);
+            } else if exts.get::<Arc<stats::ResourceStats>>().is_some() {
                 // otherwise, is the span a resource? in that case, we also want
                 // to enter it, although we don't care about recording poll
                 // stats.
-            } else if exts.get::<Arc<stats::ResourceStats>>().is_some() {
-                Some(at.unwrap_or_else(Instant::now))
             } else {
-                None
-            }
-        }
+                return;
+            };
 
-        if let Some(span) = cx.span(id) {
-            if let Some(now) = update(&span, None) {
-                if let Some(parent) = span.parent() {
-                    update(&parent, Some(now));
-                }
-                self.current_spans.get_or_default().borrow_mut().pop(id);
+            self.current_spans.get_or_default().borrow_mut().pop(id);
 
-                self.record(|| record::Event::Exit {
-                    id: id.into_u64(),
-                    at: self.base_time.to_system_time(now),
-                });
-            }
+            self.record(|| record::Event::Exit {
+                id: id.into_u64(),
+                at: self.base_time.to_system_time(now),
+            });
         }
     }