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 55cbea6b8ab75165e23d766eaea972581d847169..a14cdbe15526160f7eb7fd73ba857feb6eb1f0f3 100644 (file)
--- 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::microseconds>(
-          std::chrono::steady_clock::now() - startWork_);
+          now - startWork_);
       idle = std::chrono::duration_cast<std::chrono::microseconds>(
           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 9912d17b1f9e78fc5cef4ea34e8b2df5a1510b8f..a7662d5b3b0b92b3108afc99249aa09266922ffb 100644 (file)
--- 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<EventBaseObserver>& observer) {

diff --git a/folly/io/async/test/EventBaseBenchmark.cpp b/folly/io/async/test/EventBaseBenchmark.cpp
index b50e3eb64b5ddc0e9bcd09f8bf28479444baced8..7911713fba9186935c076570afb1b68fb8f703c8 100644 (file)
--- 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 <folly/Benchmark.h>
 #include <folly/io/async/EventBase.h>
 #include <folly/portability/GFlags.h>
@@ -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
  * ============================================================================
  */