Cache time conversions for localtime() and CreateTimeString()

When converting a time in seconds (64-bit seconds since 1970) to
Month/Day/Year hours minutes, Suricata calls localtime_r(), which
always aquires a lock and then does complex comutation based on the
current time zone. The time zone can be specified in the TZ
environment variable, which is only parsed the first time it is used,
or from a file. The default file is /etc/localtime. The file is
checked each time to see if it might have changed and is reparsed if
it has changed.

The GLIBC library has a lock inside localtime_r(), which limits
parallelism, which is a problem when the rate of generating alerts is
high, since Suricata generates a new ascii time string for each alert
into fast.log.

This change caches the value returned by localtime_t() and then sets
the seconds within the minute based on the cached start-of-minute
time. All of the values return, expect for the seconds, is constant
within the same minute. Switching to a new seconds could change all
the other values, year, month, day, hour. The cache stores the current
and previous minute values.

The same trick is used in CreateTimeString() for generated time
string. The string, up to the minutes, is cached and then copied into
the result string, followed by printing the new seconds into the
result string.

The seconds within a minute are calculated as the difference in
seconds from the start of the current minute.

diff --git a/src/util-time.c b/src/util-time.c
index 48dfb4f8091a998938a0b88ca3e8a7f209e3159c..2ea29d43f12a598a3a048b937b15a699e3290d51 100644 (file)
--- a/src/util-time.c
+++ b/src/util-time.c
@@ -19,8 +19,10 @@
  * \file
  *
  * \author Victor Julien <victor@inliniac.net>
+ * \author Ken Steele <suricata@tilera.com>
  *
- * Time keeping for offline (non-live) packet handling (pcap files)
+ * Time keeping for offline (non-live) packet handling (pcap files).
+ * And time string generation for alerts.
  */
 
 #include "suricata-common.h"
@@ -33,8 +35,25 @@ static struct timeval current_time = { 0, 0 };
 static SCSpinlock current_time_spinlock;
 static char live = TRUE;
 
