HHWheelTimerSlowTests.cpp 9.4 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322
  1. /*
  2. * Copyright 2016-present 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. #include <thread>
  23. #include <vector>
  24. using namespace folly;
  25. using std::chrono::milliseconds;
  26. typedef UndelayedDestruction<HHWheelTimer> StackWheelTimer;
  27. class TestTimeout : public HHWheelTimer::Callback {
  28. public:
  29. TestTimeout() {}
  30. TestTimeout(HHWheelTimer* t, milliseconds timeout) {
  31. t->scheduleTimeout(this, timeout);
  32. }
  33. void timeoutExpired() noexcept override {
  34. timestamps.emplace_back();
  35. if (fn) {
  36. fn();
  37. }
  38. }
  39. void callbackCanceled() noexcept override {
  40. canceledTimestamps.emplace_back();
  41. if (fn) {
  42. fn();
  43. }
  44. }
  45. std::deque<TimePoint> timestamps;
  46. std::deque<TimePoint> canceledTimestamps;
  47. std::function<void()> fn;
  48. };
  49. class TestTimeoutDelayed : public TestTimeout {
  50. protected:
  51. std::chrono::steady_clock::time_point getCurTime() override {
  52. return std::chrono::steady_clock::now() - milliseconds(5);
  53. }
  54. };
  55. struct HHWheelTimerTest : public ::testing::Test {
  56. EventBase eventBase;
  57. };
  58. /* Test takes ~2.5 minutes to run */
  59. TEST_F(HHWheelTimerTest, Level2) {
  60. HHWheelTimer& t = eventBase.timer();
  61. TestTimeout t1;
  62. TestTimeout t2;
  63. ASSERT_EQ(t.count(), 0);
  64. t.scheduleTimeout(&t1, milliseconds(605 * 256));
  65. t.scheduleTimeout(&t2, milliseconds(300 * 256));
  66. ASSERT_EQ(t.count(), 2);
  67. TimePoint start;
  68. eventBase.loop();
  69. TimePoint end;
  70. ASSERT_EQ(t1.timestamps.size(), 1);
  71. ASSERT_EQ(t2.timestamps.size(), 1);
  72. ASSERT_EQ(t.count(), 0);
  73. // Check that the timeout was delayed by sleep
  74. T_CHECK_TIMEOUT(
  75. start,
  76. t1.timestamps[0],
  77. milliseconds(605 * 256),
  78. milliseconds(256 * 256));
  79. T_CHECK_TIMEOUT(
  80. start,
  81. t2.timestamps[0],
  82. milliseconds(300 * 256),
  83. milliseconds(256 * 256));
  84. }
  85. /*
  86. * Test the tick interval parameter
  87. */
  88. TEST_F(HHWheelTimerTest, AtMostEveryN) {
  89. // Create a timeout set with a 10ms interval, to fire no more than once
  90. // every 3ms.
  91. milliseconds interval(10);
  92. milliseconds atMostEveryN(3);
  93. StackWheelTimer t(&eventBase, atMostEveryN);
  94. // Create 60 timeouts to be added to ts1 at 1ms intervals.
  95. uint32_t numTimeouts = 60;
  96. std::vector<TestTimeout> timeouts(numTimeouts);
  97. // Create a scheduler timeout to add the timeouts 1ms apart.
  98. uint32_t index = 0;
  99. StackWheelTimer ts1(&eventBase, milliseconds(1));
  100. TestTimeout scheduler(&ts1, milliseconds(1));
  101. scheduler.fn = [&] {
  102. if (index >= numTimeouts) {
  103. return;
  104. }
  105. // Call timeoutExpired() on the timeout so it will record a timestamp.
  106. // This is done only so we can record when we scheduled the timeout.
  107. // This way if ts1 starts to fall behind a little over time we will still
  108. // be comparing the ts1 timeouts to when they were first scheduled (rather
  109. // than when we intended to schedule them). The scheduler may fall behind
  110. // eventually since we don't really schedule it once every millisecond.
  111. // Each time it finishes we schedule it for 1 millisecond in the future.
  112. // The amount of time it takes to run, and any delays it encounters
  113. // getting scheduled may eventually add up over time.
  114. timeouts[index].timeoutExpired();
  115. // Schedule the new timeout
  116. t.scheduleTimeout(&timeouts[index], interval);
  117. // Reschedule ourself
  118. ts1.scheduleTimeout(&scheduler, milliseconds(1));
  119. ++index;
  120. };
  121. TimePoint start;
  122. eventBase.loop();
  123. TimePoint end;
  124. // This should take roughly 60 + 10 ms to finish. If it takes more than
  125. // 250 ms to finish the system is probably heavily loaded, so skip.
  126. if (std::chrono::duration_cast<std::chrono::milliseconds>(
  127. end.getTime() - start.getTime())
  128. .count() > 250) {
  129. LOG(WARNING) << "scheduling all timeouts takes too long";
  130. return;
  131. }
  132. // We scheduled timeouts 1ms apart, when the HHWheelTimer is only allowed
  133. // to wake up at most once every 3ms. It will therefore wake up every 3ms
  134. // and fire groups of approximately 3 timeouts at a time.
  135. //
  136. // This is "approximately 3" since it may get slightly behind and fire 4 in
  137. // one interval, etc. T_CHECK_TIMEOUT normally allows a few milliseconds of
  138. // tolerance. We have to add the same into our checking algorithm here.
  139. for (uint32_t idx = 0; idx < numTimeouts; ++idx) {
  140. ASSERT_EQ(timeouts[idx].timestamps.size(), 2);
  141. TimePoint scheduledTime(timeouts[idx].timestamps[0]);
  142. TimePoint firedTime(timeouts[idx].timestamps[1]);
  143. // Assert that the timeout fired at roughly the right time.
  144. // T_CHECK_TIMEOUT() normally has a tolerance of 5ms. Allow an additional
  145. // atMostEveryN.
  146. milliseconds tolerance = milliseconds(5) + interval;
  147. T_CHECK_TIMEOUT(scheduledTime, firedTime, atMostEveryN, tolerance);
  148. // Assert that the difference between the previous timeout and now was
  149. // either very small (fired in the same event loop), or larger than
  150. // atMostEveryN.
  151. if (idx == 0) {
  152. // no previous value
  153. continue;
  154. }
  155. TimePoint prev(timeouts[idx - 1].timestamps[1]);
  156. auto delta = (firedTime.getTimeStart() - prev.getTimeEnd()) -
  157. (firedTime.getTimeWaiting() - prev.getTimeWaiting());
  158. if (delta > milliseconds(1)) {
  159. T_CHECK_TIMEOUT(prev, firedTime, atMostEveryN);
  160. }
  161. }
  162. }
  163. /*
  164. * Test an event loop that is blocking
  165. */
  166. TEST_F(HHWheelTimerTest, SlowLoop) {
  167. StackWheelTimer t(&eventBase, milliseconds(1));
  168. TestTimeout t1;
  169. TestTimeout t2;
  170. ASSERT_EQ(t.count(), 0);
  171. eventBase.runInLoop([]() {
  172. /* sleep override */
  173. std::this_thread::sleep_for(std::chrono::microseconds(10000));
  174. });
  175. t.scheduleTimeout(&t1, milliseconds(5));
  176. ASSERT_EQ(t.count(), 1);
  177. TimePoint start;
  178. eventBase.loop();
  179. TimePoint end;
  180. ASSERT_EQ(t1.timestamps.size(), 1);
  181. ASSERT_EQ(t.count(), 0);
  182. // Check that the timeout was delayed by sleep
  183. T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(10), milliseconds(1));
  184. T_CHECK_TIMEOUT(start, end, milliseconds(10), milliseconds(1));
  185. eventBase.runInLoop([]() {
  186. /* sleep override */
  187. std::this_thread::sleep_for(std::chrono::microseconds(10000));
  188. });
  189. t.scheduleTimeout(&t2, milliseconds(5));
  190. ASSERT_EQ(t.count(), 1);
  191. TimePoint start2;
  192. eventBase.loop();
  193. TimePoint end2;
  194. ASSERT_EQ(t2.timestamps.size(), 1);
  195. ASSERT_EQ(t.count(), 0);
  196. // Check that the timeout was NOT delayed by sleep
  197. T_CHECK_TIMEOUT(start2, t2.timestamps[0], milliseconds(10), milliseconds(1));
  198. T_CHECK_TIMEOUT(start2, end2, milliseconds(10), milliseconds(1));
  199. }
  200. /*
  201. * Test upper timer levels. Slow by necessity :/
  202. */
  203. TEST_F(HHWheelTimerTest, Level1) {
  204. HHWheelTimer& t = eventBase.timer();
  205. TestTimeout t1;
  206. TestTimeout t2;
  207. ASSERT_EQ(t.count(), 0);
  208. t.scheduleTimeout(&t1, milliseconds(605));
  209. t.scheduleTimeout(&t2, milliseconds(300));
  210. ASSERT_EQ(t.count(), 2);
  211. TimePoint start;
  212. eventBase.loop();
  213. TimePoint end;
  214. ASSERT_EQ(t1.timestamps.size(), 1);
  215. ASSERT_EQ(t2.timestamps.size(), 1);
  216. ASSERT_EQ(t.count(), 0);
  217. // Check that the timeout was delayed by sleep
  218. T_CHECK_TIMEOUT(
  219. start, t1.timestamps[0], milliseconds(605), milliseconds(256));
  220. T_CHECK_TIMEOUT(
  221. start, t2.timestamps[0], milliseconds(300), milliseconds(256));
  222. }
  223. TEST_F(HHWheelTimerTest, Stress) {
  224. StackWheelTimer t(&eventBase, milliseconds(1));
  225. long timeoutcount = 10000;
  226. TestTimeout timeouts[10000];
  227. long runtimeouts = 0;
  228. for (long i = 0; i < timeoutcount; i++) {
  229. long timeout = Random::rand32(1, 10000);
  230. if (Random::rand32(3)) {
  231. // NOTE: hhwheel timer runs before eventbase runAfterDelay,
  232. // so runAfterDelay cancelTimeout() must run at least one timerwheel
  233. // before scheduleTimeout, to ensure it runs first.
  234. timeout += 256;
  235. t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(timeout));
  236. eventBase.runAfterDelay(
  237. [&, i]() {
  238. timeouts[i].fn = nullptr;
  239. timeouts[i].cancelTimeout();
  240. runtimeouts++;
  241. LOG(INFO) << "Ran " << runtimeouts << " timeouts, cancelled";
  242. },
  243. timeout - 256);
  244. timeouts[i].fn = [&, i, timeout]() {
  245. LOG(INFO) << "FAIL:timer " << i << " still fired in " << timeout;
  246. ADD_FAILURE();
  247. };
  248. } else {
  249. t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(timeout));
  250. timeouts[i].fn = [&, i]() {
  251. timeoutcount++;
  252. long newtimeout = Random::rand32(1, 10000);
  253. t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(newtimeout));
  254. runtimeouts++;
  255. /* sleep override */ usleep(1000);
  256. LOG(INFO) << "Ran " << runtimeouts << " timeouts of " << timeoutcount;
  257. timeouts[i].fn = [&]() {
  258. runtimeouts++;
  259. LOG(INFO) << "Ran " << runtimeouts << " timeouts of " << timeoutcount;
  260. };
  261. };
  262. }
  263. }
  264. LOG(INFO) << "RUNNING TEST";
  265. eventBase.loop();
  266. EXPECT_EQ(runtimeouts, timeoutcount);
  267. }