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:
- Log date tags —
%t, %tr, %T, %Tl, %trg, %trl
(src/log.c, all via get_localtime()/get_gmtime()).
- 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:
- 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?
- Preferred slot count / eviction? 4-slot ring was enough to eliminate the
convoy in our tests; happy to tune.
- 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.
Summary
get_localtime()/get_gmtime()ininclude/haproxy/tools.hare thin wrappersaround 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:
%t,%tr,%T,%Tl,%trg,%trl(
src/log.c, all viaget_localtime()/get_gmtime()).ltime,utime,ms_ltime,ms_utime(
src/sample.c, viaconv_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_lockinside__tzfile_compute()while the others block infutex, off-CPU. Tasklets stopmaking progress and the watchdog fires.
This is not glibc-version specific — the
tzset_lockin__tz_convert()ispresent 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 formatuses
%t; the config also evaluates thedate,ltime(...)converter once perrequest. Under a mild flood we get:
The stuck thread is building a log line (
sess_build_logline→ libc → futex),i.e. formatting the
%taccept-date vialocaltime_r().Evidence (perf)
perf recordwhile 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 thelock holder burns CPU in
__tzfile_compute):We confirmed it is not a malloc/arena issue:
libjemalloc.so.1was alreadyLD_PRELOADed and the stalls persisted unchanged.perf lock/ off-CPUprofiling point at the tz lock.
Why the usual mitigations don't fix it
malloc.TZ— reduces the parse/statwork inside the critical section butdoes not remove the lock;
__tz_convert()still takestzset_lockand runs__tzfile_compute()under it on every call. The convoy remains.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()perrequest.
Proposed fix
localtime_r(t)/gmtime_r(t)are pure functions oft— the timezone isfixed 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_datefor%tand "now" for thedate,ltimeconverter), whichwould 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, socorrectness 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):
(The
[0 ... N-1]designated-range initializer is a GCC extension; can bereplaced 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
time_t, so a hit returns byte-for-byte whatlocaltime_r()/gmtime_r()would return. Not an approximation.struct tmincludestm_gmtoffandtm_zone;tm_zonepoints toa static
tznamestring, which is stable, so%z/%Zoutput is unaffected.TZdoes not change at runtime. If HAProxy ever needs to honor aruntime TZ change (SIGHUP-style tz reload / updated tzdata), the cache would
need invalidation. As far as we can tell HAProxy does not re-
tzset()atruntime, but reviewers know this better than we do.
Questions for maintainers:
to integrate with the existing clock infrastructure (e.g. maintain the
broken-down "now" centrally and special-case it), keeping the wrappers thin?
convoy in our tests; happy to tune.
MINORvsMEDIUM: tools:— it does tripthe watchdog, but there is no data corruption).
We are running this locally and can provide before/after
perf locknumbers anda reproducer (many threads + HTTP/2 +
%tin log-format +date,ltimeconverter)if useful.