From 2f3b69cc03f35a021614cfd14c9dd43f9ebc915e Mon Sep 17 00:00:00 2001 From: Andre Pinto Date: Fri, 20 Feb 2015 14:51:39 -0800 Subject: [PATCH] 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 | 95 +++++++++++++--------- folly/io/async/EventBase.h | 29 ++++++- folly/io/async/test/EventBaseBenchmark.cpp | 76 +++++++++++++++++ folly/io/async/test/EventBaseTest.cpp | 15 ++++ 4 files changed, 174 insertions(+), 41 deletions(-) create mode 100644 folly/io/async/test/EventBaseBenchmark.cpp diff --git a/folly/io/async/EventBase.cpp b/folly/io/async/EventBase.cpp index 2f38749b..0a7b0bb7 100644 --- a/folly/io/async/EventBase.cpp +++ b/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::steady_clock::now().time_since_epoch()).count(); + if (enableTimeMeasurement_) { + prev = std::chrono::steady_clock::now(); + idleStart = std::chrono::duration_cast( + 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::steady_clock::now().time_since_epoch()).count() - startWork_; - int64_t idle = startWork_ - idleStart; + if (enableTimeMeasurement_) { + busy = std::chrono::duration_cast( + 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::steady_clock::now().time_since_epoch()).count(); + // Our loop run did real work; reset the idle timer + idleStart = std::chrono::duration_cast( + 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; diff --git a/folly/io/async/EventBase.h b/folly/io/async/EventBase.h index a4051dfe..769d72fb 100644 --- a/folly/io/async/EventBase.h +++ b/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& observer) { + void setObserver(const std::shared_ptr& 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 diff --git a/folly/io/async/test/EventBaseBenchmark.cpp b/folly/io/async/test/EventBaseBenchmark.cpp new file mode 100644 index 00000000..cbb8b42c --- /dev/null +++ b/folly/io/async/test/EventBaseBenchmark.cpp @@ -0,0 +1,76 @@ +/* + * 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 +#include + +#include + +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(); +} diff --git a/folly/io/async/test/EventBaseTest.cpp b/folly/io/async/test/EventBaseTest.cpp index f94ebfc4..f80cdcc4 100644 --- a/folly/io/async/test/EventBaseTest.cpp +++ b/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; -- 2.34.1