Commit a4306bcd authored by Dave Watson's avatar Dave Watson Committed by Facebook Github Bot

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
parent 86cefd11
...@@ -290,7 +290,7 @@ bool EventBase::loopBody(int flags) { ...@@ -290,7 +290,7 @@ bool EventBase::loopBody(int flags) {
if (enableTimeMeasurement_) { if (enableTimeMeasurement_) {
prev = std::chrono::steady_clock::now(); prev = std::chrono::steady_clock::now();
idleStart = std::chrono::steady_clock::now(); idleStart = prev;
} }
while (!stop_.load(std::memory_order_relaxed)) { while (!stop_.load(std::memory_order_relaxed)) {
...@@ -318,15 +318,15 @@ bool EventBase::loopBody(int flags) { ...@@ -318,15 +318,15 @@ bool EventBase::loopBody(int flags) {
ranLoopCallbacks = runLoopCallbacks(); ranLoopCallbacks = runLoopCallbacks();
if (enableTimeMeasurement_) { if (enableTimeMeasurement_) {
auto now = std::chrono::steady_clock::now();
busy = std::chrono::duration_cast<std::chrono::microseconds>( busy = std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::steady_clock::now() - startWork_); now - startWork_);
idle = std::chrono::duration_cast<std::chrono::microseconds>( idle = std::chrono::duration_cast<std::chrono::microseconds>(
startWork_ - idleStart); startWork_ - idleStart);
auto loop_time = busy + idle;
avgLoopTime_.addSample(std::chrono::microseconds(idle), avgLoopTime_.addSample(loop_time, busy);
std::chrono::microseconds(busy)); maxLatencyLoopTime_.addSample(loop_time, busy);
maxLatencyLoopTime_.addSample(std::chrono::microseconds(idle),
std::chrono::microseconds(busy));
if (observer_) { if (observer_) {
if (observerSampleCount_++ == observer_->getSampleRate()) { if (observerSampleCount_++ == observer_->getSampleRate()) {
...@@ -335,15 +335,15 @@ bool EventBase::loopBody(int flags) { ...@@ -335,15 +335,15 @@ bool EventBase::loopBody(int flags) {
} }
} }
VLOG(11) << "EventBase " << this << " did not timeout " << VLOG(11) << "EventBase " << this << " did not timeout "
" loop time guess: " << (busy + idle).count() << << " loop time guess: " << loop_time.count()
" idle time: " << idle.count() << << " idle time: " << idle.count()
" busy time: " << busy.count() << << " busy time: " << busy.count()
" avgLoopTime: " << avgLoopTime_.get() << << " avgLoopTime: " << avgLoopTime_.get()
" maxLatencyLoopTime: " << maxLatencyLoopTime_.get() << << " maxLatencyLoopTime: " << maxLatencyLoopTime_.get()
" maxLatency_: " << maxLatency_.count() << "us" << << " maxLatency_: " << maxLatency_.count() << "us"
" notificationQueueSize: " << getNotificationQueueSize() << << " notificationQueueSize: " << getNotificationQueueSize()
" nothingHandledYet(): " << nothingHandledYet(); << " nothingHandledYet(): " << nothingHandledYet();
// see if our average loop time has exceeded our limit // see if our average loop time has exceeded our limit
if ((maxLatency_ > std::chrono::microseconds::zero()) && if ((maxLatency_ > std::chrono::microseconds::zero()) &&
...@@ -355,7 +355,7 @@ bool EventBase::loopBody(int flags) { ...@@ -355,7 +355,7 @@ bool EventBase::loopBody(int flags) {
} }
// Our loop run did real work; reset the idle timer // Our loop run did real work; reset the idle timer
idleStart = std::chrono::steady_clock::now(); idleStart = now;
} else { } else {
VLOG(11) << "EventBase " << this << " did not timeout"; VLOG(11) << "EventBase " << this << " did not timeout";
} }
...@@ -651,31 +651,21 @@ void EventBase::SmoothLoopTime::reset(double value) { ...@@ -651,31 +651,21 @@ void EventBase::SmoothLoopTime::reset(double value) {
} }
void EventBase::SmoothLoopTime::addSample( void EventBase::SmoothLoopTime::addSample(
std::chrono::microseconds idle, std::chrono::microseconds total,
std::chrono::microseconds busy) { std::chrono::microseconds busy) {
/* if ((buffer_time_ + total) > buffer_interval_ && buffer_cnt_ > 0) {
* Position at which the busy sample is considered to be taken. // See https://en.wikipedia.org/wiki/Exponential_smoothing for
* (Allows to quickly skew our average without editing much code) // more info on this calculation.
*/ double coeff = exp(buffer_time_.count() * expCoeff_);
enum BusySamplePosition { value_ =
RIGHT = 0, // busy sample placed at the end of the iteration value_ * coeff + (1.0 - coeff) * (busy_buffer_.count() / buffer_cnt_);
CENTER = 1, // busy sample placed at the middle point of the iteration buffer_time_ = std::chrono::microseconds{0};
LEFT = 2, // busy sample placed at the beginning of the iteration busy_buffer_ = std::chrono::microseconds{0};
}; buffer_cnt_ = 0;
}
// See http://en.wikipedia.org/wiki/Moving_average#Exponential_moving_average buffer_time_ += total;
// and D676020 for more info on this calculation. busy_buffer_ += busy;
VLOG(11) << "idle " << idle.count() << " oldBusyLeftover_ " buffer_cnt_++;
<< 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();
} }
bool EventBase::nothingHandledYet() const noexcept { bool EventBase::nothingHandledYet() const noexcept {
...@@ -753,4 +743,5 @@ VirtualEventBase& EventBase::getVirtualEventBase() { ...@@ -753,4 +743,5 @@ VirtualEventBase& EventBase::getVirtualEventBase() {
return *virtualEventBase_; return *virtualEventBase_;
} }
constexpr std::chrono::milliseconds EventBase::SmoothLoopTime::buffer_interval_;
} // namespace folly } // namespace folly
...@@ -541,9 +541,7 @@ class EventBase : private boost::noncopyable, ...@@ -541,9 +541,7 @@ class EventBase : private boost::noncopyable,
class SmoothLoopTime { class SmoothLoopTime {
public: public:
explicit SmoothLoopTime(std::chrono::microseconds timeInterval) explicit SmoothLoopTime(std::chrono::microseconds timeInterval)
: expCoeff_(-1.0 / timeInterval.count()), : expCoeff_(-1.0 / timeInterval.count()), value_(0.0) {
value_(0.0),
oldBusyLeftover_(0) {
VLOG(11) << "expCoeff_ " << expCoeff_ << " " << __PRETTY_FUNCTION__; VLOG(11) << "expCoeff_ " << expCoeff_ << " " << __PRETTY_FUNCTION__;
} }
...@@ -551,11 +549,14 @@ class EventBase : private boost::noncopyable, ...@@ -551,11 +549,14 @@ class EventBase : private boost::noncopyable,
void reset(double value = 0.0); void reset(double value = 0.0);
void addSample( void addSample(
std::chrono::microseconds idle, std::chrono::microseconds total,
std::chrono::microseconds busy); std::chrono::microseconds busy);
double get() const { 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) { void dampen(double factor) {
...@@ -565,7 +566,10 @@ class EventBase : private boost::noncopyable, ...@@ -565,7 +566,10 @@ class EventBase : private boost::noncopyable,
private: private:
double expCoeff_; double expCoeff_;
double value_; 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) { void setObserver(const std::shared_ptr<EventBaseObserver>& observer) {
......
...@@ -13,7 +13,6 @@ ...@@ -13,7 +13,6 @@
* See the License for the specific language governing permissions and * See the License for the specific language governing permissions and
* limitations under the License. * limitations under the License.
*/ */
#include <folly/Benchmark.h> #include <folly/Benchmark.h>
#include <folly/io/async/EventBase.h> #include <folly/io/async/EventBase.h>
#include <folly/portability/GFlags.h> #include <folly/portability/GFlags.h>
...@@ -64,8 +63,8 @@ BENCHMARK_RELATIVE(timeMeasurementsOff, n) { ...@@ -64,8 +63,8 @@ BENCHMARK_RELATIVE(timeMeasurementsOff, n) {
* ============================================================================ * ============================================================================
* folly/io/async/test/EventBaseBenchmark.cpp relative time/iter iters/s * folly/io/async/test/EventBaseBenchmark.cpp relative time/iter iters/s
* ============================================================================ * ============================================================================
* timeMeasurementsOn 2.02us 494.57K * timeMeasurementsOn 1.25us 798.33K
* timeMeasurementsOff 231.19% 874.58ns 1.14M * timeMeasurementsOff 214.47% 584.04ns 1.71M
* ============================================================================ * ============================================================================
*/ */
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment