DEBUG: wdt: make the blocked traffic warning delay configurable

The new global "warn-blocked-traffic-after" allows one to configure
after how much time a warning should be emitted when traffic is blocked.

diff --git a/doc/configuration.txt b/doc/configuration.txt
index 23dfd5d2b185048365967a884924c3ec929557d9..7faf865ab6e8f287e3da57673d5a9dc92788f330 100644 (file)
--- a/doc/configuration.txt
+++ b/doc/configuration.txt
@@ -1562,6 +1562,7 @@ The following keywords are supported in the "global" section :
  * Debugging
    - anonkey
    - quiet
+   - warn-blocked-traffic-after
    - zero-warning
 
  * HTTPClient
@@ -4394,6 +4395,24 @@ quiet
   Do not display any message during startup. It is equivalent to the command-
   line argument "-q".
 
+warn-blocked-traffic-after <time>
+  This allows to adjust the delay after which a stuck task blocking the traffic
+  will trigger the emission of a warning on the standard error output. The
+  delay is expressed in milliseconds and defaults to 1000 ms. Permitted values
+  must be comprised between 1 ms and 1000 ms included. Lower values will
+  trigger warnings frequently and higher ones will rarely. The watchdog will
+  kill a runaway task that fails to respond twice for one second anyway, so a
+  1000 ms warning delay will normally not trigger any warning. It is
+  recommended to stay with values between 10 and 100ms to detect configuration
+  anomalies that may degrade the user's experience, causing long response times
+  or jerkiness on interactive sessions. For example, a poorly designed Lua
+  sample-fetch function doing heavy computations, or a very large map_reg or
+  map_regm map file with a very high evaluation cost may cause such trouble.
+  For comparison a TLS handshake can eat between one and two milliseconds, and
+  compressing a 16kB HTTP response buffer is around one millisecond. The output
+  contains a thread dump of the offending task with a backtrace and some
+  context that helps figure where the time is being spent.
+
 zero-warning
   When this option is set, HAProxy will refuse to start if any warning was
   emitted while processing the configuration and applying it. It means that

diff --git a/src/debug.c b/src/debug.c
index 1d9ac4155582720c2ae58a853ee1fd4ff299f1d1..75307dd7bea5332c282755b5d311f59034fcd08d 100644 (file)
--- a/src/debug.c
+++ b/src/debug.c
@@ -760,9 +760,10 @@ void ha_stuck_warning(int thr)
                     "    this must remain exceptional because the system's stability is now at risk.\n"
                     "    Timers in logs may be reported incorrectly, spurious timeouts may happen,\n"
                     "    some incoming connections may silently be dropped, health checks may\n"
-                    "    randomly fail, and accesses to the CLI may block the whole process. Please\n"
-                    "    check the trace below for any clues about configuration elements that need\n"
-                    "    to be corrected:\n\n",
+                    "    randomly fail, and accesses to the CLI may block the whole process. The\n"
+                    "    blocking delay before emitting this warning may be adjusted via the global\n"
+                    "    'warn-blocked-traffic-after' directive. Please check the trace below for\n"
+                    "    any clues about configuration elements that need to be corrected:\n\n",
                     thr + 1, (n - p) / 1000000ULL,
                     HA_ATOMIC_LOAD(&ha_thread_ctx[thr].stream_cnt));
 

diff --git a/src/wdt.c b/src/wdt.c
index a28923b333be703462d0315db753f7795163ca93..edd9c09b31f7153d9a5f0e679a277fb6d491970e 100644 (file)
--- a/src/wdt.c
+++ b/src/wdt.c
@@ -14,6 +14,7 @@
 
 #include <haproxy/activity.h>
 #include <haproxy/api.h>
+#include <haproxy/cfgparse.h>
 #include <haproxy/clock.h>
 #include <haproxy/debug.h>
 #include <haproxy/errors.h>
@@ -42,6 +43,9 @@ static struct {
        uint prev_ctxsw;
 } per_thread_wd_ctx[MAX_THREADS];
 
+/* warn about stuck tasks after this delay (ns) */
+static unsigned int wdt_warn_blocked_traffic_ns = 1000000000U;
+
 /* Setup (or ping) the watchdog timer for thread <thr>. Returns non-zero on
  * success, zero on failure. It interrupts once per second of CPU time. It
  * happens that timers based on the CPU time are not automatically re-armed
@@ -51,7 +55,8 @@ int wdt_ping(int thr)
 {
        struct itimerspec its;
 
-       its.it_value.tv_sec    = 1; its.it_value.tv_nsec    = 0;
+       its.it_value.tv_sec    = wdt_warn_blocked_traffic_ns / 1000000000U;
+       its.it_value.tv_nsec   = wdt_warn_blocked_traffic_ns % 1000000000U;
        its.it_interval.tv_sec = 0; its.it_interval.tv_nsec = 0;
        return timer_settime(per_thread_wd_ctx[thr].timer, 0, &its, NULL) == 0;
 }
@@ -87,7 +92,7 @@ void wdt_handler(int sig, siginfo_t *si, void *arg)
                /* not yet reached the deadline of 1 sec,
                 * or p wasn't initialized yet
                 */
