folly/io/async/test/HHWheelTimerTest.cpp

   1 /*
   2  * Licensed to the Apache Software Foundation (ASF) under one
   3  * or more contributor license agreements. See the NOTICE file
   4  * distributed with this work for additional information
   5  * regarding copyright ownership. The ASF licenses this file
   6  * to you under the Apache License, Version 2.0 (the
   7  * "License"); you may not use this file except in compliance
   8  * with the License. You may obtain a copy of the License at
   9  *
  10  *   http://www.apache.org/licenses/LICENSE-2.0
  11  *
  12  * Unless required by applicable law or agreed to in writing,
  13  * software distributed under the License is distributed on an
  14  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
  15  * KIND, either express or implied. See the License for the
  16  * specific language governing permissions and limitations
  17  * under the License.
  18  */
  19 #include <folly/io/async/HHWheelTimer.h>
  20 #include <folly/io/async/EventBase.h>
  21 #include <folly/io/async/test/UndelayedDestruction.h>
  22 #include <folly/io/async/test/Util.h>
  23
  24 #include <gtest/gtest.h>
  25 #include <vector>
  26
  27 using namespace folly;
  28 using std::chrono::milliseconds;
  29
  30 typedef UndelayedDestruction<HHWheelTimer> StackWheelTimer;
  31
  32 class TestTimeout : public HHWheelTimer::Callback {
  33  public:
  34   TestTimeout() {}
  35   TestTimeout(HHWheelTimer* t, milliseconds timeout) {
  36     t->scheduleTimeout(this, timeout);
  37   }
  38
  39   void timeoutExpired() noexcept override {
  40     timestamps.emplace_back();
  41     if (fn) {
  42       fn();
  43     }
  44   }
  45
  46   void callbackCanceled() noexcept override {
  47     canceledTimestamps.emplace_back();
  48     if (fn) {
  49       fn();
  50     }
  51   }
  52
  53   std::deque<TimePoint> timestamps;
  54   std::deque<TimePoint> canceledTimestamps;
  55   std::function<void()> fn;
  56 };
  57
  58
  59 class TestTimeoutDelayed : public TestTimeout {
  60  protected:
  61     std::chrono::milliseconds getCurTime() override {
  62       return std::chrono::duration_cast<std::chrono::milliseconds>(
  63         std::chrono::steady_clock::now().time_since_epoch()) -
  64         milliseconds(5);
  65     }
  66 };
  67
  68 struct HHWheelTimerTest : public ::testing::Test {
  69   EventBase eventBase;
  70 };
  71
  72 /*
  73  * Test firing some simple timeouts that are fired once and never rescheduled
  74  */
  75 TEST_F(HHWheelTimerTest, FireOnce) {
  76   StackWheelTimer t(&eventBase, milliseconds(1));
  77
  78   TestTimeout t1;
  79   TestTimeout t2;
  80   TestTimeout t3;
  81
  82   ASSERT_EQ(t.count(), 0);
  83
  84   t.scheduleTimeout(&t1, milliseconds(5));
  85   t.scheduleTimeout(&t2, milliseconds(5));
  86   // Verify scheduling it twice cancels, then schedules.
  87   // Should only get one callback.
  88   t.scheduleTimeout(&t2, milliseconds(5));
  89   t.scheduleTimeout(&t3, milliseconds(10));
  90
  91   ASSERT_EQ(t.count(), 3);
  92
  93   TimePoint start;
  94   eventBase.loop();
  95   TimePoint end;
  96
  97   ASSERT_EQ(t1.timestamps.size(), 1);
  98   ASSERT_EQ(t2.timestamps.size(), 1);
  99   ASSERT_EQ(t3.timestamps.size(), 1);
 100
 101   ASSERT_EQ(t.count(), 0);
 102
 103   T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(5));
 104   T_CHECK_TIMEOUT(start, t2.timestamps[0], milliseconds(5));
 105   T_CHECK_TIMEOUT(start, t3.timestamps[0], milliseconds(10));
 106   T_CHECK_TIMEOUT(start, end, milliseconds(10));
 107 }
 108
 109 /*
 110  * Test scheduling a timeout from another timeout callback.
 111  */
 112 TEST_F(HHWheelTimerTest, TestSchedulingWithinCallback) {
 113   HHWheelTimer& t = eventBase.timer();
 114
 115   TestTimeout t1;
 116   // Delayed to simulate the steady_clock counter lagging
 117   TestTimeoutDelayed t2;
 118
 119   t.scheduleTimeout(&t1, milliseconds(500));
 120   t1.fn = [&] { t.scheduleTimeout(&t2, milliseconds(1)); };
 121   // If t is in an inconsistent state, detachEventBase should fail.
 122   t2.fn = [&] { t.detachEventBase(); };
 123
 124   ASSERT_EQ(t.count(), 1);
 125
 126   eventBase.loop();
 127
 128   ASSERT_EQ(t.count(), 0);
 129   ASSERT_EQ(t1.timestamps.size(), 1);
 130   ASSERT_EQ(t2.timestamps.size(), 1);
 131 }
 132
 133 /*
 134  * Test cancelling a timeout when it is scheduled to be fired right away.
 135  */
 136
 137 TEST_F(HHWheelTimerTest, CancelTimeout) {
 138   HHWheelTimer& t = eventBase.timer();
 139
 140   // Create several timeouts that will all fire in 5ms.
 141   TestTimeout t5_1(&t, milliseconds(5));
 142   TestTimeout t5_2(&t, milliseconds(5));
 143   TestTimeout t5_3(&t, milliseconds(5));
 144   TestTimeout t5_4(&t, milliseconds(5));
 145   TestTimeout t5_5(&t, milliseconds(5));
 146
 147   // Also create a few timeouts to fire in 10ms
 148   TestTimeout t10_1(&t, milliseconds(10));
 149   TestTimeout t10_2(&t, milliseconds(10));
 150   TestTimeout t10_3(&t, milliseconds(10));
 151
 152   TestTimeout t20_1(&t, milliseconds(20));
 153   TestTimeout t20_2(&t, milliseconds(20));
 154
 155   // Have t5_1 cancel t5_2 and t5_4.
 156   //
 157   // Cancelling t5_2 will test cancelling a timeout that is at the head of the
 158   // list and ready to be fired.
 159   //
 160   // Cancelling t5_4 will test cancelling a timeout in the middle of the list
 161   t5_1.fn = [&] {
 162     t5_2.cancelTimeout();
 163     t5_4.cancelTimeout();
 164   };
 165
 166   // Have t5_3 cancel t5_5.
 167   // This will test cancelling the last remaining timeout.
 168   //
 169   // Then have t5_3 reschedule itself.
 170   t5_3.fn = [&] {
 171     t5_5.cancelTimeout();
 172     // Reset our function so we won't continually reschedule ourself
 173     std::function<void()> fnDtorGuard;
 174     t5_3.fn.swap(fnDtorGuard);
 175     t.scheduleTimeout(&t5_3, milliseconds(5));
 176
 177     // Also test cancelling timeouts in another timeset that isn't ready to
 178     // fire yet.
 179     //
 180     // Cancel the middle timeout in ts10.
 181     t10_2.cancelTimeout();
 182     // Cancel both the timeouts in ts20.
 183     t20_1.cancelTimeout();
 184     t20_2.cancelTimeout();
 185   };
 186
 187   TimePoint start;
 188   eventBase.loop();
 189   TimePoint end;
 190
 191   ASSERT_EQ(t5_1.timestamps.size(), 1);
 192   T_CHECK_TIMEOUT(start, t5_1.timestamps[0], milliseconds(5));
 193
 194   ASSERT_EQ(t5_3.timestamps.size(), 2);
 195   T_CHECK_TIMEOUT(start, t5_3.timestamps[0], milliseconds(5));
 196   T_CHECK_TIMEOUT(t5_3.timestamps[0], t5_3.timestamps[1], milliseconds(5));
 197
 198   ASSERT_EQ(t10_1.timestamps.size(), 1);
 199   T_CHECK_TIMEOUT(start, t10_1.timestamps[0], milliseconds(10));
 200   ASSERT_EQ(t10_3.timestamps.size(), 1);
 201   T_CHECK_TIMEOUT(start, t10_3.timestamps[0], milliseconds(10));
 202
 203   // Cancelled timeouts
 204   ASSERT_EQ(t5_2.timestamps.size(), 0);
 205   ASSERT_EQ(t5_4.timestamps.size(), 0);
 206   ASSERT_EQ(t5_5.timestamps.size(), 0);
 207   ASSERT_EQ(t10_2.timestamps.size(), 0);
 208   ASSERT_EQ(t20_1.timestamps.size(), 0);
 209   ASSERT_EQ(t20_2.timestamps.size(), 0);
 210
 211   T_CHECK_TIMEOUT(start, end, milliseconds(10));
 212 }
 213
 214 /*
 215  * Test destroying a HHWheelTimer with timeouts outstanding
 216  */
 217
 218 TEST_F(HHWheelTimerTest, DestroyTimeoutSet) {
 219   HHWheelTimer::UniquePtr t(
 220       HHWheelTimer::newTimer(&eventBase, milliseconds(1)));
 221
 222   TestTimeout t5_1(t.get(), milliseconds(5));
 223   TestTimeout t5_2(t.get(), milliseconds(5));
 224   TestTimeout t5_3(t.get(), milliseconds(5));
 225
 226   TestTimeout t10_1(t.get(), milliseconds(10));
 227   TestTimeout t10_2(t.get(), milliseconds(10));
 228
 229   // Have t5_2 destroy t
 230   // Note that this will call destroy() inside t's timeoutExpired()
 231   // method.
 232   t5_2.fn = [&] {
 233     t5_3.cancelTimeout();
 234     t5_1.cancelTimeout();
 235     t10_1.cancelTimeout();
 236     t10_2.cancelTimeout();
 237     t.reset();};
 238
 239   TimePoint start;
 240   eventBase.loop();
 241   TimePoint end;
 242
 243   ASSERT_EQ(t5_1.timestamps.size(), 1);
 244   T_CHECK_TIMEOUT(start, t5_1.timestamps[0], milliseconds(5));
 245   ASSERT_EQ(t5_2.timestamps.size(), 1);
 246   T_CHECK_TIMEOUT(start, t5_2.timestamps[0], milliseconds(5));
 247
 248   ASSERT_EQ(t5_3.timestamps.size(), 0);
 249   ASSERT_EQ(t10_1.timestamps.size(), 0);
 250   ASSERT_EQ(t10_2.timestamps.size(), 0);
 251
 252   T_CHECK_TIMEOUT(start, end, milliseconds(5));
 253 }
 254
 255 /*
 256  * Test the tick interval parameter
 257  */
 258 TEST_F(HHWheelTimerTest, AtMostEveryN) {
 259
 260   // Create a timeout set with a 10ms interval, to fire no more than once
 261   // every 3ms.
 262   milliseconds interval(25);
 263   milliseconds atMostEveryN(6);
 264   StackWheelTimer t(&eventBase, atMostEveryN);
 265   t.setCatchupEveryN(70);
 266
 267   // Create 60 timeouts to be added to ts1 at 1ms intervals.
 268   uint32_t numTimeouts = 60;
 269   std::vector<TestTimeout> timeouts(numTimeouts);
 270
 271   // Create a scheduler timeout to add the timeouts 1ms apart.
 272   uint32_t index = 0;
 273   StackWheelTimer ts1(&eventBase, milliseconds(1));
 274   TestTimeout scheduler(&ts1, milliseconds(1));
 275   scheduler.fn = [&] {
 276     if (index >= numTimeouts) {
 277       return;
 278     }
 279     // Call timeoutExpired() on the timeout so it will record a timestamp.
 280     // This is done only so we can record when we scheduled the timeout.
 281     // This way if ts1 starts to fall behind a little over time we will still
 282     // be comparing the ts1 timeouts to when they were first scheduled (rather
 283     // than when we intended to schedule them).  The scheduler may fall behind
 284     // eventually since we don't really schedule it once every millisecond.
 285     // Each time it finishes we schedule it for 1 millisecond in the future.
 286     // The amount of time it takes to run, and any delays it encounters
 287     // getting scheduled may eventually add up over time.
 288     timeouts[index].timeoutExpired();
 289
 290     // Schedule the new timeout
 291     t.scheduleTimeout(&timeouts[index], interval);
 292     // Reschedule ourself
 293     ts1.scheduleTimeout(&scheduler, milliseconds(1));
 294     ++index;
 295   };
 296
 297   // Go ahead and schedule the first timeout now.
 298   //scheduler.fn();
 299
 300   TimePoint start;
 301   eventBase.loop();
 302   TimePoint end;
 303
 304   // This should take roughly 2*60 + 25 ms to finish. If it takes more than
 305   // 250 ms to finish the system is probably heavily loaded, so skip.
 306   if (std::chrono::duration_cast<std::chrono::milliseconds>(
 307         end.getTime() - start.getTime()).count() > 250) {
 308     LOG(WARNING) << "scheduling all timeouts takes too long";
 309     return;
 310   }
 311
 312   // We scheduled timeouts 1ms apart, when the HHWheelTimer is only allowed
 313   // to wake up at most once every 3ms.  It will therefore wake up every 3ms
 314   // and fire groups of approximately 3 timeouts at a time.
 315   //
 316   // This is "approximately 3" since it may get slightly behind and fire 4 in
 317   // one interval, etc.  T_CHECK_TIMEOUT normally allows a few milliseconds of
 318   // tolerance.  We have to add the same into our checking algorithm here.
 319   for (uint32_t idx = 0; idx < numTimeouts; ++idx) {
 320     ASSERT_EQ(timeouts[idx].timestamps.size(), 2);
 321
 322     TimePoint scheduledTime(timeouts[idx].timestamps[0]);
 323     TimePoint firedTime(timeouts[idx].timestamps[1]);
 324
 325     // Assert that the timeout fired at roughly the right time.
 326     // T_CHECK_TIMEOUT() normally has a tolerance of 5ms.  Allow an additional
 327     // atMostEveryN.
 328     milliseconds tolerance = milliseconds(5) + interval;
 329     T_CHECK_TIMEOUT(scheduledTime, firedTime, atMostEveryN, tolerance);
 330
 331     // Assert that the difference between the previous timeout and now was
 332     // either very small (fired in the same event loop), or larger than
 333     // atMostEveryN.
 334     if (idx == 0) {
 335       // no previous value
 336       continue;
 337     }
 338     TimePoint prev(timeouts[idx - 1].timestamps[1]);
 339
 340     auto delta = (firedTime.getTimeStart() - prev.getTimeEnd()) -
 341       (firedTime.getTimeWaiting() - prev.getTimeWaiting());
 342     if (delta > milliseconds(1)) {
 343       T_CHECK_TIMEOUT(prev, firedTime, atMostEveryN);
 344     }
 345   }
 346 }
 347
 348 /*
 349  * Test an event loop that is blocking
 350  */
 351
 352 TEST_F(HHWheelTimerTest, SlowLoop) {
 353   HHWheelTimer& t = eventBase.timer();
 354
 355   TestTimeout t1;
 356   TestTimeout t2;
 357
 358   ASSERT_EQ(t.count(), 0);
 359
 360   eventBase.runInLoop([](){usleep(10000);});
 361   t.scheduleTimeout(&t1, milliseconds(5));
 362
 363   ASSERT_EQ(t.count(), 1);
 364
 365   TimePoint start;
 366   eventBase.loop();
 367   TimePoint end;
 368
 369   ASSERT_EQ(t1.timestamps.size(), 1);
 370   ASSERT_EQ(t.count(), 0);
 371
 372   // Check that the timeout was delayed by sleep
 373   T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(15), milliseconds(1));
 374   T_CHECK_TIMEOUT(start, end, milliseconds(15), milliseconds(1));
 375
 376   // Try it again, this time with catchup timing every loop
 377   t.setCatchupEveryN(1);
 378
 379   eventBase.runInLoop([](){usleep(10000);});
 380   t.scheduleTimeout(&t2, milliseconds(5));
 381
 382   ASSERT_EQ(t.count(), 1);
 383
 384   TimePoint start2;
 385   eventBase.loop();
 386   TimePoint end2;
 387
 388   ASSERT_EQ(t2.timestamps.size(), 1);
 389   ASSERT_EQ(t.count(), 0);
 390
 391   // Check that the timeout was NOT delayed by sleep
 392   T_CHECK_TIMEOUT(start2, t2.timestamps[0], milliseconds(10), milliseconds(1));
 393   T_CHECK_TIMEOUT(start2, end2, milliseconds(10), milliseconds(1));
 394 }
 395
 396 /*
 397  * Test scheduling a mix of timers with default timeout and variable timeout.
 398  */
 399 TEST_F(HHWheelTimerTest, DefaultTimeout) {
 400   milliseconds defaultTimeout(milliseconds(5));
 401   StackWheelTimer t(&eventBase,
 402                     milliseconds(1),
 403                     AsyncTimeout::InternalEnum::NORMAL,
 404                     defaultTimeout);
 405
 406   TestTimeout t1;
 407   TestTimeout t2;
 408
 409   ASSERT_EQ(t.count(), 0);
 410   ASSERT_EQ(t.getDefaultTimeout(), defaultTimeout);
 411
 412   t.scheduleTimeout(&t1);
 413   t.scheduleTimeout(&t2, milliseconds(10));
 414
 415   ASSERT_EQ(t.count(), 2);
 416
 417   TimePoint start;
 418   eventBase.loop();
 419   TimePoint end;
 420
 421   ASSERT_EQ(t1.timestamps.size(), 1);
 422   ASSERT_EQ(t2.timestamps.size(), 1);
 423
 424   ASSERT_EQ(t.count(), 0);
 425
 426   T_CHECK_TIMEOUT(start, t1.timestamps[0], defaultTimeout);
 427   T_CHECK_TIMEOUT(start, t2.timestamps[0], milliseconds(10));
 428   T_CHECK_TIMEOUT(start, end, milliseconds(10));
 429 }
 430
 431 TEST_F(HHWheelTimerTest, lambda) {
 432   HHWheelTimer& t = eventBase.timer();
 433   size_t count = 0;
 434   t.scheduleTimeoutFn([&]{ count++; }, milliseconds(1));
 435   eventBase.loop();
 436   EXPECT_EQ(1, count);
 437 }
 438
 439 // shouldn't crash because we swallow and log the error (you'll have to look
 440 // at the console to confirm logging)
 441 TEST_F(HHWheelTimerTest, lambdaThrows) {
 442   HHWheelTimer& t = eventBase.timer();
 443   t.scheduleTimeoutFn([&]{ throw std::runtime_error("expected"); },
 444                       milliseconds(1));
 445   eventBase.loop();
 446 }
 447
 448 TEST_F(HHWheelTimerTest, cancelAll) {
 449   HHWheelTimer& t = eventBase.timer();
 450   TestTimeout tt;
 451   t.scheduleTimeout(&tt, std::chrono::minutes(1));
 452   EXPECT_EQ(1, t.cancelAll());
 453   EXPECT_EQ(1, tt.canceledTimestamps.size());
 454 }
 455
 456 TEST_F(HHWheelTimerTest, IntrusivePtr) {
 457   HHWheelTimer::UniquePtr t(
 458       HHWheelTimer::newTimer(&eventBase, milliseconds(1)));
 459
 460   TestTimeout t1;
 461   TestTimeout t2;
 462   TestTimeout t3;
 463
 464   ASSERT_EQ(t->count(), 0);
 465
 466   t->scheduleTimeout(&t1, milliseconds(5));
 467   t->scheduleTimeout(&t2, milliseconds(5));
 468
 469   DelayedDestruction::IntrusivePtr<HHWheelTimer> s(t);
 470
 471   s->scheduleTimeout(&t3, milliseconds(10));
 472
 473   ASSERT_EQ(t->count(), 3);
 474
 475   // Kill the UniquePtr, but the SharedPtr keeps it alive
 476   t.reset();
 477
 478   TimePoint start;
 479   eventBase.loop();
 480   TimePoint end;
 481
 482   ASSERT_EQ(t1.timestamps.size(), 1);
 483   ASSERT_EQ(t2.timestamps.size(), 1);
 484   ASSERT_EQ(t3.timestamps.size(), 1);
 485
 486   ASSERT_EQ(s->count(), 0);
 487
 488   T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(5));
 489   T_CHECK_TIMEOUT(start, t2.timestamps[0], milliseconds(5));
 490   T_CHECK_TIMEOUT(start, t3.timestamps[0], milliseconds(10));
 491   T_CHECK_TIMEOUT(start, end, milliseconds(10));
 492 }