Optimize perf of EventBase with new option.

Summary:
Add option to disable time measurement in EventBase::loopBody()
to improve performances when time measurement is not used.

Test Plan:
Unit tests, benchmarking and manual tests.

Reviewed By: pavlo@fb.com

Subscribers: trunkagent, folly-diffs@, yfeldblum

FB internal diff: D1846020

Tasks: 6086197

Signature: t1:1846020:1424459703:9686a84027e1137ee43eb0458b0baa4fee3a8abf

folly/io/async/EventBase.cpp

@@ -141,7 +141,7 @@ static std::mutex libevent_mutex_;
  * EventBase methods
  */
 
-EventBase::EventBase()
+EventBase::EventBase(bool enableTimeMeasurement)
   : runOnceCallbacks_(nullptr)
   , stop_(false)
   , loopThread_(0)
@@ -150,6 +150,7 @@ EventBase::EventBase()
   , maxLatency_(0)
   , avgLoopTime_(2000000)
   , maxLatencyLoopTime_(avgLoopTime_)
+  , enableTimeMeasurement_(enableTimeMeasurement)
   , nextLoopCnt_(-40)       // Early wrap-around so bugs will manifest soon
   , latestLoopCnt_(nextLoopCnt_)
   , startWork_(0)
@@ -177,7 +178,7 @@ EventBase::EventBase()
 }
 
 // takes ownership of the event_base
-EventBase::EventBase(event_base* evb)
+EventBase::EventBase(event_base* evb, bool enableTimeMeasurement)
   : runOnceCallbacks_(nullptr)
   , stop_(false)
   , loopThread_(0)
@@ -187,6 +188,7 @@ EventBase::EventBase(event_base* evb)
   , maxLatency_(0)
   , avgLoopTime_(2000000)
   , maxLatencyLoopTime_(avgLoopTime_)
+  , enableTimeMeasurement_(enableTimeMeasurement)
   , nextLoopCnt_(-40)       // Early wrap-around so bugs will manifest soon
   , latestLoopCnt_(nextLoopCnt_)
   , startWork_(0)
