BUG/MEDIUM: wdt: improve stuck task detection accuracy

The fact that the watchdog timer measures the execution time from the
last return from the poller tends to amplify the impact of multiple
bad tasks, and may explain some of the panics reported by Felipe and
Ricardo in GH issues #3084, #3092 and #3101. The problem is that we
check the time if we see that the scheduler appears not to be moving
anymore, but one situation may still arise and catch a bad task:
  - one slow task takes so long a time that it triggers the watchdog
    twice, emitting a warning the second time (~200ms). The scheduler
    is rightfully marked as stuck.
  - then it completes and the scheduler is no longer stuck. Many other
    tasks run in turn, they all take quite some time but not enough to
    trigger a warning. But collectively their cost adds up.
  - then a task takes more than the warning time (100ms), and causes
    the total execution time to cross the second. The watchdog is
    called, sees that we've spend more than 1 second since we left the
    poller, and marks the thread as stuck.
  - the task is not finished, the watchdog is called again, sees more
    than one second with a stuck thread and panics 100ms later.

The total time away from the poller is indeed more than one second,
which is very bad, but no single task caused this individually, and
while the warnings are OK, the watchdog should not panic in this case.

This patch revisits the approach to store the moment the scheduler was
marked as stuck in the wdt context. The idea is that this date will be
used to detect warnings and panics. And by doing so and exploiting the
new is_sched_alive(thr), we can greatly simplify the mechanism so that
the signal handling thread does the strict minimum (mark the scheduler
as possibly stuck and update the stuck_start date), and only bounces to
the reporting thread if the scheduler made no progress since last call.
This means that without even doing computations in the handing thread,
we can continue to avoid all bounces unless a warning is required. Then
when the reporting thread is signaled, it will check the dates from the
last moment the scheduler was marked, and will decide to warn or panic.

The panic decision continues to pass via a TH_FL_STUCK flag to probe the
code so that exceptionally slow code (e.g. live cert generation etc) can
still find a way to avoid the panic if absolutely certain that things
are still moving.

This means that now we have the guarantee that panics will only happen
if a given task spends more than one full second not moving, and that
warnings will be issued for other calls crossing the warn delay boundary.

This was tested using artificially slow operations, and all combinations
which individually took less than a second only resulted in floods of
warnings even if the total reported time in the warning was much higher,
while those above one second provoked the panic.

One improvement could consist in reporting the time since last stuck
in the thread dumps to differentiate the individual task from the whole
set.

This needs to be backported to 3.2 along with the two previous patches:

    MINOR: sched: let's permit to share the local ctx between threads
    MINOR: sched: pass the thread number to is_sched_alive()

diff --git a/src/wdt.c b/src/wdt.c
index 4290d6115966c6e4984c6198e9bae207c13520de..a18745f0ff0a4c136004d0023f2c207414e91318 100644 (file)
--- a/src/wdt.c
+++ b/src/wdt.c
@@ -41,6 +41,7 @@
  */
 static struct {
        timer_t timer;
+       uint64_t stuck_start; /* cpu time when the scheduler's stuck was last set */
 } per_thread_wd_ctx[MAX_THREADS];
 
 /* warn about stuck tasks after this delay (ns) */
@@ -89,14 +90,6 @@ void wdt_handler(int sig, siginfo_t *si, void *arg)
 
                tgrp = ha_thread_info[thr].tgid;
                thr_bit = ha_thread_info[thr].ltid_bit;
-               p = ha_thread_ctx[thr].prev_cpu_time;
-               n = now_cpu_time_thread(thr);
-
-               /* not yet reached the deadline of 1 sec,
-                * or p wasn't initialized yet
-                */
-               if (!p)
-                       goto update_and_leave;
 
                if ((_HA_ATOMIC_LOAD(&ha_thread_ctx[thr].flags) & TH_FL_SLEEPING) ||
                    (_HA_ATOMIC_LOAD(&ha_tgroup_ctx[tgrp-1].threads_harmless) & thr_bit)) {
@@ -109,38 +102,21 @@ void wdt_handler(int sig, siginfo_t *si, void *arg)
                        goto update_and_leave;
                }
 
-               /* So the thread indeed appears locked up. In order to be
-                * certain that we're not witnessing an exceptional spike of
-                * CPU usage due to a configuration issue (like running tens
-                * of thousands of tasks in a single loop), we'll check if the
-                * scheduler is still alive by setting the TH_FL_STUCK flag
-                * that the scheduler clears when switching to the next task.
-                * If it's already set, then it's our second call with no
-                * progress and the thread is dead. However, if we figure
-                * that the scheduler made no progress since last time, we'll
-                * at least emit a warning.
+               /* check whether the scheduler is still running. The first time
+                * we check, we mark it as possibly stuck to challenge it, we
+                * store the last date where we did this, and we quit. On next
+                * wakeup, if it has not moved, we'll wake up the suspicious
+                * thread which will perform its own date checks. This way we
+                * avoid complex computations in a possibly unrelated thread
+                * and don't wake another thread up as long as everything's OK.
                 */
