Skip to content

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

Description

@zino7825

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 convertersltime, 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 ltimeutime — 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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions