From 8a551fa65d6b3cc4e99b2311b795645611a0f110 Mon Sep 17 00:00:00 2001 From: asonix Date: Mon, 9 Dec 2024 19:14:46 -0600 Subject: [PATCH] Reduce poll timer sampling from ~100% to ~10% This should improve performance just a little bit --- src/future.rs | 86 +++++++++++++++++++++++++++------------------------ 1 file changed, 45 insertions(+), 41 deletions(-) diff --git a/src/future.rs b/src/future.rs index e553491..36eb96d 100644 --- a/src/future.rs +++ b/src/future.rs @@ -141,50 +141,54 @@ where let out = this.inner.poll(cx); let elapsed = start.elapsed(); - if elapsed > Duration::from_micros(10) { - metrics::counter!(crate::init_metrics::FUTURE_POLL_TIMER_EXCEEDED, "timer" => this.name.to_string()).increment(1); - metrics::histogram!(crate::init_metrics::FUTURE_POLL_TIMER_EXCEEDED_SECONDS, "timer" => this.name.to_string()).record(elapsed.as_secs_f64()); - } - if elapsed > Duration::from_secs(1) { - #[cfg(feature = "poll-timer-warnings")] - tracing::warn!( - "Future {} polled for {} seconds", - this.name, - elapsed.as_secs() - ); + // only record 1 in 10 polls + if elapsed.as_micros() % 10 == 0 { + if elapsed > Duration::from_micros(10) { + metrics::counter!(crate::init_metrics::FUTURE_POLL_TIMER_EXCEEDED, "timer" => this.name.to_string()).increment(1); + metrics::histogram!(crate::init_metrics::FUTURE_POLL_TIMER_EXCEEDED_SECONDS, "timer" => this.name.to_string()).record(elapsed.as_secs_f64()); + } - #[cfg(not(feature = "poll-timer-warnings"))] - tracing::debug!( - "Future {} polled for {} seconds", - this.name, - elapsed.as_secs() - ); - } else if elapsed > Duration::from_millis(1) { - #[cfg(feature = "poll-timer-warnings")] - tracing::warn!("Future {} polled for {} ms", this.name, elapsed.as_millis()); + if elapsed > Duration::from_secs(1) { + #[cfg(feature = "poll-timer-warnings")] + tracing::warn!( + "Future {} polled for {} seconds", + this.name, + elapsed.as_secs() + ); - #[cfg(not(feature = "poll-timer-warnings"))] - tracing::debug!("Future {} polled for {} ms", this.name, elapsed.as_millis()); - } else if elapsed > Duration::from_micros(200) { - #[cfg(feature = "poll-timer-warnings")] - tracing::debug!( - "Future {} polled for {} microseconds", - this.name, - elapsed.as_micros(), - ); - #[cfg(not(feature = "poll-timer-warnings"))] - tracing::trace!( - "Future {} polled for {} microseconds", - this.name, - elapsed.as_micros(), - ); - } else if elapsed > Duration::from_micros(1) { - tracing::trace!( - "Future {} polled for {} microseconds", - this.name, - elapsed.as_micros() - ); + #[cfg(not(feature = "poll-timer-warnings"))] + tracing::debug!( + "Future {} polled for {} seconds", + this.name, + elapsed.as_secs() + ); + } else if elapsed > Duration::from_millis(1) { + #[cfg(feature = "poll-timer-warnings")] + tracing::warn!("Future {} polled for {} ms", this.name, elapsed.as_millis()); + + #[cfg(not(feature = "poll-timer-warnings"))] + tracing::debug!("Future {} polled for {} ms", this.name, elapsed.as_millis()); + } else if elapsed > Duration::from_micros(200) { + #[cfg(feature = "poll-timer-warnings")] + tracing::debug!( + "Future {} polled for {} microseconds", + this.name, + elapsed.as_micros(), + ); + #[cfg(not(feature = "poll-timer-warnings"))] + tracing::trace!( + "Future {} polled for {} microseconds", + this.name, + elapsed.as_micros(), + ); + } else if elapsed > Duration::from_micros(1) { + tracing::trace!( + "Future {} polled for {} microseconds", + this.name, + elapsed.as_micros() + ); + } } out