From: Brian Pane <brianp@apache.org>
Date: Sun, 12 May 2002 08:09:13 +0000 (+0000)
Subject: Added caching of formatted timestamps to speed up the access logger when
X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=1a5f26a46f56a98a3d6d99437a21096eb6e119c8;p=apache

Added caching of formatted timestamps to speed up the access logger when
using standard time format


git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@95046 13f79535-47bb-0310-9956-ffa450edef68
---

diff --git a/CHANGES b/CHANGES
index 3f3cc97c18..30ed3771ed 100644
--- a/CHANGES
+++ b/CHANGES
@@ -1,5 +1,8 @@
 Changes with Apache 2.0.37
 
+  *) Performance enhancements for access logger when using
+     default timestamp formatting  [Brian Pane]
+
   *) Added EnableMMAP config directive to enable the server
      administrator to disable memory-mapping of delivered files
      on a per-directory basis.  [Brian Pane]
diff --git a/modules/loggers/mod_log_config.c b/modules/loggers/mod_log_config.c
index 37f7b0e653..99e437af22 100644
--- a/modules/loggers/mod_log_config.c
+++ b/modules/loggers/mod_log_config.c
@@ -455,6 +455,17 @@ static const char *log_request_time_custom(request_rec *r, char *a,
     return apr_pstrdup(r->pool, tstr);
 }
 
+#define DEFAULT_REQUEST_TIME_SIZE 32
+typedef struct {
+    apr_int64_t t;
+    char timestr[DEFAULT_REQUEST_TIME_SIZE];
+    apr_int64_t t_validate;
+} cached_request_time;
+
+#define TIME_CACHE_SIZE 4
+#define TIME_CACHE_MASK 3
+static cached_request_time request_time_cache[TIME_CACHE_SIZE];
+
 static const char *log_request_time(request_rec *r, char *a)
 {
     apr_time_exp_t xt;
@@ -470,11 +481,6 @@ static const char *log_request_time(request_rec *r, char *a)
 	than force the server to pay extra cpu cycles.	if you've got
 	a problem with this, you can set the define.  -djg
     */
-#ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
-    ap_explode_recent_localtime(&xt, apr_time_now());
-#else
-    ap_explode_recent_localtime(&xt, r->request_time);
-#endif
     if (a && *a) {              /* Custom format */
         /* The custom time formatting uses a very large temp buffer
          * on the stack.  To avoid using so much stack space in the
@@ -482,25 +488,57 @@ static const char *log_request_time(request_rec *r, char *a)
          * for the custom format in a separate function.  (That's why
          * log_request_time_custom is not inlined right here.)
          */
+#ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
+        ap_explode_recent_localtime(&xt, apr_time_now());
+#else
+        ap_explode_recent_localtime(&xt, r->request_time);
+#endif
         return log_request_time_custom(r, a, &xt);
     }
     else {                      /* CLF format */
-	char sign;
-	int timz;
-
-	timz = xt.tm_gmtoff;
-	if (timz < 0) {
-	    timz = -timz;
-	    sign = '-';
-	}
-	else {
-	    sign = '+';
-	}
-
-        return apr_psprintf(r->pool, "[%02d/%s/%d:%02d:%02d:%02d %c%.2d%.2d]",
-                xt.tm_mday, apr_month_snames[xt.tm_mon], xt.tm_year+1900,
-                xt.tm_hour, xt.tm_min, xt.tm_sec,
-                sign, timz / (60*60), timz % (60*60));
+        /* This code uses the same technique as ap_explode_recent_localtime():
+         * optimistic caching with logic to detect and correct race conditions.
+         * See the comments in server/util_time.c for more information.
+         */
+        cached_request_time* cached_time = apr_palloc(r->pool,
+                                                      sizeof(*cached_time));
+#ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
+        apr_time_t request_time = apr_time_now();
+#else
+        apr_time_t request_time = r->request_time;
+#endif
+        unsigned i = request_time / APR_USEC_PER_SEC;
+        i &= TIME_CACHE_MASK;
+        memcpy(cached_time, &(request_time_cache[i]), sizeof(*cached_time));
+        if ((request_time != cached_time->t) ||
+            (request_time != cached_time->t_validate)) {
+
+            /* Invalid or old snapshot, so compute the proper time string
+             * and store it in the cache
+             */
+            char sign;
+            int timz;
+
+            ap_explode_recent_localtime(&xt, r->request_time);
+            timz = xt.tm_gmtoff;
+            if (timz < 0) {
+                timz = -timz;
+                sign = '-';
+            }
+            else {
+                sign = '+';
+            }
+            cached_time->t = request_time;
+            apr_snprintf(cached_time->timestr, DEFAULT_REQUEST_TIME_SIZE,
+                         "[%02d/%s/%d:%02d:%02d:%02d %c%.2d%.2d]",
+                         xt.tm_mday, apr_month_snames[xt.tm_mon],
+                         xt.tm_year+1900, xt.tm_hour, xt.tm_min, xt.tm_sec,
+                         sign, timz / (60*60), timz % (60*60));
+            cached_time->t_validate = request_time;
+            memcpy(&(request_time_cache[i]), cached_time,
+                   sizeof(*cached_time));
+        }
+        return cached_time->timestr;
     }
 }