watchdog: Touch Watchdog before executing most event loop callbacks to avoid spurious misses when there are many queued callbacks. (envoyproxy#13104)

This change assumes that the primary purposes of the watchdog is to terminate the proxy if worker threads are deadlocked, and aid in the debugging of long-running operations that end up scheduled in worker threads through monitoring for miss/megamiss events and auxiliary watchdog actions like the recently added watchdog profile action.

Signed-off-by: Antonio Vicente <[email protected]>

Author: antoniovicente

docs/root/version_history/current.rst

@@ -29,6 +29,7 @@ Bug Fixes
 * http: sending CONNECT_ERROR for HTTP/2 where appropriate during CONNECT requests.
 * proxy_proto: fixed a bug where the wrong downstream address got sent to upstream connections.
 * tls: fix read resumption after triggering buffer high-watermark and all remaining request/response bytes are stored in the SSL connection's internal buffers.
+* watchdog: touch the watchdog before most event loop operations to avoid misses when handling bursts of callbacks.
 
 Removed Config or Runtime
 -------------------------

include/envoy/event/BUILD

@@ -31,6 +31,7 @@ envoy_cc_library(
         "//include/envoy/network:listen_socket_interface",
         "//include/envoy/network:listener_interface",
         "//include/envoy/network:transport_socket_interface",
+        "//include/envoy/server:watchdog_interface",
         "//include/envoy/thread:thread_interface",
     ],
 )

include/envoy/event/dispatcher.h

@@ -19,6 +19,7 @@
 #include "envoy/network/listen_socket.h"
 #include "envoy/network/listener.h"
 #include "envoy/network/transport_socket.h"
+#include "envoy/server/watchdog.h"
 #include "envoy/stats/scope.h"
 #include "envoy/stats/stats_macros.h"
 #include "envoy/stream_info/stream_info.h"
