OPTIM: tools: keep a cache of recent localtime() and gmtime()

The log subsystem already keeps a cache of the latest generated time
header to avoid paying the price of snprintf() notably. However, as
reported in GH issue #3444 by @zino7825, localtime() and gmtime() are
affected (at least in glibc) by a tzset_lock held during the call to
__tz_convert(), which ruins performance when logging time such as the
accept date. Even just "option httplog" sees its performance divided
by two on a 64-core machine, from 1.8M to 910k req/s.

The following config even goes down to 388k req/s:

  defaults
    mode http

  frontend fe
    bind :8001
    log 127.0.0.1:5514 len 8192 local0
    log-format '{"t":"%t","tr":"%tr","ci":"%ci"}'
    http-request set-var(txn.now) date(),ltime("%Y-%m-%dT%H:%M:%S")
    option httplog
    default_backend be

  backend be
    server s1 198.18.0.31:8000

With native_queued_spin_lock_slowpath() taking 80% of the CPU, showing
that it's also involved in futexes.

This patch, suggested by @zino7825, implements a very simple thread-
local cache for the 4 previously seen values for both localtime() and
gmtime(). The cache is visited in reverse order so that most recently
updated values are visited first (the most likely ones to be used). A
test with the config above and 12.8M requests showed 38.4M lookups with
only 12k total misses. A more naive scan from 0 to N caused 59M misses.
With this patch, all variants of the tests above remain at native speed
without native_queued_spin_lock_slowpath() being noticeable at all. If
for any reason a log format was so complex that it needed more stored
local times, it would be easy to change the cache size by redefining
TIME_CACHE_BITS.

The functions are no longer inlined, they were moved to tools.c since
we'd rather avoid loops and complex constructs in inlined functions.

Co-authored-by: Jinho Kong <zino7825@users.noreply.github.com>

diff --git a/include/haproxy/defaults.h b/include/haproxy/defaults.h
index 8a9062ea431eb54a0052fea7e8e806a78d20d827..aec594e0690770812ed3df9c4e3d0233134e068e 100644 (file)
--- a/include/haproxy/defaults.h
+++ b/include/haproxy/defaults.h
@@ -749,4 +749,13 @@
 #define STKTABLE_MAX_UPDATES_AT_ONCE 100
 #endif /* STKTABLE_MAX_UPDATES_AT_ONCE */
 
+/* number of time cache entries, must be a power of two, hence the setting in
+ * bits. Note that 2 or 4 slots is already sufficient in practice.
+ */
+#ifndef TIME_CACHE_BITS
+# define TIME_CACHE_BITS 2
+#endif
+#define TIME_CACHE_SLOTS (1U << TIME_CACHE_BITS)
+
+
 #endif /* _HAPROXY_DEFAULTS_H */

diff --git a/include/haproxy/tools.h b/include/haproxy/tools.h
index b00c21b3b29b7a716469e21a8ece991bc365d993..148d56f1313661e154e2520ef284fda5eb5e4049 100644 (file)
--- a/include/haproxy/tools.h
+++ b/include/haproxy/tools.h
@@ -602,25 +602,8 @@ static inline char *alltrim(char *s, char c) {
        return ltrim(s, c);
 }
 
-/* This function converts the time_t value <now> into a broken out struct tm
- * which must be allocated by the caller. It is highly recommended to use this
- * function instead of localtime() because that one requires a time_t* which
- * is not always compatible with tv_sec depending on OS/hardware combinations.
- */
-static inline void get_localtime(const time_t now, struct tm *tm)
-{
-       localtime_r(&now, tm);
-}
-
-/* This function converts the time_t value <now> into a broken out struct tm
- * which must be allocated by the caller. It is highly recommended to use this
- * function instead of gmtime() because that one requires a time_t* which
- * is not always compatible with tv_sec depending on OS/hardware combinations.
- */
-static inline void get_gmtime(const time_t now, struct tm *tm)
-{
-       gmtime_r(&now, tm);
-}
+void get_localtime(const time_t now, struct tm *tm);
+void get_gmtime(const time_t now, struct tm *tm);
 
 /* Counts a number of elapsed days since 01/01/0000 based solely on elapsed
  * years and assuming the regular rule for leap years applies. It's fake but

diff --git a/src/tools.c b/src/tools.c
index 5b15905a87c0299b6dce473ecb5b6159683c0abd..afb29460b6ad31ebde97cb28e7083a429e34b9b2 100644 (file)
--- a/src/tools.c
+++ b/src/tools.c
@@ -3892,6 +3892,72 @@ size_t ipaddrcpy(unsigned char *buf, const struct sockaddr_storage *saddr)
        return p - buf;
 }
 
+/* cache of conversions from time_t to struct tm via localtime() and gmtime(). */
+static THREAD_LOCAL struct {
+       time_t sec;
+       struct tm tm;
+} localtime_cache[TIME_CACHE_SLOTS], gmtime_cache[TIME_CACHE_SLOTS];
+
+/* slot where most recent value was stored */
+static THREAD_LOCAL uint localtime_cache_slot, gmtime_cache_slot;
+
+/* This function converts the time_t value <now> into a broken out struct tm
+ * which must be allocated by the caller. It is highly recommended to use this
+ * function instead of localtime() because that one requires a time_t* which
+ * is not always compatible with tv_sec depending on OS/hardware combinations.
+ * Also it implements a cache that avoids internal libc contention on tz_lock
+ * when entering __tz_convert().
+ */
+void get_localtime(const time_t now, struct tm *tm)
+{
+       uint32_t idx;
+
+       /* visit recent entries in age order */
+       idx = localtime_cache_slot;
+       do {
+               if (likely(localtime_cache[idx].sec == now)) {
+                       /* that's a hit, return the cached entry */
+                       *tm = localtime_cache[idx].tm;
+                       return;
+               }
+               idx = (idx - 1) % TIME_CACHE_SLOTS;
+       } while (idx != localtime_cache_slot);
+
+       /* that's a miss, convert the time and cache it */
+       localtime_r(&now, tm);
+       localtime_cache_slot = (localtime_cache_slot + 1) % TIME_CACHE_SLOTS;
+       localtime_cache[localtime_cache_slot].sec = now;
+       localtime_cache[localtime_cache_slot].tm = *tm;
+}
+
+/* This function converts the time_t value <now> into a broken out struct tm
+ * which must be allocated by the caller. It is highly recommended to use this
+ * function instead of gmtime() because that one requires a time_t* which
+ * is not always compatible with tv_sec depending on OS/hardware combinations.
+ * Also it implements a cache that avoids internal libc contention on tz_lock
+ * when entering __tz_convert().
+ */
+void get_gmtime(const time_t now, struct tm *tm)
+{
+       uint32_t idx;
+
+       /* visit recent entries in age order */
+       idx = gmtime_cache_slot;
+       do {
+               if (likely(gmtime_cache[idx].sec == now)) {
+                       /* that's a hit, return the cached entry */
+                       *tm = gmtime_cache[idx].tm;
+                       return;
+               }
+               idx = (idx - 1) % TIME_CACHE_SLOTS;
+       } while (idx != gmtime_cache_slot);
+
+       /* that's a miss, convert the time and cache it */
+       gmtime_r(&now, tm);
+       gmtime_cache_slot = (gmtime_cache_slot + 1) % TIME_CACHE_SLOTS;
+       gmtime_cache[gmtime_cache_slot].sec = now;
+       gmtime_cache[gmtime_cache_slot].tm = *tm;
+}
 
 char *human_time(int t, short hz_div) {
        static char rv[sizeof("24855d23h")+1];  // longest of "23h59m" and "59m59s"