per-request localtime_r()/gmtime_r() in log/date converters serialize on the glibc tz lock, stalling threads

The get_localtime()/get_gmtime() wrappers live in include/haproxy/tools.h; the per-request callers to trace are sess_build_logline() date tags in src/log.c and conv_time_common() (ltime/utime/ms_ltime/ms_utime) in src/sample.c. Read the 12-comment thread first: per CONTRIBUTING patches go to the mailing list, and maintainers must settle the caching approach and the TZ-fixed-at-runtime assumption before code lands. Done looks like a reproducer (many threads, HTTP/2, %t plus date,ltime) with no watchdog stalls and before/after perf lock numbers.

Note: this is filed as a GitHub issue for visibility, but per CONTRIBUTING
the canonical channel for patches is the mailing list. Happy to resend the
patch via git send-email rebased on the current dev branch if you prefer —
this issue is primarily to discuss whether the approach is acceptable.

Summary

get_localtime() / get_gmtime() in include/haproxy/tools.h are thin wrappers
around glibc localtime_r() / gmtime_r(). On glibc, both of those enter
__tz_convert(), which takes a process-wide lock (tzset_lock, via
__libc_lock_lock) on every call — and holds it while running
__tzfile_compute() to resolve the UTC offset for the given timestamp.

HAProxy calls these functions per request through two very common paths:

1. Log date tags — %t, %tr, %T, %Tl, %trg, %trl
   (src/log.c, all via get_localtime()/get_gmtime()).
2. Date/time sample converters — ltime, utime, ms_ltime, ms_utime
   (src/sample.c, via conv_time_common() → get_localtime()/get_gmtime()).

With many threads at a high request rate, these calls all contend on that one
lock. The result is a classic lock convoy: one thread holds tzset_lock inside
__tzfile_compute() while the others block in futex, off-CPU. Tasklets stop
making progress and the watchdog fires.

This is not glibc-version specific — the tzset_lock in __tz_convert() is
present in current glibc as well, not only old releases. It just gets worse with
higher thread counts and request rates.

Observed symptom

HAProxy 3.2.19, nbthread 36, HTTP/2, high request rate, glibc 2.17. Log format
uses %t; the config also evaluates the date,ltime(...) converter once per
request. Under a mild flood we get:

haproxy[20895]: WARNING! thread 24 has stopped processing traffic for 125 milliseconds
   with 25876 streams currently blocked, prevented from making any progress.
...
* Thread 24: ... rqsz=26256
   curr_task=... (tasklet) calls=803 fct=...(h2_io_cb)
   lock_hist: R:LISTENER U:LISTENER R:SNI U:SNI R:TLSKEYS_REF U:TLSKEYS_REF R:SNI U:SNI
   call trace(22):
   | ha_stuck_warning ...
   | wdt_handler ...
   | libc:... (futex / pthread)
   | sess_build_logline...+0x17a1 ...   <-- log line building
   | _sess_log ...
   | h2_sess_log_strm ...
   | h2_io_cb ...

The stuck thread is building a log line (sess_build_logline → libc → futex),
i.e. formatting the %t accept-date via localtime_r().

Evidence (perf)

perf record while stalling shows the tz path plus the internal-lock futex wait
(low on-CPU % is expected — the waiters are off-CPU in futex_wait, only the
lock holder burns CPU in __tzfile_compute):

__tz_convert            libc
__tz_compute            libc
__tzfile_compute        libc
__tzset_parse_tz        libc
__lll_lock_wait_private libc      <-- futex wait on the internal (tz) lock
__lll_unlock_wake_private libc

We confirmed it is not a malloc/arena issue: libjemalloc.so.1 was already
LD_PRELOADed and the stalls persisted unchanged. perf lock / off-CPU
profiling point at the tz lock.

Why the usual mitigations don't fix it

• Allocator (jemalloc/tcmalloc) — irrelevant; the lock is glibc's tz lock, not malloc.
• Setting TZ — reduces the parse/stat work inside the critical section but
  does not remove the lock; __tz_convert() still takes tzset_lock and runs
  __tzfile_compute() under it on every call. The convoy remains.
• Switching ltime→utime — no help; gmtime_r() also goes through
  __tz_convert() and takes the same lock (on the glibc we tested).

The only effective lever is to not call localtime_r()/gmtime_r() per
request.

Proposed fix

localtime_r(t) / gmtime_r(t) are pure functions of t — the timezone is
fixed for the lifetime of the process, and a given UTC instant maps to a fixed
broken-down time regardless of DST. So the result can be cached and reused
lock-free.

