From: Dave Watson Date: Wed, 17 Jan 2018 16:17:44 +0000 (-0800) Subject: Loop Time X-Git-Tag: v2018.01.22.00~22 X-Git-Url: http://plrg.eecs.uci.edu/git/?p=folly.git;a=commitdiff_plain;h=a4306bcdf04c95f321a96ab9b0f29de1c1e678f1 Loop Time Summary: Only do the exponential loop smoothing once every 10ms. If we need it before then, do it linearly. Also, remove one of the now()s by only calling it once. Reviewed By: bmaurer, yfeldblum Differential Revision: D6690047 fbshipit-source-id: 8267c01064aabc17cb8e86eb888e6120c99a129f --- diff --git a/folly/io/async/EventBase.cpp b/folly/io/async/EventBase.cpp index 55cbea6b..a14cdbe1 100644 --- a/folly/io/async/EventBase.cpp +++ b/folly/io/async/EventBase.cpp @@ -290,7 +290,7 @@ bool EventBase::loopBody(int flags) { if (enableTimeMeasurement_) { prev = std::chrono::steady_clock::now(); - idleStart = std::chrono::steady_clock::now(); + idleStart = prev; } while (!stop_.load(std::memory_order_relaxed)) { @@ -318,15 +318,15 @@ bool EventBase::loopBody(int flags) { ranLoopCallbacks = runLoopCallbacks(); if (enableTimeMeasurement_) { + auto now = std::chrono::steady_clock::now(); busy = std::chrono::duration_cast( - std::chrono::steady_clock::now() - startWork_); + now - startWork_); idle = std::chrono::duration_cast( startWork_ - idleStart); + auto loop_time = busy + idle; - avgLoopTime_.addSample(std::chrono::microseconds(idle), - std::chrono::microseconds(busy)); - maxLatencyLoopTime_.addSample(std::chrono::microseconds(idle), - std::chrono::microseconds(busy)); + avgLoopTime_.addSample(loop_time, busy); + maxLatencyLoopTime_.addSample(loop_time, busy); if (observer_) { if (observerSampleCount_++ == observer_->getSampleRate()) { @@ -335,15 +335,15 @@ bool EventBase::loopBody(int flags) { } } - VLOG(11) << "EventBase " << this << " did not timeout " << - " loop time guess: " << (busy + idle).count() << - " idle time: " << idle.count() << - " busy time: " << busy.count() << - " avgLoopTime: " << avgLoopTime_.get() << - " maxLatencyLoopTime: " << maxLatencyLoopTime_.get() << - " maxLatency_: " << maxLatency_.count() << "us" << - " notificationQueueSize: " << getNotificationQueueSize() << - " nothingHandledYet(): " << nothingHandledYet(); + VLOG(11) << "EventBase " << this << " did not timeout " + << " loop time guess: " << loop_time.count() + << " idle time: " << idle.count() + << " busy time: " << busy.count() + << " avgLoopTime: " << avgLoopTime_.get() + << " maxLatencyLoopTime: " << maxLatencyLoopTime_.get() + << " maxLatency_: " << maxLatency_.count() << "us" + << " notificationQueueSize: " << getNotificationQueueSize() + << " nothingHandledYet(): " << nothingHandledYet(); // see if our average loop time has exceeded our limit if ((maxLatency_ > std::chrono::microseconds::zero()) && @@ -355,7 +355,7 @@ bool EventBase::loopBody(int flags) { } // Our loop run did real work; reset the idle timer - idleStart = std::chrono::steady_clock::now(); + idleStart = now; } else { VLOG(11) << "EventBase " << this << " did not timeout"; } @@ -651,31 +651,21 @@ void EventBase::SmoothLoopTime::reset(double value) { } void EventBase::SmoothLoopTime::addSample( - std::chrono::microseconds idle, + std::chrono::microseconds total, std::chrono::microseconds busy) { - /* - * Position at which the busy sample is considered to be taken. - * (Allows to quickly skew our average without editing much code) - */ - enum BusySamplePosition { - RIGHT = 0, // busy sample placed at the end of the iteration - CENTER = 1, // busy sample placed at the middle point of the iteration - LEFT = 2, // busy sample placed at the beginning of the iteration - }; - - // See http://en.wikipedia.org/wiki/Moving_average#Exponential_moving_average - // and D676020 for more info on this calculation. - VLOG(11) << "idle " << idle.count() << " oldBusyLeftover_ " - << oldBusyLeftover_.count() << " idle + oldBusyLeftover_ " - << (idle + oldBusyLeftover_).count() << " busy " << busy.count() - << " " << __PRETTY_FUNCTION__; - idle += oldBusyLeftover_ + busy; - oldBusyLeftover_ = (busy * BusySamplePosition::CENTER) / 2; - idle -= oldBusyLeftover_; - - double coeff = exp(idle.count() * expCoeff_); - value_ *= coeff; - value_ += (1.0 - coeff) * busy.count(); + if ((buffer_time_ + total) > buffer_interval_ && buffer_cnt_ > 0) { + // See https://en.wikipedia.org/wiki/Exponential_smoothing for + // more info on this calculation. + double coeff = exp(buffer_time_.count() * expCoeff_); + value_ = + value_ * coeff + (1.0 - coeff) * (busy_buffer_.count() / buffer_cnt_); + buffer_time_ = std::chrono::microseconds{0}; + busy_buffer_ = std::chrono::microseconds{0}; + buffer_cnt_ = 0; + } + buffer_time_ += total; + busy_buffer_ += busy; + buffer_cnt_++; } bool EventBase::nothingHandledYet() const noexcept { @@ -753,4 +743,5 @@ VirtualEventBase& EventBase::getVirtualEventBase() { return *virtualEventBase_; } +constexpr std::chrono::milliseconds EventBase::SmoothLoopTime::buffer_interval_; } // namespace folly diff --git a/folly/io/async/EventBase.h b/folly/io/async/EventBase.h index 9912d17b..a7662d5b 100644 --- a/folly/io/async/EventBase.h +++ b/folly/io/async/EventBase.h @@ -541,9 +541,7 @@ class EventBase : private boost::noncopyable, class SmoothLoopTime { public: explicit SmoothLoopTime(std::chrono::microseconds timeInterval) - : expCoeff_(-1.0 / timeInterval.count()), - value_(0.0), - oldBusyLeftover_(0) { + : expCoeff_(-1.0 / timeInterval.count()), value_(0.0) { VLOG(11) << "expCoeff_ " << expCoeff_ << " " << __PRETTY_FUNCTION__; } @@ -551,11 +549,14 @@ class EventBase : private boost::noncopyable, void reset(double value = 0.0); void addSample( - std::chrono::microseconds idle, + std::chrono::microseconds total, std::chrono::microseconds busy); double get() const { - return value_; + // Add the outstanding buffered times linearly, to avoid + // expensive exponentiation + auto lcoeff = buffer_time_.count() * -expCoeff_; + return value_ * (1.0 - lcoeff) + lcoeff * busy_buffer_.count(); } void dampen(double factor) { @@ -565,7 +566,10 @@ class EventBase : private boost::noncopyable, private: double expCoeff_; double value_; - std::chrono::microseconds oldBusyLeftover_; + std::chrono::microseconds buffer_time_{0}; + std::chrono::microseconds busy_buffer_{0}; + uint64_t buffer_cnt_{0}; + static constexpr std::chrono::milliseconds buffer_interval_{10}; }; void setObserver(const std::shared_ptr& observer) { diff --git a/folly/io/async/test/EventBaseBenchmark.cpp b/folly/io/async/test/EventBaseBenchmark.cpp index b50e3eb6..7911713f 100644 --- a/folly/io/async/test/EventBaseBenchmark.cpp +++ b/folly/io/async/test/EventBaseBenchmark.cpp @@ -13,7 +13,6 @@ * See the License for the specific language governing permissions and * limitations under the License. */ - #include #include #include @@ -64,8 +63,8 @@ BENCHMARK_RELATIVE(timeMeasurementsOff, n) { * ============================================================================ * folly/io/async/test/EventBaseBenchmark.cpp relative time/iter iters/s * ============================================================================ - * timeMeasurementsOn 2.02us 494.57K - * timeMeasurementsOff 231.19% 874.58ns 1.14M + * timeMeasurementsOn 1.25us 798.33K + * timeMeasurementsOff 214.47% 584.04ns 1.71M * ============================================================================ */