@@ -247,6 +249,7 @@ void EventBase::setMaxReadAtOnce(uint32_t maxAtOnce) {
 // Set smoothing coefficient for loop load average; input is # of milliseconds
 // for exp(-1) decay.
 void EventBase::setLoadAvgMsec(uint32_t ms) {
+  assert(enableTimeMeasurement_);
   uint64_t us = 1000 * ms;
   if (ms > 0) {
     maxLatencyLoopTime_.setTimeInterval(us);
@@ -257,6 +260,7 @@ void EventBase::setLoadAvgMsec(uint32_t ms) {
 }
 
 void EventBase::resetLoadAvg(double value) {
+  assert(enableTimeMeasurement_);
   avgLoopTime_.reset(value);
   maxLatencyLoopTime_.reset(value);
 }
@@ -291,15 +295,23 @@ bool EventBase::loopBody(int flags) {
   bool blocking = !(flags & EVLOOP_NONBLOCK);
   bool once = (flags & EVLOOP_ONCE);
 
+  // time-measurement variables.
+  std::chrono::steady_clock::time_point prev;
+  int64_t idleStart;
+  int64_t busy;
+  int64_t idle;
+
   loopThread_.store(pthread_self(), std::memory_order_release);
 
   if (!name_.empty()) {
     setThreadName(name_);
   }
 
-  auto prev = std::chrono::steady_clock::now();
-  int64_t idleStart = std::chrono::duration_cast<std::chrono::microseconds>(
-    std::chrono::steady_clock::now().time_since_epoch()).count();
+  if (enableTimeMeasurement_) {
+    prev = std::chrono::steady_clock::now();
+    idleStart = std::chrono::duration_cast<std::chrono::microseconds>(
+      std::chrono::steady_clock::now().time_since_epoch()).count();
+  }
 
   // TODO: Read stop_ atomically with an acquire barrier.
   while (!stop_) {
@@ -325,41 +337,48 @@ bool EventBase::loopBody(int flags) {
 
     ranLoopCallbacks = runLoopCallbacks();
 
-    int64_t busy = std::chrono::duration_cast<std::chrono::microseconds>(
-      std::chrono::steady_clock::now().time_since_epoch()).count() - startWork_;
-    int64_t idle = startWork_ - idleStart;
+    if (enableTimeMeasurement_) {
+      busy = std::chrono::duration_cast<std::chrono::microseconds>(
+        std::chrono::steady_clock::now().time_since_epoch()).count() -
+        startWork_;
+      idle = startWork_ - idleStart;
 
-    avgLoopTime_.addSample(idle, busy);
-    maxLatencyLoopTime_.addSample(idle, busy);
+      avgLoopTime_.addSample(idle, busy);
+      maxLatencyLoopTime_.addSample(idle, busy);
 
-    if (observer_) {
-      if (observerSampleCount_++ == observer_->getSampleRate()) {
-        observerSampleCount_ = 0;
-        observer_->loopSample(busy, idle);
+      if (observer_) {
+        if (observerSampleCount_++ == observer_->getSampleRate()) {
+          observerSampleCount_ = 0;
+          observer_->loopSample(busy, idle);
+        }
       }
-    }
 
-    VLOG(11) << "EventBase " << this         << " did not timeout "
-     " loop time guess: "    << busy + idle  <<
-     " idle time: "          << idle         <<
-     " busy time: "          << busy         <<
-     " avgLoopTime: "        << avgLoopTime_.get() <<
-     " maxLatencyLoopTime: " << maxLatencyLoopTime_.get() <<
-     " maxLatency_: "        << maxLatency_ <<
-     " nothingHandledYet(): "<< nothingHandledYet();
-
-    // see if our average loop time has exceeded our limit
-    if ((maxLatency_ > 0) &&
-        (maxLatencyLoopTime_.get() > double(maxLatency_))) {
-      maxLatencyCob_();
-      // back off temporarily -- don't keep spamming maxLatencyCob_
-      // if we're only a bit over the limit
-      maxLatencyLoopTime_.dampen(0.9);
-    }
+      VLOG(11) << "EventBase "  << this         << " did not timeout "
+        " loop time guess: "    << busy + idle  <<
+        " idle time: "          << idle         <<
+        " busy time: "          << busy         <<
+        " avgLoopTime: "        << avgLoopTime_.get() <<
+        " maxLatencyLoopTime: " << maxLatencyLoopTime_.get() <<
+        " maxLatency_: "        << maxLatency_ <<
+        " nothingHandledYet(): "<< nothingHandledYet();
+
+      // see if our average loop time has exceeded our limit
+      if ((maxLatency_ > 0) &&
+          (maxLatencyLoopTime_.get() > double(maxLatency_))) {
+        maxLatencyCob_();
+        // back off temporarily -- don't keep spamming maxLatencyCob_
+        // if we're only a bit over the limit
+        maxLatencyLoopTime_.dampen(0.9);
+      }
 
-    // Our loop run did real work; reset the idle timer
-    idleStart = std::chrono::duration_cast<std::chrono::microseconds>(
-      std::chrono::steady_clock::now().time_since_epoch()).count();
+      // Our loop run did real work; reset the idle timer
+      idleStart = std::chrono::duration_cast<std::chrono::microseconds>(
+        std::chrono::steady_clock::now().time_since_epoch()).count();
+    } else {
+      VLOG(11) << "EventBase "  << this << " did not timeout "
+        " time measurement is disabled "
+        " nothingHandledYet(): "<< nothingHandledYet();
+    }
 
     // If the event loop indicate that there were no more events, and
     // we also didn't have any loop callbacks to run, there is nothing left to
@@ -375,8 +394,10 @@ bool EventBase::loopBody(int flags) {
       }
     }
 
-    VLOG(5) << "EventBase " << this << " loop time: " <<
-      getTimeDelta(&prev).count();
+    if (enableTimeMeasurement_) {
+      VLOG(5) << "EventBase " << this << " loop time: " <<
+        getTimeDelta(&prev).count();
+    }
 
     if (once) {
       break;

folly/io/async/EventBase.h

@@ -143,8 +143,14 @@ class EventBase : private boost::noncopyable,
 
   /**
    * Create a new EventBase object.
+   *
+   * @param enableTimeMeasurement Informs whether this event base should measure
+   *                              time. Disabling it would likely improve
+   *                              performance, but will disable some features
+   *                              that relies on time-measurement, including:
+   *                              observer, max latency and avg loop time.
    */
-  EventBase();
+  explicit EventBase(bool enableTimeMeasurement = true);
 
   /**
    * Create a new EventBase object that will use the specified libevent
@@ -152,8 +158,14 @@ class EventBase : private boost::noncopyable,
    *
    * The EventBase will take ownership of this event_base, and will call
    * event_base_free(evb) when the EventBase is destroyed.
+   *
+   * @param enableTimeMeasurement Informs whether this event base should measure
+   *                              time. Disabling it would likely improve
+   *                              performance, but will disable some features
+   *                              that relies on time-measurement, including:
+   *                              observer, max latency and avg loop time.
    */
-  explicit EventBase(event_base* evb);
+  explicit EventBase(event_base* evb, bool enableTimeMeasurement = true);
   ~EventBase();
 
   /**
@@ -384,12 +396,15 @@ class EventBase : private boost::noncopyable,
   /**
    * Set the maximum desired latency in us and provide a callback which will be
    * called when that latency is exceeded.
+   * OBS: This functionality depends on time-measurement.
    */
   void setMaxLatency(int64_t maxLatency, const Cob& maxLatencyCob) {
+    assert(enableTimeMeasurement_);
     maxLatency_ = maxLatency;
     maxLatencyCob_ = maxLatencyCob;
   }
 
+
   /**
    * Set smoothing coefficient for loop load average; # of milliseconds
    * for exp(-1) (1/2.71828...) decay.
@@ -405,6 +420,7 @@ class EventBase : private boost::noncopyable,
    * Get the average loop time in microseconds (an exponentially-smoothed ave)
    */
   double getAvgLoopTime() const {
+    assert(enableTimeMeasurement_);
     return avgLoopTime_.get();
   }
 
@@ -484,8 +500,8 @@ class EventBase : private boost::noncopyable,
     int64_t oldBusyLeftover_;
   };
 
-  void setObserver(
-    const std::shared_ptr<EventBaseObserver>& observer) {
+  void setObserver(const std::shared_ptr<EventBaseObserver>& observer) {
+    assert(enableTimeMeasurement_);
     observer_ = observer;
   }
 
@@ -632,6 +648,11 @@ class EventBase : private boost::noncopyable,
   // callback called when latency limit is exceeded
   Cob maxLatencyCob_;
 
+  // Enables/disables time measurements in loopBody(). if disabled, the
+  // following functionality that relies on time-measurement, will not
+  // be supported: avg loop time, observer and max latency.
+  const bool enableTimeMeasurement_;
+
   // we'll wait this long before running deferred callbacks if the event
   // loop is idle.
   static const int kDEFAULT_IDLE_WAIT_USEC = 20000; // 20ms

folly/io/async/test/EventBaseBenchmark.cpp

+/*
+ * Copyright 2015 Facebook, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * 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 <gflags/gflags.h>
+
+using namespace folly;
+
+class CountedLoopCallback : public EventBase::LoopCallback {
+ public:
+  CountedLoopCallback(EventBase* eventBase, unsigned int count)
+    : eventBase_(eventBase)
+    , count_(count) {}
+
+  virtual void runLoopCallback() noexcept {
+    --count_;
+    if (count_ > 0) {
+      eventBase_->runInLoop(this);
+    }
+  }
+
+ private:
+  EventBase* eventBase_;
+  unsigned int count_;
+};
+
+BENCHMARK(timeMeasurementsOn, n) {
+  EventBase eventBase;
+
+  while (n--) {
+    CountedLoopCallback c(&eventBase, 10);
+    eventBase.runInLoop(&c);
+    eventBase.loop();
+  }
+}
+
+BENCHMARK_RELATIVE(timeMeasurementsOff, n) {
+  EventBase eventBase(/* enableTimeMeasurement */ false);
+
+  while (n--) {
+    CountedLoopCallback c(&eventBase, 10);
+    eventBase.runInLoop(&c);
+    eventBase.loop();
+  }
+}
+
+/**
+ * --bm_min_iters=1000000
+ *
+ * ============================================================================
+ * folly/io/async/test/EventBaseBenchmark.cpp      relative  time/iter  iters/s
+ * ============================================================================
+ * timeMeasurementsOn                                           2.02us  494.57K
+ * timeMeasurementsOff                              231.19%   874.58ns    1.14M
+ * ============================================================================
+ */
+
+int main(int argc, char** argv) {
+  gflags::ParseCommandLineFlags(&argc, &argv, true);
+  runBenchmarks();
+}

folly/io/async/test/EventBaseTest.cpp

@@ -1265,6 +1265,21 @@ TEST(EventBaseTest, RepeatedRunInLoop) {
   ASSERT_EQ(c.getCount(), 0);
 }
 
+// Test that EventBase::loop() works as expected without time measurements.
+TEST(EventBaseTest, RunInLoopNoTimeMeasurement) {
+  EventBase eventBase(false);
+
+  CountedLoopCallback c(&eventBase, 10);
+  eventBase.runInLoop(&c);
+  // The callback shouldn't have run immediately
+  ASSERT_EQ(c.getCount(), 10);
+  eventBase.loop();
+
+  // loop() should loop until the CountedLoopCallback stops
+  // re-installing itself.
+  ASSERT_EQ(c.getCount(), 0);
+}
+
 // Test runInLoop() calls with terminateLoopSoon()
 TEST(EventBaseTest, RunInLoopStopLoop) {
   EventBase eventBase;