proxygen
HHWheelTimerSlowTests.cpp
Go to the documentation of this file.
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>
22 
23 #include <thread>
24 #include <vector>
25 
26 using namespace folly;
27 using std::chrono::milliseconds;
28 
30 
31 class TestTimeout : public HHWheelTimer::Callback {
32  public:
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 
58  protected:
59  std::chrono::steady_clock::time_point getCurTime() override {
60  return std::chrono::steady_clock::now() - milliseconds(5);
61  }
62 };
63 
66 };
67 
68 /* Test takes ~2.5 minutes to run */
70  HHWheelTimer& t = eventBase.timer();
71 
72  TestTimeout t1;
73  TestTimeout t2;
74 
75  ASSERT_EQ(t.count(), 0);
76 
77  t.scheduleTimeout(&t1, milliseconds(605 * 256));
78  t.scheduleTimeout(&t2, milliseconds(300 * 256));
79 
80  ASSERT_EQ(t.count(), 2);
81 
83  eventBase.loop();
84  TimePoint end;
85 
86  ASSERT_EQ(t1.timestamps.size(), 1);
87  ASSERT_EQ(t2.timestamps.size(), 1);
88  ASSERT_EQ(t.count(), 0);
89 
90  // Check that the timeout was delayed by sleep
92  start,
93  t1.timestamps[0],
94  milliseconds(605 * 256),
95  milliseconds(256 * 256));
97  start,
98  t2.timestamps[0],
99  milliseconds(300 * 256),
100  milliseconds(256 * 256));
101 }
102 
103 /*
104  * Test the tick interval parameter
105  */
106 TEST_F(HHWheelTimerTest, AtMostEveryN) {
107  // Create a timeout set with a 10ms interval, to fire no more than once
108  // every 3ms.
109  milliseconds interval(10);
110  milliseconds atMostEveryN(3);
111  StackWheelTimer t(&eventBase, atMostEveryN);
112 
113  // Create 60 timeouts to be added to ts1 at 1ms intervals.
114  uint32_t numTimeouts = 60;
115  std::vector<TestTimeout> timeouts(numTimeouts);
116 
117  // Create a scheduler timeout to add the timeouts 1ms apart.
118  uint32_t index = 0;
119  StackWheelTimer ts1(&eventBase, milliseconds(1));
120  TestTimeout scheduler(&ts1, milliseconds(1));
121  scheduler.fn = [&] {
122  if (index >= numTimeouts) {
123  return;
124  }
125  // Call timeoutExpired() on the timeout so it will record a timestamp.
126  // This is done only so we can record when we scheduled the timeout.
127  // This way if ts1 starts to fall behind a little over time we will still
128  // be comparing the ts1 timeouts to when they were first scheduled (rather
129  // than when we intended to schedule them). The scheduler may fall behind
130  // eventually since we don't really schedule it once every millisecond.
131  // Each time it finishes we schedule it for 1 millisecond in the future.
132  // The amount of time it takes to run, and any delays it encounters
133  // getting scheduled may eventually add up over time.
134  timeouts[index].timeoutExpired();
135 
136  // Schedule the new timeout
137  t.scheduleTimeout(&timeouts[index], interval);
138  // Reschedule ourself
139  ts1.scheduleTimeout(&scheduler, milliseconds(1));
140  ++index;
141  };
142 
144  eventBase.loop();
145  TimePoint end;
146 
147  // This should take roughly 60 + 10 ms to finish. If it takes more than
148  // 250 ms to finish the system is probably heavily loaded, so skip.
149  if (std::chrono::duration_cast<std::chrono::milliseconds>(
150  end.getTime() - start.getTime())
151  .count() > 250) {
152  LOG(WARNING) << "scheduling all timeouts takes too long";
153  return;
154  }
155 
156  // We scheduled timeouts 1ms apart, when the HHWheelTimer is only allowed
157  // to wake up at most once every 3ms. It will therefore wake up every 3ms
158  // and fire groups of approximately 3 timeouts at a time.
159  //
160  // This is "approximately 3" since it may get slightly behind and fire 4 in
161  // one interval, etc. T_CHECK_TIMEOUT normally allows a few milliseconds of
162  // tolerance. We have to add the same into our checking algorithm here.
163  for (uint32_t idx = 0; idx < numTimeouts; ++idx) {
164  ASSERT_EQ(timeouts[idx].timestamps.size(), 2);
165 
166  TimePoint scheduledTime(timeouts[idx].timestamps[0]);
167  TimePoint firedTime(timeouts[idx].timestamps[1]);
168 
169  // Assert that the timeout fired at roughly the right time.
170  // T_CHECK_TIMEOUT() normally has a tolerance of 5ms. Allow an additional
171  // atMostEveryN.
172  milliseconds tolerance = milliseconds(5) + interval;
173  T_CHECK_TIMEOUT(scheduledTime, firedTime, atMostEveryN, tolerance);
174 
175  // Assert that the difference between the previous timeout and now was
176  // either very small (fired in the same event loop), or larger than
177  // atMostEveryN.
178  if (idx == 0) {
179  // no previous value
180  continue;
181  }
182  TimePoint prev(timeouts[idx - 1].timestamps[1]);
183 
184  auto delta = (firedTime.getTimeStart() - prev.getTimeEnd()) -
185  (firedTime.getTimeWaiting() - prev.getTimeWaiting());
186  if (delta > milliseconds(1)) {
187  T_CHECK_TIMEOUT(prev, firedTime, atMostEveryN);
188  }
189  }
190 }
191 
192 /*
193  * Test an event loop that is blocking
194  */
195 
197  StackWheelTimer t(&eventBase, milliseconds(1));
198 
199  TestTimeout t1;
200  TestTimeout t2;
201 
202  ASSERT_EQ(t.count(), 0);
203 
204  eventBase.runInLoop([]() {
205  /* sleep override */
206  std::this_thread::sleep_for(std::chrono::microseconds(10000));
207  });
208  t.scheduleTimeout(&t1, milliseconds(5));
209 
210  ASSERT_EQ(t.count(), 1);
211 
213  eventBase.loop();
214  TimePoint end;
215 
216  ASSERT_EQ(t1.timestamps.size(), 1);
217  ASSERT_EQ(t.count(), 0);
218 
219  // Check that the timeout was delayed by sleep
220  T_CHECK_TIMEOUT(start, t1.timestamps[0], milliseconds(10), milliseconds(1));
221  T_CHECK_TIMEOUT(start, end, milliseconds(10), milliseconds(1));
222 
223  eventBase.runInLoop([]() {
224  /* sleep override */
225  std::this_thread::sleep_for(std::chrono::microseconds(10000));
226  });
227  t.scheduleTimeout(&t2, milliseconds(5));
228 
229  ASSERT_EQ(t.count(), 1);
230 
231  TimePoint start2;
232  eventBase.loop();
233  TimePoint end2;
234 
235  ASSERT_EQ(t2.timestamps.size(), 1);
236  ASSERT_EQ(t.count(), 0);
237 
238  // Check that the timeout was NOT delayed by sleep
239  T_CHECK_TIMEOUT(start2, t2.timestamps[0], milliseconds(10), milliseconds(1));
240  T_CHECK_TIMEOUT(start2, end2, milliseconds(10), milliseconds(1));
241 }
242 
243 /*
244  * Test upper timer levels. Slow by necessity :/
245  */
246 
248  HHWheelTimer& t = eventBase.timer();
249 
250  TestTimeout t1;
251  TestTimeout t2;
252 
253  ASSERT_EQ(t.count(), 0);
254 
255  t.scheduleTimeout(&t1, milliseconds(605));
256  t.scheduleTimeout(&t2, milliseconds(300));
257 
258  ASSERT_EQ(t.count(), 2);
259 
261  eventBase.loop();
262  TimePoint end;
263 
264  ASSERT_EQ(t1.timestamps.size(), 1);
265  ASSERT_EQ(t2.timestamps.size(), 1);
266  ASSERT_EQ(t.count(), 0);
267 
268  // Check that the timeout was delayed by sleep
270  start, t1.timestamps[0], milliseconds(605), milliseconds(256));
272  start, t2.timestamps[0], milliseconds(300), milliseconds(256));
273 }
274 
276  StackWheelTimer t(&eventBase, milliseconds(1));
277 
278  long timeoutcount = 10000;
279  TestTimeout timeouts[10000];
280  long runtimeouts = 0;
281  for (long i = 0; i < timeoutcount; i++) {
282  long timeout = Random::rand32(1, 10000);
283  if (Random::rand32(3)) {
284  // NOTE: hhwheel timer runs before eventbase runAfterDelay,
285  // so runAfterDelay cancelTimeout() must run at least one timerwheel
286  // before scheduleTimeout, to ensure it runs first.
287  timeout += 256;
288  t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(timeout));
289  eventBase.runAfterDelay(
290  [&, i]() {
291  timeouts[i].fn = nullptr;
292  timeouts[i].cancelTimeout();
293  runtimeouts++;
294  LOG(INFO) << "Ran " << runtimeouts << " timeouts, cancelled";
295  },
296  timeout - 256);
297  timeouts[i].fn = [&, i, timeout]() {
298  LOG(INFO) << "FAIL:timer " << i << " still fired in " << timeout;
299  ADD_FAILURE();
300  };
301  } else {
302  t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(timeout));
303  timeouts[i].fn = [&, i]() {
304  timeoutcount++;
305  long newtimeout = Random::rand32(1, 10000);
306  t.scheduleTimeout(&timeouts[i], std::chrono::milliseconds(newtimeout));
307  runtimeouts++;
308  /* sleep override */ usleep(1000);
309  LOG(INFO) << "Ran " << runtimeouts << " timeouts of " << timeoutcount;
310  timeouts[i].fn = [&]() {
311  runtimeouts++;
312  LOG(INFO) << "Ran " << runtimeouts << " timeouts of " << timeoutcount;
313  };
314  };
315  }
316  }
317 
318  LOG(INFO) << "RUNNING TEST";
319  eventBase.loop();
320 
321  EXPECT_EQ(runtimeouts, timeoutcount);
322 }
std::chrono::steady_clock::time_point getTime() const
Definition: TimeUtil.h:50
UndelayedDestruction< HHWheelTimer > StackWheelTimer
#define ASSERT_EQ(val1, val2)
Definition: gtest.h:1956
std::chrono::nanoseconds getTimeWaiting() const
Definition: TimeUtil.h:62
std::deque< TimePoint > canceledTimestamps
#define EXPECT_EQ(val1, val2)
Definition: gtest.h:1922
std::chrono::steady_clock::time_point now()
—— Concurrent Priority Queue Implementation ——
Definition: AtomicBitSet.h:29
requires E e noexcept(noexcept(s.error(std::move(e))))
std::shared_ptr< folly::FunctionScheduler > scheduler
Definition: FilePoller.cpp:50
void scheduleTimeout(Callback *callback, std::chrono::milliseconds timeout)
std::deque< TimePoint > timestamps
TestTimeout(HHWheelTimer *t, milliseconds timeout)
void callbackCanceled() noexceptoverride
auto end(TestAdlIterable &instance)
Definition: ForeachTest.cpp:62
void timeoutExpired() noexceptoverride
std::chrono::steady_clock::time_point getTimeStart() const
Definition: TimeUtil.h:54
auto start
TEST_F(AsyncSSLSocketWriteTest, write_coalescing1)
int * count
std::size_t count() const
Definition: HHWheelTimer.h:252
std::chrono::steady_clock::time_point getCurTime() override
static uint32_t rand32()
Definition: Random.h:213
#define ADD_FAILURE()
Definition: gtest.h:1808
std::function< void()> fn
#define T_CHECK_TIMEOUT(start, end, expectedMS,...)
Definition: Util.h:38
std::chrono::steady_clock::time_point getTimeEnd() const
Definition: TimeUtil.h:58