dispatcher: Run zero-delay timeout timers on the next iteration of th…

…e event loop (#11823)

Processing 0-delay timers in the same loop they are generated can result in long timer callback chains which could starve other operations in the event loop or even result in infinite processing loops. Cases that required same-iteration scheduling behavior for 0-delay timers were refactored to use SchedulableCallback::scheduleCallbackCurrentIteration in #11663, so behavior changes due to this change should be relatively minor.

Signed-off-by: Antonio Vicente <avd@google.com>

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",
     ],
 )
 

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<void()>;

source/common/event/timer_impl.cc

@@ -3,14 +3,24 @@
 #include <chrono>
 
 #include "common/common/assert.h"
+#include "common/runtime/runtime_features.h"
 
 #include "event2/event.h"
 
 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);

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<const ScopeTrackedObject*> 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

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",

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<int64_t>(1), duration.ToMicroseconds())));
 }

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",
     ],
 )