folly/io/async/test/HHWheelTimerSlowTests.cpp

   1 /*
   2  * Copyright 2017 Facebook, Inc.
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *   http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16 #include <folly/Random.h>
  17 #include <folly/io/async/EventBase.h>
  18 #include <folly/io/async/HHWheelTimer.h>
  19 #include <folly/io/async/test/UndelayedDestruction.h>
  20 #include <folly/io/async/test/Util.h>
  21 #include <folly/portability/GTest.h>
  22
  23 #include <thread>
  24 #include <vector>
  25
  26 using namespace folly;
  27 using std::chrono::milliseconds;
  28
  29 typedef UndelayedDestruction<HHWheelTimer> StackWheelTimer;
  30
  31 class TestTimeout : public HHWheelTimer::Callback {
  32  public:
  33   TestTimeout() {}
  34   TestTimeout(HHWheelTimer* t, milliseconds timeout) {
  35     t->scheduleTimeout(this, timeout);
  36   }
  37
  38   void timeoutExpired() noexcept override {
  39     timestamps.emplace_back();
  40     if (fn) {
  41       fn();
  42     }
  43   }
  44
  45   void callbackCanceled() noexcept override {
  46     canceledTimestamps.emplace_back();
  47     if (fn) {
  48       fn();
  49     }
  50   }
  51
  52   std::deque<TimePoint> timestamps;
  53   std::deque<TimePoint> canceledTimestamps;
  54   std::function<void()> fn;
  55 };
  56
  57 class TestTimeoutDelayed : public TestTimeout {
  58  protected:
  59   std::chrono::milliseconds getCurTime() override {
  60     return std::chrono::duration_cast<std::chrono::milliseconds>(
  61                std::chrono::steady_clock::now().time_since_epoch()) -
  62         milliseconds(5);
  63   }
  64 };
  65
  66 struct HHWheelTimerTest : public ::testing::Test {
  67   EventBase eventBase;
  68 };
  69
  70 /* Test takes ~2.5 minutes to run */
  71 TEST_F(HHWheelTimerTest, Level2) {
  72   HHWheelTimer& t = eventBase.timer();
  73
  74   TestTimeout t1;
  75   TestTimeout t2;
  76
  77   ASSERT_EQ(t.count(), 0);
  78
  79   t.scheduleTimeout(&t1, milliseconds(605 * 256));
  80   t.scheduleTimeout(&t2, milliseconds(300 * 256));
  81
  82   ASSERT_EQ(t.count(), 2);
  83
  84   TimePoint start;
  85   eventBase.loop();
  86   TimePoint end;
  87
  88   ASSERT_EQ(t1.timestamps.size(), 1);
  89   ASSERT_EQ(t2.timestamps.size(), 1);
  90   ASSERT_EQ(t.count(), 0);
  91
  92   // Check that the timeout was delayed by sleep
  93   T_CHECK_TIMEOUT(
  94       start,
  95       t1.timestamps[0],
  96       milliseconds(605 * 256),
  97       milliseconds(256 * 256));
  98   T_CHECK_TIMEOUT(
  99       start,
 100       t2.timestamps[0],
 101       milliseconds(300 * 256),
 102       milliseconds(256 * 256));
 103 }
 104
 105 /*
 106  * Test the tick interval parameter
 107  */
 108 TEST_F(HHWheelTimerTest, AtMostEveryN) {
 109   // Create a timeout set with a 10ms interval, to fire no more than once
 110   // every 3ms.
 111   milliseconds interval(10);
 112   milliseconds atMostEveryN(3);
 113   StackWheelTimer t(&eventBase, atMostEveryN);
 114
 115   // Create 60 timeouts to be added to ts1 at 1ms intervals.
 116   uint32_t numTimeouts = 60;
 117   std::vector<TestTimeout> timeouts(numTimeouts);
 118
 119   // Create a scheduler timeout to add the timeouts 1ms apart.
 120   uint32_t index = 0;
 121   StackWheelTimer ts1(&eventBase, milliseconds(1));
 122   TestTimeout scheduler(&ts1, milliseconds(1));
 123   scheduler.fn = [&] {
 124     if (index >= numTimeouts) {
 125       return;
 126     }
 127     // Call timeoutExpired() on the timeout so it will record a timestamp.
 128     // This is done only so we can record when we scheduled the timeout.
 129     // This way if ts1 starts to fall behind a little over time we will still
 130     // be comparing the ts1 timeouts to when they were first scheduled (rather
 131     // than when we intended to schedule them).  The scheduler may fall behind
 132     // eventually since we don't really schedule it once every millisecond.
 133     // Each time it finishes we schedule it for 1 millisecond in the future.
 134     // The amount of time it takes to run, and any delays it encounters
 135     // getting scheduled may eventually add up over time.
 136     timeouts[index].timeoutExpired();
 137
 138     // Schedule the new timeout
 139     t.scheduleTimeout(&timeouts[index], interval);
 140     // Reschedule ourself
 141     ts1.scheduleTimeout(&scheduler, milliseconds(1));
 142     ++index;
 143   };
 144
 145   TimePoint start;
 146   eventBase.loop();
 147   TimePoint end;
 148
 149   // This should take roughly 60 + 10 ms to finish. If it takes more than
 150   // 250 ms to finish the system is probably heavily loaded, so skip.
 151   if (std::chrono::duration_cast<std::chrono::milliseconds>(
 152           end.getTime() - start.getTime())
 153           .count() > 250) {
 154     LOG(WARNING) << "scheduling all timeouts takes too long";
 155     return;
 156   }
 157
 158   // We scheduled timeouts 1ms apart, when the HHWheelTimer is only allowed
 159   // to wake up at most once every 3ms.  It will therefore wake up every 3ms
 160   // and fire groups of approximately 3 timeouts at a time.
 161   //
 162   // This is "approximately 3" since it may get slightly behind and fire 4 in
 163   // one interval, etc.  T_CHECK_TIMEOUT normally allows a few milliseconds of
 164   // tolerance.  We have to add the same into our checking algorithm here.
 165   for (uint32_t idx = 0; idx < numTimeouts; ++idx) {
 166     ASSERT_EQ(timeouts[idx].timestamps.size(), 2);
 167
 168     TimePoint scheduledTime(timeouts[idx].timestamps[0]);
 169     TimePoint firedTime(timeouts[idx].timestamps[1]);
 170
 171     // Assert that the timeout fired at roughly the right time.
 172     // T_CHECK_TIMEOUT() normally has a tolerance of 5ms.  Allow an additional
 173     // atMostEveryN.
 174     milliseconds tolerance = milliseconds(5) + interval;
 175     T_CHECK_TIMEOUT(scheduledTime, firedTime, atMostEveryN, tolerance);
 176
 177     // Assert that the difference between the previous timeout and now was
 178     // either very small (fired in the same event loop), or larger than
 179     // atMostEveryN.
 180     if (idx == 0) {
 181       // no previous value
 182       continue;
 183     }
 184     TimePoint prev(timeouts[idx - 1].timestamps[1]);
 185
 186     auto delta = (firedTime.getTimeStart() - prev.getTimeEnd()) -
 187         (firedTime.getTimeWaiting() - prev.getTimeWaiting());
 188     if (delta > milliseconds(1)) {
 189       T_CHECK_TIMEOUT(prev, firedTime, atMostEveryN);
 190     }
 191   }
 192 }
 193
 194 /*
 195  * Test an event loop that is blocking
 196  */
 197
 198 TEST_F(HHWheelTimerTest, SlowLoop) {
 199   StackWheelTimer t(&eventBase, milliseconds(1));
 200
 201   TestTimeout t1;
 202   TestTimeout t2;
 203
 204   ASSERT_EQ(t.count(), 0);
 205
 206   eventBase.runInLoop([]() {
 207     /* sleep override */
 208     std::this_thread::sleep_for(std::chrono::microseconds(10000));
 209   });
 210   t.scheduleTimeout(&t1, milliseconds(5));
 211
 212   ASSERT_EQ(t.count(), 1);
 213
 214   TimePoint start;
 215   eventBase.loop();
 216   TimePoint end;
 217
 218   ASSERT_EQ(t1.timestamps.size(), 1);
 219   ASSERT_EQ(t.count(), 0);
 220
 221   // Check that the timeout was delayed by sleep
 222   T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(10), milliseconds(1));
 223   T_CHECK_TIMEOUT(start, end, milliseconds(10), milliseconds(1));
 224
 225   eventBase.runInLoop([]() {
 226     /* sleep override */
 227     std::this_thread::sleep_for(std::chrono::microseconds(10000));
 228   });
 229   t.scheduleTimeout(&t2, milliseconds(5));
 230
 231   ASSERT_EQ(t.count(), 1);
 232
 233   TimePoint start2;
 234   eventBase.loop();
 235   TimePoint end2;
 236
 237   ASSERT_EQ(t2.timestamps.size(), 1);
 238   ASSERT_EQ(t.count(), 0);
 239
 240   // Check that the timeout was NOT delayed by sleep
 241   T_CHECK_TIMEOUT(start2, t2.timestamps[0], milliseconds(10), milliseconds(1));
 242   T_CHECK_TIMEOUT(start2, end2, milliseconds(10), milliseconds(1));
 243 }
 244
 245 /*
 246  * Test upper timer levels.  Slow by necessity :/
 247  */
 248
 249 TEST_F(HHWheelTimerTest, Level1) {
 250   HHWheelTimer& t = eventBase.timer();
 251
 252   TestTimeout t1;
 253   TestTimeout t2;
 254
 255   ASSERT_EQ(t.count(), 0);
 256
 257   t.scheduleTimeout(&t1, milliseconds(605));
 258   t.scheduleTimeout(&t2, milliseconds(300));
 259
 260   ASSERT_EQ(t.count(), 2);
 261
 262   TimePoint start;
 263   eventBase.loop();
 264   TimePoint end;
 265
 266   ASSERT_EQ(t1.timestamps.size(), 1);
 267   ASSERT_EQ(t2.timestamps.size(), 1);
 268   ASSERT_EQ(t.count(), 0);
 269
 270   // Check that the timeout was delayed by sleep
 271   T_CHECK_TIMEOUT(
 272       start, t1.timestamps[0], milliseconds(605), milliseconds(256));
 273   T_CHECK_TIMEOUT(
 274       start, t2.timestamps[0], milliseconds(300), milliseconds(256));
 275 }
 276
 277 TEST_F(HHWheelTimerTest, Stress) {
 278   StackWheelTimer t(&eventBase, milliseconds(1));
 279
 280   long timeoutcount = 10000;
 281   TestTimeout timeouts[10000];
 282   long runtimeouts = 0;
 283   for (long i = 0; i < timeoutcount; i++) {
 284     long timeout = Random::rand32(1, 10000);
 285     if (Random::rand32(3)) {
 286       // NOTE: hhwheel timer runs before eventbase runAfterDelay,
 287       // so runAfterDelay cancelTimeout() must run  at least one timerwheel
 288       // before scheduleTimeout, to ensure it runs first.
 289       timeout += 256;
 290       t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(timeout));
 291       eventBase.runAfterDelay(
 292           [&, i]() {
 293             timeouts[i].fn = nullptr;
 294             timeouts[i].cancelTimeout();
 295             runtimeouts++;
 296             LOG(INFO) << "Ran " << runtimeouts << " timeouts, cancelled";
 297           },
 298           timeout - 256);
 299       timeouts[i].fn = [&, i, timeout]() {
 300         LOG(INFO) << "FAIL:timer " << i << " still fired in " << timeout;
 301         EXPECT_FALSE(true);
 302       };
 303     } else {
 304       t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(timeout));
 305       timeouts[i].fn = [&, i]() {
 306         timeoutcount++;
 307         long newtimeout = Random::rand32(1, 10000);
 308         t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(newtimeout));
 309         runtimeouts++;
 310         /* sleep override */ usleep(1000);
 311         LOG(INFO) << "Ran " << runtimeouts << " timeouts of " << timeoutcount;
 312         timeouts[i].fn = [&, i]() {
 313           runtimeouts++;
 314           LOG(INFO) << "Ran " << runtimeouts << " timeouts of " << timeoutcount;
 315         };
 316       };
 317     }
 318   }
 319
 320   LOG(INFO) << "RUNNING TEST";
 321   eventBase.loop();
 322
 323   EXPECT_EQ(runtimeouts, timeoutcount);
 324 }