@@ -63,6 +64,15 @@ class Dispatcher {
    */
   virtual const std::string& name() PURE;
 
+  /**
+   * Register a watchdog for this dispatcher. The dispatcher is responsible for touching the
+   * watchdog at least once per touch interval. Dispatcher implementations may choose to touch more
+   * often to avoid spurious miss events when processing long callback queues.
+   * @param min_touch_interval Touch interval for the watchdog.
+   */
+  virtual void registerWatchdog(const Server::WatchDogSharedPtr& watchdog,
+                                std::chrono::milliseconds min_touch_interval) PURE;
+
   /**
    * Returns a time-source to use with this dispatcher.
    */

include/envoy/server/BUILD

@@ -68,6 +68,7 @@ envoy_cc_library(
     name = "guarddog_interface",
     hdrs = ["guarddog.h"],
     deps = [
+        "//include/envoy/event:dispatcher_interface",
         "//include/envoy/server:watchdog_interface",
         "//include/envoy/stats:stats_interface",
         "//include/envoy/thread:thread_interface",
@@ -159,8 +160,6 @@ envoy_cc_library(
     name = "watchdog_interface",
     hdrs = ["watchdog.h"],
     deps = [
-        "//include/envoy/event:dispatcher_interface",
-        "//include/envoy/network:address_interface",
         "//include/envoy/thread:thread_interface",
     ],
 )

include/envoy/server/guarddog.h

@@ -1,6 +1,7 @@
 #pragma once
 
 #include "envoy/common/pure.h"
+#include "envoy/event/dispatcher.h"
 #include "envoy/server/watchdog.h"
 
 namespace Envoy {
@@ -28,9 +29,11 @@ class GuardDog {
    *
    * @param thread_id a Thread::ThreadId containing the system thread id
    * @param thread_name supplies the name of the thread which is used for per-thread miss stats.
+   * @param dispatcher dispatcher responsible for petting the watchdog.
    */
   virtual WatchDogSharedPtr createWatchDog(Thread::ThreadId thread_id,
-                                           const std::string& thread_name) PURE;
+                                           const std::string& thread_name,
+                                           Event::Dispatcher& dispatcher) PURE;
 
   /**
    * Tell the GuardDog to forget about this WatchDog.

include/envoy/server/watchdog.h

@@ -3,7 +3,6 @@
 #include <memory>
 
 #include "envoy/common/pure.h"
-#include "envoy/event/dispatcher.h"
 #include "envoy/thread/thread.h"
 
 namespace Envoy {
@@ -19,21 +18,12 @@ class WatchDog {
 public:
   virtual ~WatchDog() = default;
 
-  /**
-   * Start a recurring touch timer in the dispatcher passed as argument.
-   *
-   * This will automatically call the touch() method at the interval specified
-   * during construction.
-   *
-   * The timer object is stored within the WatchDog object. It will go away if
-   * the object goes out of scope and stop the timer.
-   */
-  virtual void startWatchdog(Event::Dispatcher& dispatcher) PURE;
-
   /**
    * Manually indicate that you are still alive by calling this.
    *
-   * This can be used if this is later used on a thread where there is no dispatcher.
+   * When the watchdog is registered with a dispatcher, the dispatcher will periodically call this
+   * method to indicate the thread is still alive. It should be called directly by the application
+   * code in cases where the watchdog is not registered with a dispatcher.
    */
   virtual void touch() PURE;
   virtual Thread::ThreadId threadId() const PURE;

source/common/event/dispatcher_impl.cc

@@ -58,6 +58,13 @@ DispatcherImpl::DispatcherImpl(const std::string& name, Buffer::WatermarkFactory
 
 DispatcherImpl::~DispatcherImpl() { FatalErrorHandler::removeFatalErrorHandler(*this); }
 
+void DispatcherImpl::registerWatchdog(const Server::WatchDogSharedPtr& watchdog,
+                                      std::chrono::milliseconds min_touch_interval) {
+  ASSERT(!watchdog_registration_, "Each dispatcher can have at most one registered watchdog.");
+  watchdog_registration_ =
+      std::make_unique<WatchdogRegistration>(watchdog, *scheduler_, min_touch_interval, *this);
+}
+
 void DispatcherImpl::initializeStats(Stats::Scope& scope,
                                      const absl::optional<std::string>& prefix) {
   const std::string effective_prefix = prefix.has_value() ? *prefix : absl::StrCat(name_, ".");
@@ -150,7 +157,13 @@ Network::DnsResolverSharedPtr DispatcherImpl::createDnsResolver(
 FileEventPtr DispatcherImpl::createFileEvent(os_fd_t fd, FileReadyCb cb, FileTriggerType trigger,
                                              uint32_t events) {
   ASSERT(isThreadSafe());
-  return FileEventPtr{new FileEventImpl(*this, fd, cb, trigger, events)};
+  return FileEventPtr{new FileEventImpl(
+      *this, fd,
+      [this, cb](uint32_t events) {
+        touchWatchdog();
+        cb(events);
+      },
+      trigger, events)};
 }
 
 Filesystem::WatcherPtr DispatcherImpl::createFilesystemWatcher() {
@@ -179,11 +192,19 @@ TimerPtr DispatcherImpl::createTimer(TimerCb cb) {
 
 Event::SchedulableCallbackPtr DispatcherImpl::createSchedulableCallback(std::function<void()> cb) {
   ASSERT(isThreadSafe());
-  return base_scheduler_.createSchedulableCallback(cb);
+  return base_scheduler_.createSchedulableCallback([this, cb]() {
+    touchWatchdog();
+    cb();
+  });
 }
 
 TimerPtr DispatcherImpl::createTimerInternal(TimerCb cb) {
-  return scheduler_->createTimer(cb, *this);
+  return scheduler_->createTimer(
+      [this, cb]() {
+        touchWatchdog();
+        cb();
+      },
+      *this);
 }
 
 void DispatcherImpl::deferredDelete(DeferredDeletablePtr&& to_delete) {
@@ -257,5 +278,11 @@ void DispatcherImpl::runPostCallbacks() {
   }
 }
 
+void DispatcherImpl::touchWatchdog() {
+  if (watchdog_registration_) {
+    watchdog_registration_->touchWatchdog();
+  }
+}
+
 } // namespace Event
 } // namespace Envoy

source/common/event/dispatcher_impl.h

@@ -42,6 +42,8 @@ class DispatcherImpl : Logger::Loggable<Logger::Id::main>,
 
   // Event::Dispatcher
   const std::string& name() override { return name_; }
+  void registerWatchdog(const Server::WatchDogSharedPtr& watchdog,
+                        std::chrono::milliseconds min_touch_interval) override;
   TimeSource& timeSource() override { return api_.timeSource(); }
   void initializeStats(Stats::Scope& scope, const absl::optional<std::string>& prefix) override;
   void clearDeferredDeleteList() override;
@@ -93,9 +95,36 @@ class DispatcherImpl : Logger::Loggable<Logger::Id::main>,
   }
 
 private:
+  // Holds a reference to the watchdog registered with this dispatcher and the timer used to ensure
+  // that the dog is touched periodically.
+  class WatchdogRegistration {
+  public:
+    WatchdogRegistration(const Server::WatchDogSharedPtr& watchdog, Scheduler& scheduler,
+                         std::chrono::milliseconds timer_interval, Dispatcher& dispatcher)
+        : watchdog_(watchdog), timer_interval_(timer_interval) {
+      touch_timer_ = scheduler.createTimer(
+          [this]() -> void {
+            watchdog_->touch();
+            touch_timer_->enableTimer(timer_interval_);
+          },
+          dispatcher);
+      touch_timer_->enableTimer(timer_interval_);
+    }
+
+    void touchWatchdog() { watchdog_->touch(); }
+
+  private:
+    Server::WatchDogSharedPtr watchdog_;
+    const std::chrono::milliseconds timer_interval_;
+    TimerPtr touch_timer_;
+  };
+  using WatchdogRegistrationPtr = std::unique_ptr<WatchdogRegistration>;
+
   TimerPtr createTimerInternal(TimerCb cb);
   void updateApproximateMonotonicTimeInternal();
   void runPostCallbacks();
+  // Helper used to touch the watchdog after most schedulable, fd, and timer callbacks.
+  void touchWatchdog();
 
   // Validate that an operation is thread safe, i.e. it's invoked on the same thread that the
   // dispatcher run loop is executing on. We allow run_tid_ to be empty for tests where we don't
@@ -122,6 +151,7 @@ class DispatcherImpl : Logger::Loggable<Logger::Id::main>,
   const ScopeTrackedObject* current_object_{};
   bool deferred_deleting_{};
   MonotonicTime approximate_monotonic_time_;
+  WatchdogRegistrationPtr watchdog_registration_;
 };
 
 } // namespace Event

source/server/BUILD

@@ -113,6 +113,7 @@ envoy_cc_library(
         ":watchdog_lib",
         "//include/envoy/api:api_interface",
         "//include/envoy/common:time_interface",
+        "//include/envoy/event:dispatcher_interface",
         "//include/envoy/event:timer_interface",
         "//include/envoy/server:configuration_interface",
         "//include/envoy/server:guarddog_config_interface",
@@ -473,11 +474,9 @@ envoy_cc_library(
 
 envoy_cc_library(
     name = "watchdog_lib",
-    srcs = ["watchdog_impl.cc"],
     hdrs = ["watchdog_impl.h"],
     deps = [
         "//include/envoy/common:time_interface",
-        "//include/envoy/event:dispatcher_interface",
         "//include/envoy/server:watchdog_interface",
         "//source/common/common:assert_lib",
     ],

source/server/guarddog_impl.cc

@@ -185,19 +185,22 @@ void GuardDogImpl::step() {
 }
 
 WatchDogSharedPtr GuardDogImpl::createWatchDog(Thread::ThreadId thread_id,
-                                               const std::string& thread_name) {
+                                               const std::string& thread_name,
+                                               Event::Dispatcher& dispatcher) {
   // Timer started by WatchDog will try to fire at 1/2 of the interval of the
   // minimum timeout specified. loop_interval_ is const so all shared state
   // accessed out of the locked section below is const (time_source_ has no
   // state).
   const auto wd_interval = loop_interval_ / 2;
-  auto new_watchdog = std::make_shared<WatchDogImpl>(std::move(thread_id), wd_interval);
+  auto new_watchdog = std::make_shared<WatchDogImpl>(std::move(thread_id));
   WatchedDogPtr watched_dog = std::make_unique<WatchedDog>(stats_scope_, thread_name, new_watchdog);
   new_watchdog->touch();
   {
     Thread::LockGuard guard(wd_lock_);
     watched_dogs_.push_back(std::move(watched_dog));
   }
+  dispatcher.registerWatchdog(new_watchdog, wd_interval);
+  new_watchdog->touch();
   return new_watchdog;
 }
 

source/server/guarddog_impl.h

@@ -92,8 +92,8 @@ class GuardDogImpl : public GuardDog {
   }
 
   // Server::GuardDog
-  WatchDogSharedPtr createWatchDog(Thread::ThreadId thread_id,
-                                   const std::string& thread_name) override;
+  WatchDogSharedPtr createWatchDog(Thread::ThreadId thread_id, const std::string& thread_name,
+                                   Event::Dispatcher& dispatcher) override;
   void stopWatching(WatchDogSharedPtr wd) override;
 
 private:

source/server/server.cc

@@ -682,8 +682,7 @@ void InstanceImpl::run() {
   // Run the main dispatch loop waiting to exit.
   ENVOY_LOG(info, "starting main dispatch loop");
   auto watchdog = main_thread_guard_dog_->createWatchDog(api_->threadFactory().currentThreadId(),
-                                                         "main_thread");
-  watchdog->startWatchdog(*dispatcher_);
+                                                         "main_thread", *dispatcher_);
   dispatcher_->post([this] { notifyCallbacksForStage(Stage::Startup); });
   dispatcher_->run(Event::Dispatcher::RunType::Block);
   ENVOY_LOG(info, "main dispatch loop exited");

source/server/watchdog_impl.cc

@@ -1,10 +1,7 @@
 #pragma once
 
 #include <atomic>
-#include <chrono>
 
-#include "envoy/common/time.h"
-#include "envoy/event/dispatcher.h"
 #include "envoy/server/watchdog.h"
 
 namespace Envoy {
@@ -17,17 +14,15 @@ namespace Server {
 class WatchDogImpl : public WatchDog {
 public:
   /**
-   * @param interval WatchDog timer interval (used after startWatchdog())
+   * @param thread_id ThreadId of the monitored thread
    */
-  WatchDogImpl(Thread::ThreadId thread_id, std::chrono::milliseconds interval)
-      : thread_id_(thread_id), timer_interval_(interval) {}
+  WatchDogImpl(Thread::ThreadId thread_id) : thread_id_(thread_id) {}
 
   Thread::ThreadId threadId() const override { return thread_id_; }
   // Used by GuardDogImpl determine if the watchdog was touched recently and reset the touch status.
   bool getTouchedAndReset() { return touched_.exchange(false, std::memory_order_relaxed); }
 
   // Server::WatchDog
-  void startWatchdog(Event::Dispatcher& dispatcher) override;
   void touch() override {
     // Set touched_ if not already set.
     bool expected = false;
@@ -37,8 +32,6 @@ class WatchDogImpl : public WatchDog {
 private:
   const Thread::ThreadId thread_id_;
   std::atomic<bool> touched_{false};
-  Event::TimerPtr timer_;
-  const std::chrono::milliseconds timer_interval_;
 };
 
 } // namespace Server

source/server/watchdog_impl.h

@@ -128,9 +128,8 @@ void WorkerImpl::threadRoutine(GuardDog& guard_dog) {
   // The watch dog must be created after the dispatcher starts running and has post events flushed,
   // as this is when TLS stat scopes start working.
   dispatcher_->post([this, &guard_dog]() {
-    watch_dog_ =
-        guard_dog.createWatchDog(api_.threadFactory().currentThreadId(), dispatcher_->name());
-    watch_dog_->startWatchdog(*dispatcher_);
+    watch_dog_ = guard_dog.createWatchDog(api_.threadFactory().currentThreadId(),
+                                          dispatcher_->name(), *dispatcher_);
   });
   dispatcher_->run(Event::Dispatcher::RunType::Block);
   ENVOY_LOG(debug, "worker exited dispatch loop");

source/server/worker_impl.cc

@@ -19,6 +19,7 @@ envoy_cc_test(
         "//source/common/event:dispatcher_lib",
         "//source/common/stats:isolated_store_lib",
         "//test/mocks:common_lib",
+        "//test/mocks/server:watch_dog_mocks",
         "//test/mocks/stats:stats_mocks",
         "//test/test_common:simulated_time_system_lib",
         "//test/test_common:test_runtime_lib",