diff --git a/source/common/event/BUILD b/source/common/event/BUILD index 1a99e72fe7bd..23ccee3b5ff7 100644 --- a/source/common/event/BUILD +++ b/source/common/event/BUILD @@ -136,6 +136,7 @@ envoy_cc_library( ":libevent_lib", "//include/envoy/event:timer_interface", "//source/common/common:scope_tracker", + "//source/common/runtime:runtime_features_lib", ], ) diff --git a/source/common/event/libevent_scheduler.h b/source/common/event/libevent_scheduler.h index 748036114f5b..6059a0017bae 100644 --- a/source/common/event/libevent_scheduler.h +++ b/source/common/event/libevent_scheduler.h @@ -15,6 +15,49 @@ namespace Envoy { namespace Event { // Implements Scheduler based on libevent. +// +// Here is a rough summary of operations that libevent performs in each event loop iteration, in +// order. Note that the invocation order for "same-iteration" operations that execute as a group +// can be surprising and invocation order of expired timers is non-deterministic. +// Whenever possible, it is preferable to avoid making event invocation ordering assumptions. +// +// 1. Calculate the poll timeout by comparing the current time to the deadline of the closest +// timer (the one at head of the priority queue). +// 2. Run registered "prepare" callbacks. +// 3. Poll for fd events using the closest timer as timeout, add active fds to the work list. +// 4. Run registered "check" callbacks. +// 5. Check timer deadlines against current time and move expired timers from the timer priority +// queue to the work list. Expired timers are moved to the work list is a non-deterministic order. +// 6. Execute items in the work list until the list is empty. Note that additional work +// items could be added to the work list during execution of this step, more details below. +// 7. Goto 1 if the loop termination condition has not been reached +// +// The following "same-iteration" work items are added directly to the work list when they are +// scheduled so they execute in the current iteration of the event loop. Note that there are no +// ordering guarantees when mixing the mechanisms below. Specifically, it is unsafe to assume that +// calling post followed by deferredDelete will result in the post callback being invoked before the +// deferredDelete; deferredDelete will run first if there is a pending deferredDeletion at the time +// the post callback is scheduled because deferredDelete invocation is grouped. +// - Event::Dispatcher::post(cb). Post callbacks are invoked as a group. +// - Event::Dispatcher::deferredDelete(object) and Event::DeferredTaskUtil::deferredRun(...). +// The same mechanism implements both of these operations, so they are invoked as a group. +// - Event::SchedulableCallback::scheduleCallbackCurrentIteration(). Each of these callbacks is +// scheduled and invoked independently. +// - Event::FileEvent::activate() if "envoy.reloadable_features.activate_fds_next_event_loop" +// runtime feature is disabled. +// - Event::Timer::enableTimer(0) if "envoy.reloadable_features.activate_timers_next_event_loop" +// runtime feature is disabled. +// +// Event::FileEvent::activate and Event::SchedulableCallback::scheduleCallbackNextIteration are +// implemented as libevent timers with a deadline of 0. Both of these actions are moved to the work +// list while checking for expired timers during step 5. +// +// Events execute in the following order, derived from the order in which items were added to the +// work list: +// 0. Events added via event_active prior to the start of the event loop (in tests) +// 1. Fd events +// 2. Timers, FileEvent::activate and SchedulableCallback::scheduleCallbackNextIteration +// 3. "Same-iteration" work items described above, including Event::Dispatcher::post callbacks class LibeventScheduler : public Scheduler, public CallbackScheduler { public: using OnPrepareCallback = std::function; diff --git a/source/common/event/timer_impl.cc b/source/common/event/timer_impl.cc index 6c71f3cfe5ac..56137dc8b2e3 100644 --- a/source/common/event/timer_impl.cc +++ b/source/common/event/timer_impl.cc @@ -3,6 +3,7 @@ #include #include "common/common/assert.h" +#include "common/runtime/runtime_features.h" #include "event2/event.h" @@ -10,7 +11,16 @@ namespace Envoy { namespace Event { TimerImpl::TimerImpl(Libevent::BasePtr& libevent, TimerCb cb, Dispatcher& dispatcher) - : cb_(cb), dispatcher_(dispatcher) { + : cb_(cb), dispatcher_(dispatcher), + activate_timers_next_event_loop_( + // Only read the runtime feature if the runtime loader singleton has already been created. + // Accessing runtime features too early in the initialization sequence triggers logging + // and the logging code itself depends on the use of timers. Attempts to log while + // initializing the logging subsystem will result in a crash. + Runtime::LoaderSingleton::getExisting() + ? Runtime::runtimeFeatureEnabled( + "envoy.reloadable_features.activate_timers_next_event_loop") + : true) { ASSERT(cb_); evtimer_assign( &raw_event_, libevent.get(), @@ -44,7 +54,8 @@ void TimerImpl::enableHRTimer(const std::chrono::microseconds& d, void TimerImpl::internalEnableTimer(const timeval& tv, const ScopeTrackedObject* object) { object_ = object; - if (tv.tv_sec == 0 && tv.tv_usec == 0) { + + if (!activate_timers_next_event_loop_ && tv.tv_sec == 0 && tv.tv_usec == 0) { event_active(&raw_event_, EV_TIMEOUT, 0); } else { event_add(&raw_event_, &tv); diff --git a/source/common/event/timer_impl.h b/source/common/event/timer_impl.h index f9e980824269..307fb3fe80d7 100644 --- a/source/common/event/timer_impl.h +++ b/source/common/event/timer_impl.h @@ -70,6 +70,11 @@ class TimerImpl : public Timer, ImplBase { // example if the DispatcherImpl::post is called by two threads, they race to // both set this to null. std::atomic object_{}; + + // Latched "envoy.reloadable_features.activate_timers_next_event_loop" runtime feature. If true, + // timers scheduled with a 0 time delta are evaluated in the next iteration of the event loop + // after polling and activating new fd events. + const bool activate_timers_next_event_loop_; }; } // namespace Event diff --git a/source/common/runtime/runtime_features.cc b/source/common/runtime/runtime_features.cc index 80d33ae2fc3f..ae0602138651 100644 --- a/source/common/runtime/runtime_features.cc +++ b/source/common/runtime/runtime_features.cc @@ -58,6 +58,7 @@ constexpr const char* runtime_features[] = { "envoy.reloadable_features.connection_header_sanitization", // Begin alphabetically sorted section. "envoy.reloadable_features.activate_fds_next_event_loop", + "envoy.reloadable_features.activate_timers_next_event_loop", "envoy.reloadable_features.allow_500_after_100", "envoy.deprecated_features.allow_deprecated_extension_names", "envoy.reloadable_features.allow_prefetch", diff --git a/source/extensions/quic_listeners/quiche/envoy_quic_alarm.cc b/source/extensions/quic_listeners/quiche/envoy_quic_alarm.cc index e652b79a6120..349eb5f2a32b 100644 --- a/source/extensions/quic_listeners/quiche/envoy_quic_alarm.cc +++ b/source/extensions/quic_listeners/quiche/envoy_quic_alarm.cc @@ -18,7 +18,8 @@ void EnvoyQuicAlarm::SetImpl() { // loop. QUICHE alarm is not expected to be scheduled in current event loop. This bit is a bummer // in QUICHE, and we are working on the fix. Once QUICHE is fixed of expecting this behavior, we // no longer need to round up the duration. - // TODO(antoniovicente) improve the timer behavior in such case. + // TODO(antoniovicente) Remove the std::max(1, ...) when decommissioning the + // envoy.reloadable_features.activate_timers_next_event_loop runtime flag. timer_->enableHRTimer( std::chrono::microseconds(std::max(static_cast(1), duration.ToMicroseconds()))); } diff --git a/test/common/event/BUILD b/test/common/event/BUILD index 50a792f01804..b6032fe71825 100644 --- a/test/common/event/BUILD +++ b/test/common/event/BUILD @@ -21,6 +21,7 @@ envoy_cc_test( "//test/mocks:common_lib", "//test/mocks/stats:stats_mocks", "//test/test_common:simulated_time_system_lib", + "//test/test_common:test_runtime_lib", "//test/test_common:utility_lib", ], ) diff --git a/test/common/event/dispatcher_impl_test.cc b/test/common/event/dispatcher_impl_test.cc index 4a709e4972b8..30fbcd32f248 100644 --- a/test/common/event/dispatcher_impl_test.cc +++ b/test/common/event/dispatcher_impl_test.cc @@ -12,6 +12,7 @@ #include "test/mocks/common.h" #include "test/mocks/stats/mocks.h" #include "test/test_common/simulated_time_system.h" +#include "test/test_common/test_runtime.h" #include "test/test_common/utility.h" #include "gmock/gmock.h" @@ -25,6 +26,12 @@ namespace Envoy { namespace Event { namespace { +static void onWatcherReady(evwatch*, const evwatch_prepare_cb_info*, void* arg) { + // `arg` contains the ReadyWatcher passed in from evwatch_prepare_new. + auto watcher = static_cast(arg); + watcher->ready(); +} + class SchedulableCallbackImplTest : public testing::Test { protected: SchedulableCallbackImplTest() @@ -37,12 +44,6 @@ class SchedulableCallbackImplTest : public testing::Test { Api::ApiPtr api_; DispatcherPtr dispatcher_; std::vector callbacks_; - - static void onWatcherReady(evwatch*, const evwatch_prepare_cb_info*, void* arg) { - // `arg` contains the ReadyWatcher passed in from evwatch_prepare_new. - auto watcher = static_cast(arg); - watcher->ready(); - } }; TEST_F(SchedulableCallbackImplTest, ScheduleCurrentAndCancel) { @@ -472,8 +473,19 @@ TEST_F(DispatcherMonotonicTimeTest, ApproximateMonotonicTime) { dispatcher_->run(Dispatcher::RunType::Block); } -class TimerImplTest : public testing::Test { +class TimerImplTest : public testing::TestWithParam { protected: + TimerImplTest() { + Runtime::LoaderSingleton::getExisting()->mergeValues( + {{"envoy.reloadable_features.activate_timers_next_event_loop", + activateTimersNextEventLoop() ? "true" : "false"}}); + // Watch for dispatcher prepare events. + evwatch_prepare_new(&static_cast(dispatcher_.get())->base(), onWatcherReady, + &prepare_watcher_); + } + + bool activateTimersNextEventLoop() { return GetParam(); } + void SetUp() override { // Update time cache to provide a stable time reference for timer registration. event_base_update_cache_time(&libevent_base_); @@ -498,26 +510,153 @@ class TimerImplTest : public testing::Test { } while (duration > absl::DurationFromTimeval(now_tv) - absl::DurationFromTimeval(start_tv)); } + TestScopedRuntime scoped_runtime_; Api::ApiPtr api_{Api::createApiForTest()}; DispatcherPtr dispatcher_{api_->allocateDispatcher("test_thread")}; event_base& libevent_base_{static_cast(*dispatcher_).base()}; + ReadyWatcher prepare_watcher_; }; -TEST_F(TimerImplTest, TimerEnabledDisabled) { +INSTANTIATE_TEST_SUITE_P(DelayActivation, TimerImplTest, testing::Bool()); + +TEST_P(TimerImplTest, TimerEnabledDisabled) { + InSequence s; + Event::TimerPtr timer = dispatcher_->createTimer([] {}); EXPECT_FALSE(timer->enabled()); timer->enableTimer(std::chrono::milliseconds(0)); EXPECT_TRUE(timer->enabled()); + EXPECT_CALL(prepare_watcher_, ready()); dispatcher_->run(Dispatcher::RunType::NonBlock); EXPECT_FALSE(timer->enabled()); timer->enableHRTimer(std::chrono::milliseconds(0)); EXPECT_TRUE(timer->enabled()); + EXPECT_CALL(prepare_watcher_, ready()); dispatcher_->run(Dispatcher::RunType::NonBlock); EXPECT_FALSE(timer->enabled()); } +TEST_P(TimerImplTest, ChangeTimerBackwardsBeforeRun) { + ReadyWatcher watcher1; + Event::TimerPtr timer1 = dispatcher_->createTimer([&] { watcher1.ready(); }); + + ReadyWatcher watcher2; + Event::TimerPtr timer2 = dispatcher_->createTimer([&] { watcher2.ready(); }); + + ReadyWatcher watcher3; + Event::TimerPtr timer3 = dispatcher_->createTimer([&] { watcher3.ready(); }); + + timer1->enableTimer(std::chrono::milliseconds(0)); + timer2->enableTimer(std::chrono::milliseconds(1)); + timer3->enableTimer(std::chrono::milliseconds(2)); + timer2->enableTimer(std::chrono::milliseconds(3)); + timer1->enableTimer(std::chrono::milliseconds(4)); + + // Advance time by 5ms so timers above all trigger in the same loop iteration. + advanceLibeventTime(absl::Milliseconds(5)); + + // Expect watcher3 to trigger first because the deadlines for timers 1 and 2 was moved backwards. + InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); + EXPECT_CALL(watcher3, ready()); + EXPECT_CALL(watcher2, ready()); + EXPECT_CALL(watcher1, ready()); + dispatcher_->run(Dispatcher::RunType::Block); +} + +TEST_P(TimerImplTest, ChangeTimerForwardsToZeroBeforeRun) { + ReadyWatcher watcher1; + Event::TimerPtr timer1 = dispatcher_->createTimer([&] { watcher1.ready(); }); + + ReadyWatcher watcher2; + Event::TimerPtr timer2 = dispatcher_->createTimer([&] { watcher2.ready(); }); + + timer1->enableTimer(std::chrono::milliseconds(2)); + timer2->enableTimer(std::chrono::milliseconds(1)); + timer1->enableTimer(std::chrono::milliseconds(0)); + + // Advance time by 5ms so timers above all trigger in the same loop iteration. + advanceLibeventTime(absl::Milliseconds(5)); + + // Expect watcher1 to trigger first because timer1's deadline was moved forward. + InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); + if (activateTimersNextEventLoop()) { + EXPECT_CALL(watcher1, ready()); + EXPECT_CALL(watcher2, ready()); + } else { + // Timers execute in the wrong order. + EXPECT_CALL(watcher2, ready()); + EXPECT_CALL(watcher1, ready()); + } + dispatcher_->run(Dispatcher::RunType::NonBlock); +} + +TEST_P(TimerImplTest, ChangeTimerForwardsToNonZeroBeforeRun) { + ReadyWatcher watcher1; + Event::TimerPtr timer1 = dispatcher_->createTimer([&] { watcher1.ready(); }); + + ReadyWatcher watcher2; + Event::TimerPtr timer2 = dispatcher_->createTimer([&] { watcher2.ready(); }); + + timer1->enableTimer(std::chrono::milliseconds(3)); + timer2->enableTimer(std::chrono::milliseconds(2)); + timer1->enableTimer(std::chrono::milliseconds(1)); + + // Advance time by 5ms so timers above all trigger in the same loop iteration. + advanceLibeventTime(absl::Milliseconds(5)); + + // Expect watcher1 to trigger first because timer1's deadline was moved forward. + InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); + EXPECT_CALL(watcher1, ready()); + EXPECT_CALL(watcher2, ready()); + dispatcher_->run(Dispatcher::RunType::NonBlock); +} + +TEST_P(TimerImplTest, ChangeLargeTimerForwardToZeroBeforeRun) { + ReadyWatcher watcher1; + Event::TimerPtr timer1 = dispatcher_->createTimer([&] { watcher1.ready(); }); + + ReadyWatcher watcher2; + Event::TimerPtr timer2 = dispatcher_->createTimer([&] { watcher2.ready(); }); + + timer1->enableTimer(std::chrono::seconds(2000)); + timer2->enableTimer(std::chrono::seconds(1000)); + timer1->enableTimer(std::chrono::seconds(0)); + + // Expect watcher1 to trigger because timer1's deadline was moved forward. + InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); + EXPECT_CALL(watcher1, ready()); + EXPECT_CALL(prepare_watcher_, ready()); + dispatcher_->run(Dispatcher::RunType::NonBlock); +} + +TEST_P(TimerImplTest, ChangeLargeTimerForwardToNonZeroBeforeRun) { + ReadyWatcher watcher1; + Event::TimerPtr timer1 = dispatcher_->createTimer([&] { watcher1.ready(); }); + + ReadyWatcher watcher2; + Event::TimerPtr timer2 = dispatcher_->createTimer([&] { watcher2.ready(); }); + + timer1->enableTimer(std::chrono::seconds(2000)); + timer2->enableTimer(std::chrono::seconds(1000)); + timer1->enableTimer(std::chrono::milliseconds(1)); + + // Advance time by 5ms so timers above all trigger in the same loop iteration. + advanceLibeventTime(absl::Milliseconds(5)); + + // Expect watcher1 to trigger because timer1's deadline was moved forward. + InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); + EXPECT_CALL(watcher1, ready()); + EXPECT_CALL(prepare_watcher_, ready()); + dispatcher_->run(Dispatcher::RunType::NonBlock); +} + // Timers scheduled at different times execute in order. -TEST_F(TimerImplTest, TimerOrdering) { +TEST_P(TimerImplTest, TimerOrdering) { ReadyWatcher watcher1; Event::TimerPtr timer1 = dispatcher_->createTimer([&] { watcher1.ready(); }); @@ -540,6 +679,7 @@ TEST_F(TimerImplTest, TimerOrdering) { // Expect watcher calls to happen in order since timers have different times. InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); EXPECT_CALL(watcher1, ready()); EXPECT_CALL(watcher2, ready()); EXPECT_CALL(watcher3, ready()); @@ -547,7 +687,7 @@ TEST_F(TimerImplTest, TimerOrdering) { } // Alarms that are scheduled to execute and are cancelled do not trigger. -TEST_F(TimerImplTest, TimerOrderAndDisableAlarm) { +TEST_P(TimerImplTest, TimerOrderAndDisableAlarm) { ReadyWatcher watcher3; Event::TimerPtr timer3 = dispatcher_->createTimer([&] { watcher3.ready(); }); @@ -573,6 +713,7 @@ TEST_F(TimerImplTest, TimerOrderAndDisableAlarm) { // Expect watcher calls to happen in order since timers have different times. InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); EXPECT_CALL(watcher1, ready()); EXPECT_CALL(watcher3, ready()); dispatcher_->run(Dispatcher::RunType::Block); @@ -580,7 +721,7 @@ TEST_F(TimerImplTest, TimerOrderAndDisableAlarm) { // Change the registration time for a timer that is already activated by disabling and re-enabling // the timer. Verify that execution is delayed. -TEST_F(TimerImplTest, TimerOrderDisableAndReschedule) { +TEST_P(TimerImplTest, TimerOrderDisableAndReschedule) { ReadyWatcher watcher4; Event::TimerPtr timer4 = dispatcher_->createTimer([&] { watcher4.ready(); }); @@ -615,16 +756,33 @@ TEST_F(TimerImplTest, TimerOrderDisableAndReschedule) { // timer1 is expected to run first and reschedule timers 2 and 3. timer4 should fire before // timer2 and timer3 since timer4's registration is unaffected. InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); EXPECT_CALL(watcher1, ready()); - EXPECT_CALL(watcher4, ready()); - EXPECT_CALL(watcher2, ready()); - EXPECT_CALL(watcher3, ready()); + if (activateTimersNextEventLoop()) { + EXPECT_CALL(watcher4, ready()); + // Sleep during prepare to ensure that enough time has elapsed before timer evaluation to ensure + // that timers 2 and 3 are picked up by the same loop iteration. Without the sleep the two + // timers could execute in different loop iterations. + EXPECT_CALL(prepare_watcher_, ready()).WillOnce(testing::InvokeWithoutArgs([&]() { + advanceLibeventTime(absl::Milliseconds(5)); + })); + EXPECT_CALL(watcher2, ready()); + EXPECT_CALL(watcher3, ready()); + } else { + EXPECT_CALL(watcher4, ready()); + EXPECT_CALL(watcher2, ready()); + // Sleep in prepare cb to avoid flakiness if epoll_wait returns before the timer timeout. + EXPECT_CALL(prepare_watcher_, ready()).WillOnce(testing::InvokeWithoutArgs([&]() { + advanceLibeventTime(absl::Milliseconds(5)); + })); + EXPECT_CALL(watcher3, ready()); + } dispatcher_->run(Dispatcher::RunType::Block); } // Change the registration time for a timer that is already activated by re-enabling the timer // without calling disableTimer first. -TEST_F(TimerImplTest, TimerOrderAndReschedule) { +TEST_P(TimerImplTest, TimerOrderAndReschedule) { ReadyWatcher watcher4; Event::TimerPtr timer4 = dispatcher_->createTimer([&] { watcher4.ready(); }); @@ -658,14 +816,31 @@ TEST_F(TimerImplTest, TimerOrderAndReschedule) { // no effect if the time delta is 0. Expect timers 1, 2 and 4 to execute in the original order. // Timer 3 is delayed since it is rescheduled with a non-zero delta. InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); EXPECT_CALL(watcher1, ready()); - EXPECT_CALL(watcher2, ready()); - EXPECT_CALL(watcher4, ready()); - EXPECT_CALL(watcher3, ready()); + if (activateTimersNextEventLoop()) { + EXPECT_CALL(watcher4, ready()); + // Sleep during prepare to ensure that enough time has elapsed before timer evaluation to ensure + // that timers 2 and 3 are picked up by the same loop iteration. Without the sleep the two + // timers could execute in different loop iterations. + EXPECT_CALL(prepare_watcher_, ready()).WillOnce(testing::InvokeWithoutArgs([&]() { + advanceLibeventTime(absl::Milliseconds(5)); + })); + EXPECT_CALL(watcher2, ready()); + EXPECT_CALL(watcher3, ready()); + } else { + EXPECT_CALL(watcher2, ready()); + EXPECT_CALL(watcher4, ready()); + // Sleep in prepare cb to avoid flakiness if epoll_wait returns before the timer timeout. + EXPECT_CALL(prepare_watcher_, ready()).WillOnce(testing::InvokeWithoutArgs([&]() { + advanceLibeventTime(absl::Milliseconds(5)); + })); + EXPECT_CALL(watcher3, ready()); + } dispatcher_->run(Dispatcher::RunType::Block); } -TEST_F(TimerImplTest, TimerChaining) { +TEST_P(TimerImplTest, TimerChaining) { ReadyWatcher watcher1; Event::TimerPtr timer1 = dispatcher_->createTimer([&] { watcher1.ready(); }); @@ -693,9 +868,20 @@ TEST_F(TimerImplTest, TimerChaining) { EXPECT_FALSE(timer2->enabled()); EXPECT_FALSE(timer3->enabled()); EXPECT_TRUE(timer4->enabled()); + InSequence s; + EXPECT_CALL(prepare_watcher_, ready()); EXPECT_CALL(watcher4, ready()); + if (activateTimersNextEventLoop()) { + EXPECT_CALL(prepare_watcher_, ready()); + } EXPECT_CALL(watcher3, ready()); + if (activateTimersNextEventLoop()) { + EXPECT_CALL(prepare_watcher_, ready()); + } EXPECT_CALL(watcher2, ready()); + if (activateTimersNextEventLoop()) { + EXPECT_CALL(prepare_watcher_, ready()); + } EXPECT_CALL(watcher1, ready()); dispatcher_->run(Dispatcher::RunType::NonBlock); @@ -705,7 +891,7 @@ TEST_F(TimerImplTest, TimerChaining) { EXPECT_FALSE(timer4->enabled()); } -TEST_F(TimerImplTest, TimerChainDisable) { +TEST_P(TimerImplTest, TimerChainDisable) { ReadyWatcher watcher; Event::TimerPtr timer1; Event::TimerPtr timer2; @@ -729,12 +915,14 @@ TEST_F(TimerImplTest, TimerChainDisable) { EXPECT_TRUE(timer1->enabled()); EXPECT_TRUE(timer2->enabled()); EXPECT_TRUE(timer3->enabled()); + InSequence s; // Only 1 call to watcher ready since the other 2 timers were disabled by the first timer. + EXPECT_CALL(prepare_watcher_, ready()); EXPECT_CALL(watcher, ready()); dispatcher_->run(Dispatcher::RunType::NonBlock); } -TEST_F(TimerImplTest, TimerChainDelete) { +TEST_P(TimerImplTest, TimerChainDelete) { ReadyWatcher watcher; Event::TimerPtr timer1; Event::TimerPtr timer2; @@ -758,7 +946,9 @@ TEST_F(TimerImplTest, TimerChainDelete) { EXPECT_TRUE(timer1->enabled()); EXPECT_TRUE(timer2->enabled()); EXPECT_TRUE(timer3->enabled()); + InSequence s; // Only 1 call to watcher ready since the other 2 timers were deleted by the first timer. + EXPECT_CALL(prepare_watcher_, ready()); EXPECT_CALL(watcher, ready()); dispatcher_->run(Dispatcher::RunType::NonBlock); } @@ -771,6 +961,13 @@ class TimerImplTimingTest : public testing::Test { EXPECT_TRUE(timer.enabled()); while (true) { dispatcher.run(Dispatcher::RunType::NonBlock); +#ifdef WIN32 + // The event loop runs for a single iteration in NonBlock mode on Windows. A few iterations + // are required to ensure that next iteration callbacks have a chance to run before time + // advances once again. + dispatcher.run(Dispatcher::RunType::NonBlock); + dispatcher.run(Dispatcher::RunType::NonBlock); +#endif if (timer.enabled()) { time_system.advanceTimeAsync(std::chrono::microseconds(1)); } else { diff --git a/test/test_common/BUILD b/test/test_common/BUILD index b01ceabe8925..7b0a5c972382 100644 --- a/test/test_common/BUILD +++ b/test/test_common/BUILD @@ -283,6 +283,7 @@ envoy_cc_test( ":utility_lib", "//source/common/event:libevent_scheduler_lib", "//test/mocks/event:event_mocks", + "//test/test_common:test_runtime_lib", ], ) diff --git a/test/test_common/simulated_time_system.cc b/test/test_common/simulated_time_system.cc index d50560a1e3af..d361beddf471 100644 --- a/test/test_common/simulated_time_system.cc +++ b/test/test_common/simulated_time_system.cc @@ -8,6 +8,7 @@ #include "common/common/lock_guard.h" #include "common/event/real_time_system.h" #include "common/event/timer_impl.h" +#include "common/runtime/runtime_features.h" namespace Envoy { namespace Event { @@ -50,9 +51,11 @@ class UnlockGuard { // mechanism used in RealTimeSystem timers is employed for simulated alarms. class SimulatedTimeSystemHelper::Alarm : public Timer { public: - Alarm(SimulatedTimeSystemHelper& time_system, CallbackScheduler& cb_scheduler, TimerCb cb) + Alarm(SimulatedScheduler& simulated_scheduler, SimulatedTimeSystemHelper& time_system, + CallbackScheduler& cb_scheduler, TimerCb cb) : cb_(cb_scheduler.createSchedulableCallback([this, cb] { runAlarm(cb); })), - time_system_(time_system), armed_(false), pending_(false) {} + simulated_scheduler_(simulated_scheduler), time_system_(time_system), armed_(false), + pending_(false) {} ~Alarm() override; @@ -108,6 +111,7 @@ class SimulatedTimeSystemHelper::Alarm : public Timer { } SchedulableCallbackPtr cb_; + SimulatedScheduler& simulated_scheduler_; SimulatedTimeSystemHelper& time_system_; bool armed_ ABSL_GUARDED_BY(time_system_.mutex_); bool pending_ ABSL_GUARDED_BY(time_system_.mutex_); @@ -120,14 +124,19 @@ class SimulatedTimeSystemHelper::Alarm : public Timer { class SimulatedTimeSystemHelper::SimulatedScheduler : public Scheduler { public: SimulatedScheduler(SimulatedTimeSystemHelper& time_system, CallbackScheduler& cb_scheduler) - : time_system_(time_system), cb_scheduler_(cb_scheduler) {} + : time_system_(time_system), cb_scheduler_(cb_scheduler), + schedule_ready_alarms_cb_(cb_scheduler.createSchedulableCallback( + [this] { time_system_.scheduleReadyAlarms(); })) {} TimerPtr createTimer(const TimerCb& cb, Dispatcher& /*dispatcher*/) override { - return std::make_unique(time_system_, cb_scheduler_, cb); + return std::make_unique(*this, time_system_, cb_scheduler_, + cb); }; + void scheduleReadyAlarms() { schedule_ready_alarms_cb_->scheduleCallbackNextIteration(); } private: SimulatedTimeSystemHelper& time_system_; CallbackScheduler& cb_scheduler_; + SchedulableCallbackPtr schedule_ready_alarms_cb_; }; SimulatedTimeSystemHelper::Alarm::Alarm::~Alarm() { @@ -168,10 +177,11 @@ void SimulatedTimeSystemHelper::Alarm::Alarm::enableHRTimer( } armed_ = true; - if (duration.count() == 0) { + if (duration.count() == 0 && !Runtime::runtimeFeatureEnabled( + "envoy.reloadable_features.activate_timers_next_event_loop")) { activateLockHeld(); } else { - time_system_.addAlarmLockHeld(*this, duration); + time_system_.addAlarmLockHeld(*this, duration, simulated_scheduler_); } } @@ -287,7 +297,8 @@ void SimulatedTimeSystemHelper::alarmActivateLockHeld(Alarm& alarm) ABSL_NO_THRE } void SimulatedTimeSystemHelper::addAlarmLockHeld( - Alarm& alarm, const std::chrono::microseconds& duration) ABSL_NO_THREAD_SAFETY_ANALYSIS { + Alarm& alarm, const std::chrono::microseconds& duration, + SimulatedScheduler& simulated_scheduler) ABSL_NO_THREAD_SAFETY_ANALYSIS { ASSERT(&(alarm.timeSystem()) == this); ASSERT(alarms_.size() == alarm_registrations_map_.size()); ASSERT(alarm_registrations_map_.find(&alarm) == alarm_registrations_map_.end()); @@ -295,6 +306,18 @@ void SimulatedTimeSystemHelper::addAlarmLockHeld( auto insert_result = alarms_.insert({monotonic_time_ + duration, random_source_.random(), alarm}); ASSERT(insert_result.second); alarm_registrations_map_.emplace(&alarm, insert_result.first); + if (duration.count() == 0) { + // Force the event loop to check for timers that are ready to execute since we just added an 0 + // delay alarm which is ready to execution in the next iteration of the event loop. + // TODO(antoniovicente) Refactor alarm tracking so it happens per scheduler and limit wakeup to + // a single event loop. + + // We don't want to activate the alarm under lock, as it will make a libevent call, and libevent + // itself uses locks: + // https://github.com/libevent/libevent/blob/29cc8386a2f7911eaa9336692a2c5544d8b4734f/event.c#L1917 + UnlockGuard unlocker(mutex_); + simulated_scheduler.scheduleReadyAlarms(); + } // Sanity check that the parallel data structures used for alarm registration have the same number // of entries. @@ -320,33 +343,40 @@ SchedulerPtr SimulatedTimeSystemHelper::createScheduler(Scheduler& /*base_schedu } void SimulatedTimeSystemHelper::setMonotonicTimeLockHeld(const MonotonicTime& monotonic_time) { + only_one_thread_.checkOneThread(); // We don't have a MutexLock construct that allows temporarily // dropping the lock to run a callback. The main issue here is that we must // be careful not to be holding mutex_ when an exception can be thrown. // That can only happen here in alarm->activate(), which is run with the mutex // released. if (monotonic_time >= monotonic_time_) { - // Alarms is a std::set ordered by wakeup time, so pulling off begin() each - // iteration gives you wakeup order. Also note that alarms may be added - // or removed during the call to activate() so it would not be correct to - // range-iterate over the set. - while (!alarms_.empty()) { - const AlarmRegistration& alarm_registration = *alarms_.begin(); - MonotonicTime alarm_time = alarm_registration.time_; - if (alarm_time > monotonic_time) { - break; - } - ASSERT(alarm_time >= monotonic_time_); - system_time_ += - std::chrono::duration_cast(alarm_time - monotonic_time_); - monotonic_time_ = alarm_time; - Alarm& alarm = alarm_registration.alarm_; - removeAlarmLockHeld(alarm); - alarmActivateLockHeld(alarm); - } system_time_ += std::chrono::duration_cast(monotonic_time - monotonic_time_); monotonic_time_ = monotonic_time; + scheduleReadyAlarmsLockHeld(); + } +} + +void SimulatedTimeSystemHelper::scheduleReadyAlarms() { + absl::MutexLock lock(&mutex_); + scheduleReadyAlarmsLockHeld(); +} + +void SimulatedTimeSystemHelper::scheduleReadyAlarmsLockHeld() { + // Alarms is a std::set ordered by wakeup time, so pulling off begin() each + // iteration gives you wakeup order. Also note that alarms may be added + // or removed during the call to activate() so it would not be correct to + // range-iterate over the set. + while (!alarms_.empty()) { + const AlarmRegistration& alarm_registration = *alarms_.begin(); + MonotonicTime alarm_time = alarm_registration.time_; + if (alarm_time > monotonic_time_) { + break; + } + + Alarm& alarm = alarm_registration.alarm_; + removeAlarmLockHeld(alarm); + alarmActivateLockHeld(alarm); } } diff --git a/test/test_common/simulated_time_system.h b/test/test_common/simulated_time_system.h index 3b4c938d0e9e..e8a369e4f9cc 100644 --- a/test/test_common/simulated_time_system.h +++ b/test/test_common/simulated_time_system.h @@ -104,10 +104,17 @@ class SimulatedTimeSystemHelper : public TestTimeSystem { void setMonotonicTimeLockHeld(const MonotonicTime& monotonic_time) ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex_); + /** + * Schedule expired alarms so they execute in their event loops. + */ + void scheduleReadyAlarms(); + void scheduleReadyAlarmsLockHeld() ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex_); + void alarmActivateLockHeld(Alarm& alarm) ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex_); // Adds/removes an alarm. - void addAlarmLockHeld(Alarm&, const std::chrono::microseconds& duration) + void addAlarmLockHeld(Alarm&, const std::chrono::microseconds& duration, + SimulatedScheduler& simulated_scheduler) ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex_); void removeAlarmLockHeld(Alarm&) ABSL_EXCLUSIVE_LOCKS_REQUIRED(mutex_); diff --git a/test/test_common/simulated_time_system_test.cc b/test/test_common/simulated_time_system_test.cc index 9fd5314c9b92..13a435148aff 100644 --- a/test/test_common/simulated_time_system_test.cc +++ b/test/test_common/simulated_time_system_test.cc @@ -6,6 +6,7 @@ #include "test/mocks/common.h" #include "test/mocks/event/mocks.h" #include "test/test_common/simulated_time_system.h" +#include "test/test_common/test_runtime.h" #include "test/test_common/utility.h" #include "event2/event.h" @@ -16,12 +17,20 @@ namespace Event { namespace Test { namespace { -class SimulatedTimeSystemTest : public testing::Test { +enum class ActivateMode { DelayActivateTimers, EagerlyActivateTimers }; + +class SimulatedTimeSystemTest : public testing::TestWithParam { protected: SimulatedTimeSystemTest() : scheduler_(time_system_.createScheduler(base_scheduler_, base_scheduler_)), start_monotonic_time_(time_system_.monotonicTime()), - start_system_time_(time_system_.systemTime()) {} + start_system_time_(time_system_.systemTime()) { + Runtime::LoaderSingleton::getExisting()->mergeValues( + {{"envoy.reloadable_features.activate_timers_next_event_loop", + activateMode() == ActivateMode::DelayActivateTimers ? "true" : "false"}}); + } + + ActivateMode activateMode() { return GetParam(); } void trackPrepareCalls() { base_scheduler_.registerOnPrepareCallback([this]() { output_.append(1, 'p'); }); @@ -58,6 +67,7 @@ class SimulatedTimeSystemTest : public testing::Test { base_scheduler_.run(Dispatcher::RunType::NonBlock); } + TestScopedRuntime scoped_runtime_; Event::MockDispatcher dispatcher_; LibeventScheduler base_scheduler_; SimulatedTimeSystem time_system_; @@ -68,7 +78,11 @@ class SimulatedTimeSystemTest : public testing::Test { SystemTime start_system_time_; }; -TEST_F(SimulatedTimeSystemTest, AdvanceTimeAsync) { +INSTANTIATE_TEST_SUITE_P(DelayTimerActivation, SimulatedTimeSystemTest, + testing::Values(ActivateMode::DelayActivateTimers, + ActivateMode::EagerlyActivateTimers)); + +TEST_P(SimulatedTimeSystemTest, AdvanceTimeAsync) { EXPECT_EQ(start_monotonic_time_, time_system_.monotonicTime()); EXPECT_EQ(start_system_time_, time_system_.systemTime()); advanceMsAndLoop(5); @@ -76,7 +90,7 @@ TEST_F(SimulatedTimeSystemTest, AdvanceTimeAsync) { EXPECT_EQ(start_system_time_ + std::chrono::milliseconds(5), time_system_.systemTime()); } -TEST_F(SimulatedTimeSystemTest, TimerTotalOrdering) { +TEST_P(SimulatedTimeSystemTest, TimerTotalOrdering) { trackPrepareCalls(); addTask(0, '0'); @@ -90,7 +104,7 @@ TEST_F(SimulatedTimeSystemTest, TimerTotalOrdering) { EXPECT_EQ("p012", output_); } -TEST_F(SimulatedTimeSystemTest, TimerPartialOrdering) { +TEST_P(SimulatedTimeSystemTest, TimerPartialOrdering) { trackPrepareCalls(); std::set outputs; @@ -115,7 +129,7 @@ TEST_F(SimulatedTimeSystemTest, TimerPartialOrdering) { EXPECT_THAT(outputs, testing::ElementsAre("p0123", "p0213")); } -TEST_F(SimulatedTimeSystemTest, TimerPartialOrdering2) { +TEST_P(SimulatedTimeSystemTest, TimerPartialOrdering2) { trackPrepareCalls(); std::set outputs; @@ -142,7 +156,7 @@ TEST_F(SimulatedTimeSystemTest, TimerPartialOrdering2) { } // Timers that are scheduled to execute and but are disabled first do not trigger. -TEST_F(SimulatedTimeSystemTest, TimerOrderAndDisableTimer) { +TEST_P(SimulatedTimeSystemTest, TimerOrderAndDisableTimer) { trackPrepareCalls(); // Create 3 timers. The first timer should disable the second, so it doesn't trigger. @@ -159,7 +173,7 @@ TEST_F(SimulatedTimeSystemTest, TimerOrderAndDisableTimer) { } // Capture behavior of timers which are rescheduled without being disabled first. -TEST_F(SimulatedTimeSystemTest, TimerOrderAndRescheduleTimer) { +TEST_P(SimulatedTimeSystemTest, TimerOrderAndRescheduleTimer) { trackPrepareCalls(); // Reschedule timers 1, 2 and 4 without disabling first. @@ -179,15 +193,34 @@ TEST_F(SimulatedTimeSystemTest, TimerOrderAndRescheduleTimer) { // Timer 4 runs as part of the first wakeup since its new schedule time has a delta of 0. Timer 2 // is delayed since it is rescheduled with a non-zero delta. advanceMsAndLoop(5); - EXPECT_EQ("p0134", output_); + if (activateMode() == ActivateMode::DelayActivateTimers) { +#ifdef WIN32 + // Force it to run again to pick up next iteration callbacks. + // The event loop runs for a single iteration in NonBlock mode on Windows as a hack to work + // around LEVEL trigger fd registrations constantly firing events and preventing the NonBlock + // event loop from ever reaching the no-fd event and no-expired timers termination condition. It + // is not possible to get consistent event loop behavior since the time system does not override + // the base scheduler's run behavior, and libevent does not provide a mode where it runs at most + // N iterations before breaking out of the loop for us to prefer over the single iteration mode + // used on Windows. + advanceMsAndLoop(0); +#endif + EXPECT_EQ("p013p4", output_); + } else { + EXPECT_EQ("p0134", output_); + } advanceMsAndLoop(100); - EXPECT_EQ("p0134p2", output_); + if (activateMode() == ActivateMode::DelayActivateTimers) { + EXPECT_EQ("p013p4p2", output_); + } else { + EXPECT_EQ("p0134p2", output_); + } } // Disable and re-enable timers that is already pending execution and verify that execution is // delayed. -TEST_F(SimulatedTimeSystemTest, TimerOrderDisableAndRescheduleTimer) { +TEST_P(SimulatedTimeSystemTest, TimerOrderDisableAndRescheduleTimer) { trackPrepareCalls(); // Disable and reschedule timers 1, 2 and 4 when timer 0 triggers. @@ -210,13 +243,26 @@ TEST_F(SimulatedTimeSystemTest, TimerOrderDisableAndRescheduleTimer) { // because it is scheduled with zero delay. Timer 2 executes in a later iteration because it is // re-enabled with a non-zero timeout. advanceMsAndLoop(5); - EXPECT_EQ("p0314", output_); + if (activateMode() == ActivateMode::DelayActivateTimers) { +#ifdef WIN32 + // The event loop runs for a single iteration in NonBlock mode on Windows. Force it to run again + // to pick up next iteration callbacks. + advanceMsAndLoop(0); +#endif + EXPECT_THAT(output_, testing::AnyOf("p03p14", "p03p41")); + } else { + EXPECT_EQ("p0314", output_); + } advanceMsAndLoop(100); - EXPECT_EQ("p0314p2", output_); + if (activateMode() == ActivateMode::DelayActivateTimers) { + EXPECT_THAT(output_, testing::AnyOf("p03p14p2", "p03p41p2")); + } else { + EXPECT_EQ("p0314p2", output_); + } } -TEST_F(SimulatedTimeSystemTest, AdvanceTimeWait) { +TEST_P(SimulatedTimeSystemTest, AdvanceTimeWait) { EXPECT_EQ(start_monotonic_time_, time_system_.monotonicTime()); EXPECT_EQ(start_system_time_, time_system_.systemTime()); @@ -238,7 +284,7 @@ TEST_F(SimulatedTimeSystemTest, AdvanceTimeWait) { EXPECT_EQ(start_system_time_ + std::chrono::milliseconds(5), time_system_.systemTime()); } -TEST_F(SimulatedTimeSystemTest, WaitFor) { +TEST_P(SimulatedTimeSystemTest, WaitFor) { EXPECT_EQ(start_monotonic_time_, time_system_.monotonicTime()); EXPECT_EQ(start_system_time_, time_system_.systemTime()); @@ -299,7 +345,7 @@ TEST_F(SimulatedTimeSystemTest, WaitFor) { thread->join(); } -TEST_F(SimulatedTimeSystemTest, Monotonic) { +TEST_P(SimulatedTimeSystemTest, Monotonic) { // Setting time forward works. time_system_.setMonotonicTime(start_monotonic_time_ + std::chrono::milliseconds(5)); EXPECT_EQ(start_monotonic_time_ + std::chrono::milliseconds(5), time_system_.monotonicTime()); @@ -309,7 +355,7 @@ TEST_F(SimulatedTimeSystemTest, Monotonic) { EXPECT_EQ(start_monotonic_time_ + std::chrono::milliseconds(5), time_system_.monotonicTime()); } -TEST_F(SimulatedTimeSystemTest, System) { +TEST_P(SimulatedTimeSystemTest, System) { // Setting time forward works. time_system_.setSystemTime(start_system_time_ + std::chrono::milliseconds(5)); EXPECT_EQ(start_system_time_ + std::chrono::milliseconds(5), time_system_.systemTime()); @@ -319,7 +365,7 @@ TEST_F(SimulatedTimeSystemTest, System) { EXPECT_EQ(start_system_time_ + std::chrono::milliseconds(3), time_system_.systemTime()); } -TEST_F(SimulatedTimeSystemTest, Ordering) { +TEST_P(SimulatedTimeSystemTest, Ordering) { addTask(5, '5'); addTask(3, '3'); addTask(6, '6'); @@ -330,7 +376,7 @@ TEST_F(SimulatedTimeSystemTest, Ordering) { EXPECT_EQ("356", output_); } -TEST_F(SimulatedTimeSystemTest, SystemTimeOrdering) { +TEST_P(SimulatedTimeSystemTest, SystemTimeOrdering) { addTask(5, '5'); addTask(3, '3'); addTask(6, '6'); @@ -344,7 +390,7 @@ TEST_F(SimulatedTimeSystemTest, SystemTimeOrdering) { EXPECT_EQ("356", output_); // callbacks don't get replayed. } -TEST_F(SimulatedTimeSystemTest, DisableTimer) { +TEST_P(SimulatedTimeSystemTest, DisableTimer) { addTask(5, '5'); addTask(3, '3'); addTask(6, '6'); @@ -356,7 +402,7 @@ TEST_F(SimulatedTimeSystemTest, DisableTimer) { EXPECT_EQ("36", output_); } -TEST_F(SimulatedTimeSystemTest, IgnoreRedundantDisable) { +TEST_P(SimulatedTimeSystemTest, IgnoreRedundantDisable) { addTask(5, '5'); timers_[0]->disableTimer(); timers_[0]->disableTimer(); @@ -364,7 +410,7 @@ TEST_F(SimulatedTimeSystemTest, IgnoreRedundantDisable) { EXPECT_EQ("", output_); } -TEST_F(SimulatedTimeSystemTest, OverrideEnable) { +TEST_P(SimulatedTimeSystemTest, OverrideEnable) { addTask(5, '5'); timers_[0]->enableTimer(std::chrono::milliseconds(6)); advanceMsAndLoop(5); @@ -373,7 +419,7 @@ TEST_F(SimulatedTimeSystemTest, OverrideEnable) { EXPECT_EQ("5", output_); } -TEST_F(SimulatedTimeSystemTest, DeleteTime) { +TEST_P(SimulatedTimeSystemTest, DeleteTime) { addTask(5, '5'); addTask(3, '3'); addTask(6, '6'); @@ -386,7 +432,7 @@ TEST_F(SimulatedTimeSystemTest, DeleteTime) { } // Regression test for issues documented in https://github.com/envoyproxy/envoy/pull/6956 -TEST_F(SimulatedTimeSystemTest, DuplicateTimer) { +TEST_P(SimulatedTimeSystemTest, DuplicateTimer) { // Set one alarm two times to test that pending does not get duplicated.. std::chrono::milliseconds delay(0); TimerPtr zero_timer = scheduler_->createTimer([this]() { output_.append(1, '2'); }, dispatcher_); @@ -422,7 +468,7 @@ TEST_F(SimulatedTimeSystemTest, DuplicateTimer) { thread->join(); } -TEST_F(SimulatedTimeSystemTest, Enabled) { +TEST_P(SimulatedTimeSystemTest, Enabled) { TimerPtr timer = scheduler_->createTimer({}, dispatcher_); timer->enableTimer(std::chrono::milliseconds(0)); EXPECT_TRUE(timer->enabled());