-               if (!(_HA_ATOMIC_LOAD(&ha_thread_ctx[thr].flags) & TH_FL_STUCK)) {
-                       /* after one second it's clear that we're stuck */
-                       if (n - p >= 1000000000ULL) {
-                               _HA_ATOMIC_OR(&ha_thread_ctx[thr].flags, TH_FL_STUCK);
-                               goto update_and_leave;
-                       }
-                       else if (n - p < (ullong)wdt_warn_blocked_traffic_ns) {
-                               /* if we haven't crossed the warning boundary,
-                                * let's just refresh the reporting thread's timer.
-                                */
-                               goto update_and_leave;
-                       }
+               if (is_sched_alive(thr)) {
+                       n = now_cpu_time_thread(thr);
+                       _HA_ATOMIC_STORE(&per_thread_wd_ctx[thr].stuck_start, n);
+                       goto update_and_leave;
                }
 
-               /* OK so we've crossed the warning boundary and possibly the
-                * panic one as well. This may only be reported by the original
-                * thread. Let's fall back to the common code below which will
-                * possibly bounce to the reporting thread, which will then
-                * check the ctxsw count and decide whether to do nothing, to
-                * warn, or either panic.
-                */
+               /* Suspiciously didn't change: fall through target thread signaling */
                break;
 
 #if defined(USE_THREAD) && defined(SI_TKILL) /* Linux uses this */
@@ -165,8 +141,8 @@ void wdt_handler(int sig, siginfo_t *si, void *arg)
        }
 
        /* Right here, we either got a bounce from another thread's WDT to
-        * report a crossed period, or we noticed it for the current thread.
-        * For other threads, we're bouncing.
+        * report a suspciously stuck scheduler, or we noticed it for the
+        * current thread. For other threads, we're bouncing.
         */
 #ifdef USE_THREAD
        if (thr != tid) {
@@ -175,23 +151,52 @@ void wdt_handler(int sig, siginfo_t *si, void *arg)
        }
 #endif
 
-       /* Now the interesting things begin. We're on the thread of interest.
-        * Its timer was at least as large as the warning threshold since poll
-        * was left. If it was at least as high as the panic threshold, we also
-        * have TH_FL_STUCK, which now proves that nothing is happening since
-        * the scheduler clears it for each task. We can still recheck whether
-        * the scheduler looks alive and get away with all of this if we've got
-        * a proof that it's making forward progress. If stuck, we have to die,
-        * otherwise we just send a warning. In short, is_sched_alive() serves
-        * as a ping to detect the warning condition while TH_FL_STUCK works
-        * the same but for a panic condition.
+       /* OK here we're on the target thread (thr==tid). It was reported that
+        * the scheduler was not moving. This might have changed since, if we
+        * got that from another thread. Otherwise we'll run time checks to
+        * verify the situation, and possibly the need to warn or panic.
+        */
+       n = now_cpu_time();
+
+       if (is_sched_alive(thr)) {
+               _HA_ATOMIC_STORE(&per_thread_wd_ctx[thr].stuck_start, n);
+               goto update_and_leave;
+       }
+
+       /* check when we saw last activity (in CPU time) */
+       p = ha_thread_ctx[thr].prev_cpu_time;
+
+       /* p not yet initialized (e.g. signal received during early boot) */
+       if (!p)
+               goto update_and_leave;
+
+       /* check the most recent known activity */
+       if (p < per_thread_wd_ctx[thr].stuck_start)
+               p = per_thread_wd_ctx[thr].stuck_start;
+
+       /* if we haven't crossed the warning boundary, let's just refresh the
+        * reporting thread's timer.
+        */
+       if (n - p < (ullong)wdt_warn_blocked_traffic_ns)
+               goto update_and_leave;
+
+       /* The thread indeed appears locked up, it hasn't made any progress
+        * for at least the configured warning time. If it crosses the second,
+        * we'll mark it with TH_FL_STUCK so that the next call will panic.
+        * Doing so still permits exceptionally long operations to mark
+        * themselves as under control and not stuck to avoid the panic.
+        * Otherwise we just emit a warning, and this one doesn't consider
+        * TH_FL_STUCK (i.e. a slow code path must always be reported to the
+        * user, even if under control).
         */
        if (_HA_ATOMIC_LOAD(&th_ctx->flags) & TH_FL_STUCK)
                ha_panic();
 
-       if (!is_sched_alive(thr))
-               ha_stuck_warning();
+       /* after one second it's clear that we're stuck */
+       if (n - p >= 1000000000ULL)
+               _HA_ATOMIC_OR(&ha_thread_ctx[thr].flags, TH_FL_STUCK);
 
+       ha_stuck_warning();
        /* let's go on */
 
  update_and_leave: