From 3396d608d04669425d91af30aec7cab030ab0ec2 Mon Sep 17 00:00:00 2001 From: Adam Simpkins Date: Tue, 6 Jun 2017 14:09:41 -0700 Subject: [PATCH] additional minor cleanup to the TimeUtil code Summary: - Fix TimePoint to use steady_clock rather than system_clock - Use nanoseconds instead of milliseconds in most locations This code should probably also be moved into a folly::testing namespace or something. This class is pretty specific to unit tests, and `folly::TimePoint` seems like too generic of a name for it. However, just to keep things simple I'm not doing that as part of this diff yet. Reviewed By: yfeldblum Differential Revision: D5175630 fbshipit-source-id: 26490fc7ff1b25fb86f09309e81108828cd0f091 --- folly/io/async/test/TimeUtil.cpp | 46 +++++++++++++++++--------------- folly/io/async/test/TimeUtil.h | 36 +++++++++++++++---------- 2 files changed, 46 insertions(+), 36 deletions(-) diff --git a/folly/io/async/test/TimeUtil.cpp b/folly/io/async/test/TimeUtil.cpp index 8312d9f8..9340a9d6 100644 --- a/folly/io/async/test/TimeUtil.cpp +++ b/folly/io/async/test/TimeUtil.cpp @@ -151,19 +151,19 @@ static int64_t determineSchedstatUnits() { * Determine how long this process has spent waiting to get scheduled on the * CPU. * - * Returns the number of milliseconds spent waiting, or -1 if the amount of + * Returns the number of nanoseconds spent waiting, or -1 if the amount of * time cannot be determined. */ -static milliseconds getTimeWaitingMS(pid_t tid) { +static nanoseconds getSchedTimeWaiting(pid_t tid) { #ifndef __linux__ (void)tid; - return milliseconds(0); + return nanoseconds(0); #else static int64_t timeUnits = determineSchedstatUnits(); if (timeUnits < 0) { // We couldn't figure out how many jiffies there are in a second. // Don't bother reading the schedstat info if we can't interpret it. - return milliseconds(0); + return nanoseconds(0); } int fd = -1; @@ -201,28 +201,28 @@ static milliseconds getTimeWaitingMS(pid_t tid) { } close(fd); - return duration_cast(nanoseconds(waitingJiffies * timeUnits)); + return nanoseconds(waitingJiffies * timeUnits); } catch (const std::runtime_error& e) { if (fd >= 0) { close(fd); } LOG(ERROR) << "error determining process wait time: %s" << e.what(); - return milliseconds(0); + return nanoseconds(0); } #endif } void TimePoint::reset() { // Remember the current time - timeStart_ = system_clock::now(); + timeStart_ = steady_clock::now(); // Remember how long this process has spent waiting to be scheduled tid_ = getOSThreadID(); - timeWaiting_ = getTimeWaitingMS(tid_); + timeWaiting_ = getSchedTimeWaiting(tid_); // In case it took a while to read the schedstat info, // also record the time after the schedstat check - timeEnd_ = system_clock::now(); + timeEnd_ = steady_clock::now(); } std::ostream& operator<<(std::ostream& os, const TimePoint& timePoint) { @@ -232,16 +232,18 @@ std::ostream& operator<<(std::ostream& os, const TimePoint& timePoint) { return os; } -bool -checkTimeout(const TimePoint& start, const TimePoint& end, - milliseconds expectedMS, bool allowSmaller, - milliseconds tolerance) { +bool checkTimeout( + const TimePoint& start, + const TimePoint& end, + nanoseconds expected, + bool allowSmaller, + nanoseconds tolerance) { auto elapsedTime = end.getTimeStart() - start.getTimeEnd(); if (!allowSmaller) { // Timeouts should never fire before the time was up. // Allow 1ms of wiggle room for rounding errors. - if (elapsedTime < (expectedMS - milliseconds(1))) { + if (elapsedTime < (expected - milliseconds(1))) { return false; } } @@ -251,26 +253,26 @@ checkTimeout(const TimePoint& start, const TimePoint& end, // If the system is under heavy load, our process may have had to wait for a // while to be run. The time spent waiting for the processor shouldn't // count against us, so exclude this time from the check. - milliseconds excludedMS; + nanoseconds timeExcluded; if (end.getTid() != start.getTid()) { // We can only correctly compute the amount of time waiting to be scheduled // if both TimePoints were set in the same thread. - excludedMS = milliseconds(0); + timeExcluded = nanoseconds(0); } else { - excludedMS = end.getTimeWaiting() - start.getTimeWaiting(); + timeExcluded = end.getTimeWaiting() - start.getTimeWaiting(); assert(end.getTimeWaiting() >= start.getTimeWaiting()); // Add a tolerance here due to precision issues on linux, see below note. - assert((elapsedTime + tolerance) >= excludedMS); + assert((elapsedTime + tolerance) >= timeExcluded); } - milliseconds effectiveElapsedMS = milliseconds(0); - if (elapsedTime > excludedMS) { - effectiveElapsedMS = duration_cast(elapsedTime) - excludedMS; + nanoseconds effectiveElapsedTime(0); + if (elapsedTime > timeExcluded) { + effectiveElapsedTime = elapsedTime - timeExcluded; } // On x86 Linux, sleep calls generally have precision only to the nearest // millisecond. The tolerance parameter lets users allow a few ms of slop. - milliseconds overrun = effectiveElapsedMS - expectedMS; + auto overrun = effectiveElapsedTime - expected; if (overrun > tolerance) { return false; } diff --git a/folly/io/async/test/TimeUtil.h b/folly/io/async/test/TimeUtil.h index d28df919..7b41d1e4 100644 --- a/folly/io/async/test/TimeUtil.h +++ b/folly/io/async/test/TimeUtil.h @@ -22,6 +22,15 @@ namespace folly { +/** + * A class for tracking time durations in test code. + * + * This is primarily useful for testing timeout functionality. When comparing + * the differences between two TimePoints, it can exclude time spent waiting on + * the OS scheduler. This helps avoid spurious test failures when timeouts are + * exceeded by longer than expected simply because the underlying system was + * busy and could not schedule this thread in time. + */ class TimePoint { public: explicit TimePoint(bool set = true) @@ -39,19 +48,19 @@ class TimePoint { timeWaiting_.count() == 0); } - std::chrono::system_clock::time_point getTime() const { + std::chrono::steady_clock::time_point getTime() const { return timeStart_; } - std::chrono::system_clock::time_point getTimeStart() const { + std::chrono::steady_clock::time_point getTimeStart() const { return timeStart_; } - std::chrono::system_clock::time_point getTimeEnd() const { + std::chrono::steady_clock::time_point getTimeEnd() const { return timeStart_; } - std::chrono::milliseconds getTimeWaiting() const { + std::chrono::nanoseconds getTimeWaiting() const { return timeWaiting_; } @@ -60,19 +69,18 @@ class TimePoint { } private: - std::chrono::system_clock::time_point timeStart_; - std::chrono::system_clock::time_point timeEnd_; - std::chrono::milliseconds timeWaiting_{0}; + std::chrono::steady_clock::time_point timeStart_; + std::chrono::steady_clock::time_point timeEnd_; + std::chrono::nanoseconds timeWaiting_{0}; pid_t tid_; }; std::ostream& operator<<(std::ostream& os, const TimePoint& timePoint); -bool checkTimeout(const TimePoint& start, - const TimePoint& end, - std::chrono::milliseconds expectedMS, - bool allowSmaller, - std::chrono::milliseconds tolerance = - std::chrono::milliseconds(5)); - +bool checkTimeout( + const TimePoint& start, + const TimePoint& end, + std::chrono::nanoseconds expected, + bool allowSmaller, + std::chrono::nanoseconds tolerance = std::chrono::milliseconds(5)); } -- 2.34.1