-void TimeInit(void) {
+/* Values for caching in CreateTimeString */
+#define MAX_LOCAL_TIME_STRING 128
+static __thread int mru_time_slot; /* Most recently used cached value */
+static __thread time_t last_local_time[2];
+static __thread short int cached_local_time_len[2];
+static __thread char cached_local_time[2][MAX_LOCAL_TIME_STRING];
+
+/* Values for caching SCLocalTime() These cached values are
+ * independent from the CreateTimeString cached values. */
+static __thread int mru_tm_slot; /* Most recently used local tm */
+static __thread time_t cached_minute_start[2];
+static __thread struct tm cached_local_tm[2];
+
+void TimeInit(void)
+{
     SCSpinInit(&current_time_spinlock, 0);
+
+    /* Initialize Time Zone settings. */
+    tzset();
 }
 
 void TimeDeinit(void) {
@@ -111,19 +130,115 @@ void TimeSetIncrementTime(uint32_t tv_sec) {
     TimeSet(&tv);
 }
 
-
+/** \brief Convert time_t into Year, month, day, hour and minutes.
+ * \param timep Time in seconds since defined date.
+ * \param result The structure into which the broken down time it put.
+ *
+ * To convert a time in seconds into year, month, day, hours, minutes
+ * and seconds, call localtime_r(), which uses the current time zone
+ * to compute these values. Note, glibc's localtime_r() aquires a lock
+ * each time it is called, which limits parallelism. To call
+ * localtime_r() less often, the values returned are cached for the
+ * current and previous minute and then seconds are adjusted to
+ * compute the returned result. This is valid as long as the
+ * difference between the start of the current minute and the current
+ * time is less than 60 seconds. Once the minute value changes, all
+ * the other values could change.
+ *
+ * Two values are cached to prevent thrashing when changing from one
+ * minute to the next. The two cached minutes are independent and are
+ * not required to be M and M+1. If more than two minutes are
+ * requested, the least-recently-used cached value is updated more
+ * often, the results are still correct, but performance will be closer
+ * to previous performance.
+ */
 struct tm *SCLocalTime(time_t timep, struct tm *result)
 {
-    return localtime_r(&timep, result);
+    /* Only get a new local time when the time crosses into a new
+     * minute. */
+    int mru = mru_tm_slot;
+    int lru = 1 - mru;
+    int mru_seconds = timep - cached_minute_start[mru];
+    int lru_seconds = timep - cached_minute_start[lru];
+    int new_seconds;
+    if (mru_seconds >= 0 && mru_seconds <= 59) {
+        /* Use most-recently cached time, adjusting the seconds. */
+        new_seconds = mru_seconds;
+    } else if (lru_seconds >= 0 && lru_seconds <= 59) {
+        /* Use least-recently cached time, update to most recently used. */
+        new_seconds = lru_seconds;
+        mru = lru;
+        mru_tm_slot = mru;
+    } else {
+        /* Update least-recent cached time. */
+        if (localtime_r(&timep, &cached_local_tm[lru]) == NULL)
+            return NULL;
+
+        /* Subtract seconds to get back to the start of the minute. */
+        new_seconds = cached_local_tm[lru].tm_sec;
+        cached_minute_start[lru] = timep - new_seconds;
+        mru = lru;
+        mru_tm_slot = mru;
+    }
+    memcpy(result, &cached_local_tm[mru], sizeof(struct tm));
+    result->tm_sec = new_seconds;
+
+    return result;
+}
+
+/* Update the cached time string in cache index N, for the current minute. */
+static int UpdateCachedTime(int n, time_t time)
+{
+    struct tm local_tm;
+    struct tm *t = (struct tm *)SCLocalTime(time, &local_tm);
+    int cached_len = snprintf(cached_local_time[n], MAX_LOCAL_TIME_STRING,
+                              "%02d/%02d/%02d-%02d:%02d:",
+                              t->tm_mon + 1, t->tm_mday, t->tm_year + 1900,
+                              t->tm_hour, t->tm_min);
+    cached_local_time_len[n] = cached_len;
+    /* Store the time of the beginning of the minute. */
+    last_local_time[n] = time - t->tm_sec;
+    mru_time_slot = n;
+
+    return t->tm_sec;
 }
 
+/** \brief Return a formatted string for the provided time.
+ *
+ * Cache the Month/Day/Year - Hours:Min part of the time string for
+ * the current minute. Copy that result into the the return string and
+ * then only print the seconds for each call.
+ */
 void CreateTimeString (const struct timeval *ts, char *str, size_t size)
 {
     time_t time = ts->tv_sec;
-    struct tm local_tm;
-    struct tm *t = (struct tm*)SCLocalTime(time, &local_tm);
+    int seconds;
+
+    /* Only get a new local time when the time crosses into a new
+     * minute */
+    int mru = mru_time_slot;
+    int lru = 1 - mru;
+    int mru_seconds = time - last_local_time[mru];
+    int lru_seconds = time - last_local_time[lru];
+    if (mru_seconds >= 0 && mru_seconds <= 59) {
+        /* Use most-recently cached time. */
+        seconds = mru_seconds;
+    } else if (lru_seconds >= 0 && lru_seconds <= 59) {
+        /* Use least-recently cached time. Change this slot to Most-recent */
+        seconds = lru_seconds;
+        mru_time_slot = lru;
+    } else {
+        /* Update least-recent cached time. Lock accessing local time
+         * function because it keeps any internal non-spin lock. */
+        seconds = UpdateCachedTime(lru, time);
+    }
 
-    snprintf(str, size, "%02d/%02d/%02d-%02d:%02d:%02d.%06u",
-             t->tm_mon + 1, t->tm_mday, t->tm_year + 1900, t->tm_hour,
-             t->tm_min, t->tm_sec, (uint32_t) ts->tv_usec);
+    /* Copy the string up to the current minute then print the seconds
+       into the return string buffer. */
+    char *cached_str = cached_local_time[mru_time_slot];
+    int cached_len = cached_local_time_len[mru_time_slot];
+    memcpy(str, cached_str, cached_len);
+    snprintf(str + cached_len, size - cached_len,
+             "%02d.%06u",
+             seconds, (uint32_t) ts->tv_usec);
 }