We use a tiny per-thread N-slot cache keyed on the epoch second. A single
slot is not enough because one request formats more than one distinct second
(e.g. accept_date for %t and "now" for the date,ltime converter), which
would thrash a 1-slot cache; a 4-slot ring absorbs that. On a hit the result is
identical to calling localtime_r(); on a miss we fall back to the real call, so
correctness is unchanged in all cases. The lock is now taken at most ~once per
distinct second per thread.

Patch (against 3.2.19; line numbers will differ on master):

--- a/include/haproxy/tools.h
+++ b/include/haproxy/tools.h
@@ static inline void get_localtime(const time_t now, struct tm *tm)
 static inline void get_localtime(const time_t now, struct tm *tm)
 {
+	/* localtime_r() enters glibc __tz_convert() which takes a process-wide
+	 * lock (tzset_lock) on every call; under many threads at high request
+	 * rates this serializes on a single futex and stalls tasklets, tripping
+	 * the watchdog ("stopped processing traffic"). It is a pure function of
+	 * <now> (TZ is fixed at runtime), so a small per-thread cache keyed on the
+	 * epoch second returns the exact same result lock-free. Several slots are
+	 * used because a single request formats more than one distinct second
+	 * (e.g. the log's accept_date and the current time used by the date/ltime
+	 * converters), which would thrash a single-slot cache. */
+	enum { LT_SLOTS = 4 };
+	static THREAD_LOCAL time_t    lt_sec[LT_SLOTS] = { [0 ... LT_SLOTS - 1] = (time_t)-1 };
+	static THREAD_LOCAL struct tm lt_tm[LT_SLOTS];
+	static THREAD_LOCAL int       lt_next;
+	int i;
+
+	for (i = 0; i < LT_SLOTS; i++) {
+		if (lt_sec[i] == now) {
+			*tm = lt_tm[i];
+			return;
+		}
+	}
 	localtime_r(&now, tm);
+	lt_sec[lt_next] = now;
+	lt_tm[lt_next]  = *tm;
+	lt_next = (lt_next + 1) % LT_SLOTS;
 }
@@ static inline void get_gmtime(const time_t now, struct tm *tm)
 static inline void get_gmtime(const time_t now, struct tm *tm)
 {
+	/* Same rationale as get_localtime(): gmtime_r() also enters __tz_convert()
+	 * and takes the process-wide tzset_lock on glibc, so use the same small
+	 * per-thread epoch-second cache to avoid the lock convoy. */
+	enum { GT_SLOTS = 4 };
+	static THREAD_LOCAL time_t    gt_sec[GT_SLOTS] = { [0 ... GT_SLOTS - 1] = (time_t)-1 };
+	static THREAD_LOCAL struct tm gt_tm[GT_SLOTS];
+	static THREAD_LOCAL int       gt_next;
+	int i;
+
+	for (i = 0; i < GT_SLOTS; i++) {
+		if (gt_sec[i] == now) {
+			*tm = gt_tm[i];
+			return;
+		}
+	}
 	gmtime_r(&now, tm);
+	gt_sec[gt_next] = now;
+	gt_tm[gt_next]  = *tm;
+	gt_next = (gt_next + 1) % GT_SLOTS;
 }

(The [0 ... N-1] designated-range initializer is a GCC extension; can be
replaced with a small init loop if wider compiler support is desired. Plain
zero-init would also work since a real epoch second is never 0.)

Correctness notes / open questions

• Keyed on the exact time_t, so a hit returns byte-for-byte what
  localtime_r()/gmtime_r() would return. Not an approximation.
• Per-thread → no locking on the cache itself.
• The copied struct tm includes tm_gmtoff and tm_zone; tm_zone points to
  a static tzname string, which is stable, so %z/%Z output is unaffected.
• Assumption: TZ does not change at runtime. If HAProxy ever needs to honor a
  runtime TZ change (SIGHUP-style tz reload / updated tzdata), the cache would
  need invalidation. As far as we can tell HAProxy does not re-tzset() at
  runtime, but reviewers know this better than we do.

Questions for maintainers:

1. Is a small per-thread cache in these wrappers acceptable, or would you prefer
   to integrate with the existing clock infrastructure (e.g. maintain the
   broken-down "now" centrally and special-case it), keeping the wrappers thin?
2. Preferred slot count / eviction? 4-slot ring was enough to eliminate the
   convoy in our tests; happy to tune.
3. Severity/tagging for the commit (MINOR vs MEDIUM: tools: — it does trip
   the watchdog, but there is no data corruption).

We are running this locally and can provide before/after perf lock numbers and
a reproducer (many threads + HTTP/2 + %t in log-format + date,ltime converter)
if useful.