-               if (!p || n - p < 1000000000UL)
+               if (!p)
                        goto update_and_leave;
 
                if ((_HA_ATOMIC_LOAD(&ha_thread_ctx[thr].flags) & TH_FL_SLEEPING) ||
@@ -115,11 +120,22 @@ void wdt_handler(int sig, siginfo_t *si, void *arg)
                if (!(_HA_ATOMIC_LOAD(&ha_thread_ctx[thr].flags) & TH_FL_STUCK)) {
                        uint prev_ctxsw;
 
-                       _HA_ATOMIC_OR(&ha_thread_ctx[thr].flags, TH_FL_STUCK);
                        prev_ctxsw = HA_ATOMIC_LOAD(&per_thread_wd_ctx[tid].prev_ctxsw);
-                       if (HA_ATOMIC_LOAD(&activity[thr].ctxsw) == prev_ctxsw)
-                               ha_stuck_warning(thr);
-                       HA_ATOMIC_STORE(&activity[thr].ctxsw, prev_ctxsw);
+
+                       /* only after one second it's clear we're stuck */
+                       if (n - p >= 1000000000ULL)
+                               _HA_ATOMIC_OR(&ha_thread_ctx[thr].flags, TH_FL_STUCK);
+
+                       /* have we crossed the warning boundary ? If so we note were we
+                        * where, and second time called from the same place will trigger
+                        * a warning (unless already stuck).
+                        */
+                       if (n - p >= (ullong)wdt_warn_blocked_traffic_ns) {
+                               if (HA_ATOMIC_LOAD(&activity[thr].ctxsw) == prev_ctxsw)
+                                       ha_stuck_warning(thr);
+                               HA_ATOMIC_STORE(&activity[thr].ctxsw, prev_ctxsw);
+                       }
+
                        goto update_and_leave;
                }
 
@@ -163,6 +179,44 @@ void wdt_handler(int sig, siginfo_t *si, void *arg)
        wdt_ping(thr);
 }
 
+/* parse the "warn-blocked-traffic-after" parameter */
+static int wdt_parse_warn_blocked(char **args, int section_type, struct proxy *curpx,
+                                  const struct proxy *defpx, const char *file, int line,
+                                  char **err)
+{
+       const char *res;
+       uint value;
+
+       if (!*args[1]) {
+               memprintf(err, "'%s' expects <time> as argument between 1 and 1000 ms.\n", args[0]);
+               return -1;
+       }
+
+       res = parse_time_err(args[1], &value, TIME_UNIT_MS);
+       if (res == PARSE_TIME_OVER) {
+               memprintf(err, "timer overflow in argument '%s' to '%s' (maximum value is 1000 ms)",
+                         args[1], args[0]);
+               return -1;
+       }
+       else if (res == PARSE_TIME_UNDER) {
+               memprintf(err, "timer underflow in argument '%s' to '%s' (minimum value is 1 ms)",
+                         args[1], args[0]);
+               return -1;
+       }
+       else if (res) {
+               memprintf(err, "unexpected character '%c' in argument to <%s>.\n", *res, args[0]);
+               return -1;
+       }
+       else if (value > 1000 || value < 1) {
+               memprintf(err, "timer out of range in argument '%s' to '%s' (value must be between 1 and 1000 ms)",
+                         args[1], args[0]);
+               return -1;
+       }
+
+       wdt_warn_blocked_traffic_ns = value * 1000000U;
+       return 0;
+}
+
 int init_wdt_per_thread()
 {
        if (!clock_setup_signal_timer(&per_thread_wd_ctx[tid].timer, WDTSIG, tid))
@@ -202,6 +256,12 @@ int init_wdt()
        return ERR_NONE;
 }
 
+static struct cfg_kw_list cfg_kws = {ILH, {
+       { CFG_GLOBAL, "warn-blocked-traffic-after", wdt_parse_warn_blocked },
+       { 0, NULL, NULL },
+}};
+
+INITCALL1(STG_REGISTER, cfg_register_keywords, &cfg_kws);
 REGISTER_POST_CHECK(init_wdt);
 REGISTER_PER_THREAD_INIT(init_wdt_per_thread);
 REGISTER_PER_THREAD_DEINIT(deinit_wdt_per_thread);