From f3d9a55fea64803a153e9f4abfde46c664fbd47b Mon Sep 17 00:00:00 2001 From: Dave Watson Date: Fri, 5 Aug 2016 12:45:58 -0700 Subject: [PATCH] Upper level tests Summary: Add some tests to test the other levels of the timer wheel. They are slow by necessity. Reviewed By: yfeldblum Differential Revision: D3637132 fbshipit-source-id: badf8d37d726dbeb5a8220d50c60b8efdaee7989 --- folly/io/async/test/HHWheelTimerSlowTests.cpp | 274 ++++++++++++++++++ folly/io/async/test/HHWheelTimerTest.cpp | 136 +-------- 2 files changed, 275 insertions(+), 135 deletions(-) create mode 100644 folly/io/async/test/HHWheelTimerSlowTests.cpp diff --git a/folly/io/async/test/HHWheelTimerSlowTests.cpp b/folly/io/async/test/HHWheelTimerSlowTests.cpp new file mode 100644 index 00000000..74ae6127 --- /dev/null +++ b/folly/io/async/test/HHWheelTimerSlowTests.cpp @@ -0,0 +1,274 @@ +/* + * Copyright 2016 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 +#include + +#include +#include +#include + +using namespace folly; +using std::chrono::milliseconds; + +typedef UndelayedDestruction StackWheelTimer; + +class TestTimeout : public HHWheelTimer::Callback { + public: + TestTimeout() {} + TestTimeout(HHWheelTimer* t, milliseconds timeout) { + t->scheduleTimeout(this, timeout); + } + + void timeoutExpired() noexcept override { + timestamps.emplace_back(); + if (fn) { + fn(); + } + } + + void callbackCanceled() noexcept override { + canceledTimestamps.emplace_back(); + if (fn) { + fn(); + } + } + + std::deque timestamps; + std::deque canceledTimestamps; + std::function fn; +}; + +class TestTimeoutDelayed : public TestTimeout { + protected: + std::chrono::milliseconds getCurTime() override { + return std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) - + milliseconds(5); + } +}; + +struct HHWheelTimerTest : public ::testing::Test { + EventBase eventBase; +}; + +/* Test takes ~2.5 minutes to run */ +TEST_F(HHWheelTimerTest, Level2) { + HHWheelTimer& t = eventBase.timer(); + + TestTimeout t1; + TestTimeout t2; + + ASSERT_EQ(t.count(), 0); + + t.scheduleTimeout(&t1, milliseconds(605 * 256)); + t.scheduleTimeout(&t2, milliseconds(300 * 256)); + + ASSERT_EQ(t.count(), 2); + + TimePoint start; + eventBase.loop(); + TimePoint end; + + ASSERT_EQ(t1.timestamps.size(), 1); + ASSERT_EQ(t2.timestamps.size(), 1); + ASSERT_EQ(t.count(), 0); + + // Check that the timeout was delayed by sleep + T_CHECK_TIMEOUT( + start, + t1.timestamps[0], + milliseconds(605 * 256), + milliseconds(256 * 256)); + T_CHECK_TIMEOUT( + start, + t2.timestamps[0], + milliseconds(300 * 256), + milliseconds(256 * 256)); +} + +/* + * Test the tick interval parameter + */ +TEST_F(HHWheelTimerTest, AtMostEveryN) { + // Create a timeout set with a 10ms interval, to fire no more than once + // every 3ms. + milliseconds interval(10); + milliseconds atMostEveryN(3); + StackWheelTimer t(&eventBase, atMostEveryN); + + // Create 60 timeouts to be added to ts1 at 1ms intervals. + uint32_t numTimeouts = 60; + std::vector timeouts(numTimeouts); + + // Create a scheduler timeout to add the timeouts 1ms apart. + uint32_t index = 0; + StackWheelTimer ts1(&eventBase, milliseconds(1)); + TestTimeout scheduler(&ts1, milliseconds(1)); + scheduler.fn = [&] { + if (index >= numTimeouts) { + return; + } + // Call timeoutExpired() on the timeout so it will record a timestamp. + // This is done only so we can record when we scheduled the timeout. + // This way if ts1 starts to fall behind a little over time we will still + // be comparing the ts1 timeouts to when they were first scheduled (rather + // than when we intended to schedule them). The scheduler may fall behind + // eventually since we don't really schedule it once every millisecond. + // Each time it finishes we schedule it for 1 millisecond in the future. + // The amount of time it takes to run, and any delays it encounters + // getting scheduled may eventually add up over time. + timeouts[index].timeoutExpired(); + + // Schedule the new timeout + t.scheduleTimeout(&timeouts[index], interval); + // Reschedule ourself + ts1.scheduleTimeout(&scheduler, milliseconds(1)); + ++index; + }; + + TimePoint start; + eventBase.loop(); + TimePoint end; + + // This should take roughly 60 + 10 ms to finish. If it takes more than + // 250 ms to finish the system is probably heavily loaded, so skip. + if (std::chrono::duration_cast( + end.getTime() - start.getTime()) + .count() > 250) { + LOG(WARNING) << "scheduling all timeouts takes too long"; + return; + } + + // We scheduled timeouts 1ms apart, when the HHWheelTimer is only allowed + // to wake up at most once every 3ms. It will therefore wake up every 3ms + // and fire groups of approximately 3 timeouts at a time. + // + // This is "approximately 3" since it may get slightly behind and fire 4 in + // one interval, etc. T_CHECK_TIMEOUT normally allows a few milliseconds of + // tolerance. We have to add the same into our checking algorithm here. + for (uint32_t idx = 0; idx < numTimeouts; ++idx) { + ASSERT_EQ(timeouts[idx].timestamps.size(), 2); + + TimePoint scheduledTime(timeouts[idx].timestamps[0]); + TimePoint firedTime(timeouts[idx].timestamps[1]); + + // Assert that the timeout fired at roughly the right time. + // T_CHECK_TIMEOUT() normally has a tolerance of 5ms. Allow an additional + // atMostEveryN. + milliseconds tolerance = milliseconds(5) + interval; + T_CHECK_TIMEOUT(scheduledTime, firedTime, atMostEveryN, tolerance); + + // Assert that the difference between the previous timeout and now was + // either very small (fired in the same event loop), or larger than + // atMostEveryN. + if (idx == 0) { + // no previous value + continue; + } + TimePoint prev(timeouts[idx - 1].timestamps[1]); + + auto delta = (firedTime.getTimeStart() - prev.getTimeEnd()) - + (firedTime.getTimeWaiting() - prev.getTimeWaiting()); + if (delta > milliseconds(1)) { + T_CHECK_TIMEOUT(prev, firedTime, atMostEveryN); + } + } +} + +/* + * Test an event loop that is blocking + */ + +TEST_F(HHWheelTimerTest, SlowLoop) { + StackWheelTimer t(&eventBase, milliseconds(1)); + + TestTimeout t1; + TestTimeout t2; + + ASSERT_EQ(t.count(), 0); + + eventBase.runInLoop([]() { + /* sleep override */ + std::this_thread::sleep_for(std::chrono::microseconds(10000)); + }); + t.scheduleTimeout(&t1, milliseconds(5)); + + ASSERT_EQ(t.count(), 1); + + TimePoint start; + eventBase.loop(); + TimePoint end; + + ASSERT_EQ(t1.timestamps.size(), 1); + ASSERT_EQ(t.count(), 0); + + // Check that the timeout was delayed by sleep + T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(10), milliseconds(1)); + T_CHECK_TIMEOUT(start, end, milliseconds(10), milliseconds(1)); + + eventBase.runInLoop([]() { + /* sleep override */ + std::this_thread::sleep_for(std::chrono::microseconds(10000)); + }); + t.scheduleTimeout(&t2, milliseconds(5)); + + ASSERT_EQ(t.count(), 1); + + TimePoint start2; + eventBase.loop(); + TimePoint end2; + + ASSERT_EQ(t2.timestamps.size(), 1); + ASSERT_EQ(t.count(), 0); + + // Check that the timeout was NOT delayed by sleep + T_CHECK_TIMEOUT(start2, t2.timestamps[0], milliseconds(10), milliseconds(1)); + T_CHECK_TIMEOUT(start2, end2, milliseconds(10), milliseconds(1)); +} + +/* + * Test upper timer levels. Slow by necessity :/ + */ + +TEST_F(HHWheelTimerTest, Level1) { + HHWheelTimer& t = eventBase.timer(); + + TestTimeout t1; + TestTimeout t2; + + ASSERT_EQ(t.count(), 0); + + t.scheduleTimeout(&t1, milliseconds(605)); + t.scheduleTimeout(&t2, milliseconds(300)); + + ASSERT_EQ(t.count(), 2); + + TimePoint start; + eventBase.loop(); + TimePoint end; + + ASSERT_EQ(t1.timestamps.size(), 1); + ASSERT_EQ(t2.timestamps.size(), 1); + ASSERT_EQ(t.count(), 0); + + // Check that the timeout was delayed by sleep + T_CHECK_TIMEOUT( + start, t1.timestamps[0], milliseconds(605), milliseconds(256)); + T_CHECK_TIMEOUT( + start, t2.timestamps[0], milliseconds(300), milliseconds(256)); +} diff --git a/folly/io/async/test/HHWheelTimerTest.cpp b/folly/io/async/test/HHWheelTimerTest.cpp index 4899842e..bcbf72d8 100644 --- a/folly/io/async/test/HHWheelTimerTest.cpp +++ b/folly/io/async/test/HHWheelTimerTest.cpp @@ -252,146 +252,12 @@ TEST_F(HHWheelTimerTest, DestroyTimeoutSet) { T_CHECK_TIMEOUT(start, end, milliseconds(5)); } -/* - * Test the tick interval parameter - */ -TEST_F(HHWheelTimerTest, AtMostEveryN) { - - // Create a timeout set with a 10ms interval, to fire no more than once - // every 3ms. - milliseconds interval(10); - milliseconds atMostEveryN(3); - StackWheelTimer t(&eventBase, atMostEveryN); - - // Create 60 timeouts to be added to ts1 at 1ms intervals. - uint32_t numTimeouts = 60; - std::vector timeouts(numTimeouts); - - // Create a scheduler timeout to add the timeouts 1ms apart. - uint32_t index = 0; - StackWheelTimer ts1(&eventBase, milliseconds(1)); - TestTimeout scheduler(&ts1, milliseconds(1)); - scheduler.fn = [&] { - if (index >= numTimeouts) { - return; - } - // Call timeoutExpired() on the timeout so it will record a timestamp. - // This is done only so we can record when we scheduled the timeout. - // This way if ts1 starts to fall behind a little over time we will still - // be comparing the ts1 timeouts to when they were first scheduled (rather - // than when we intended to schedule them). The scheduler may fall behind - // eventually since we don't really schedule it once every millisecond. - // Each time it finishes we schedule it for 1 millisecond in the future. - // The amount of time it takes to run, and any delays it encounters - // getting scheduled may eventually add up over time. - timeouts[index].timeoutExpired(); - - // Schedule the new timeout - t.scheduleTimeout(&timeouts[index], interval); - // Reschedule ourself - ts1.scheduleTimeout(&scheduler, milliseconds(1)); - ++index; - }; - - TimePoint start; - eventBase.loop(); - TimePoint end; - - // This should take roughly 60 + 10 ms to finish. If it takes more than - // 250 ms to finish the system is probably heavily loaded, so skip. - if (std::chrono::duration_cast( - end.getTime() - start.getTime()).count() > 250) { - LOG(WARNING) << "scheduling all timeouts takes too long"; - return; - } - - // We scheduled timeouts 1ms apart, when the HHWheelTimer is only allowed - // to wake up at most once every 3ms. It will therefore wake up every 3ms - // and fire groups of approximately 3 timeouts at a time. - // - // This is "approximately 3" since it may get slightly behind and fire 4 in - // one interval, etc. T_CHECK_TIMEOUT normally allows a few milliseconds of - // tolerance. We have to add the same into our checking algorithm here. - for (uint32_t idx = 0; idx < numTimeouts; ++idx) { - ASSERT_EQ(timeouts[idx].timestamps.size(), 2); - - TimePoint scheduledTime(timeouts[idx].timestamps[0]); - TimePoint firedTime(timeouts[idx].timestamps[1]); - - // Assert that the timeout fired at roughly the right time. - // T_CHECK_TIMEOUT() normally has a tolerance of 5ms. Allow an additional - // atMostEveryN. - milliseconds tolerance = milliseconds(5) + interval; - T_CHECK_TIMEOUT(scheduledTime, firedTime, atMostEveryN, tolerance); - - // Assert that the difference between the previous timeout and now was - // either very small (fired in the same event loop), or larger than - // atMostEveryN. - if (idx == 0) { - // no previous value - continue; - } - TimePoint prev(timeouts[idx - 1].timestamps[1]); - - auto delta = (firedTime.getTimeStart() - prev.getTimeEnd()) - - (firedTime.getTimeWaiting() - prev.getTimeWaiting()); - if (delta > milliseconds(1)) { - T_CHECK_TIMEOUT(prev, firedTime, atMostEveryN); - } - } -} - -/* - * Test an event loop that is blocking - */ - -TEST_F(HHWheelTimerTest, SlowLoop) { - StackWheelTimer t(&eventBase, milliseconds(1)); - - TestTimeout t1; - TestTimeout t2; - - ASSERT_EQ(t.count(), 0); - - eventBase.runInLoop([](){usleep(10000);}); - t.scheduleTimeout(&t1, milliseconds(5)); - - ASSERT_EQ(t.count(), 1); - - TimePoint start; - eventBase.loop(); - TimePoint end; - - ASSERT_EQ(t1.timestamps.size(), 1); - ASSERT_EQ(t.count(), 0); - - // Check that the timeout was delayed by sleep - T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(10), milliseconds(1)); - T_CHECK_TIMEOUT(start, end, milliseconds(10), milliseconds(1)); - - eventBase.runInLoop([](){usleep(10000);}); - t.scheduleTimeout(&t2, milliseconds(5)); - - ASSERT_EQ(t.count(), 1); - - TimePoint start2; - eventBase.loop(); - TimePoint end2; - - ASSERT_EQ(t2.timestamps.size(), 1); - ASSERT_EQ(t.count(), 0); - - // Check that the timeout was NOT delayed by sleep - T_CHECK_TIMEOUT(start2, t2.timestamps[0], milliseconds(10), milliseconds(1)); - T_CHECK_TIMEOUT(start2, end2, milliseconds(10), milliseconds(1)); -} - /* * Test an event scheduled before the last event fires on time */ TEST_F(HHWheelTimerTest, SlowFast) { - HHWheelTimer& t = eventBase.timer(); + StackWheelTimer t(&eventBase, milliseconds(1)); TestTimeout t1; TestTimeout t2; -- 2.34.1