[patch] modules/loggers/mod_log_config.c patch

mod_log_config.patch (text/plain), 10.23 KB, created by Daniel Lescohier on 2012-12-31 16:12:49 UTC

(hide)

Description: modules/loggers/mod_log_config.c patch

Filename:

MIME Type:

Creator: Daniel Lescohier

Created: 2012-12-31 16:12:49 UTC

Size: 10.23 KB

patch

obsolete

>--- modules/loggers/mod_log_config.c.orig 2012-12-30 10:56:30.168570849 -0500 >+++ modules/loggers/mod_log_config.c 2012-12-31 09:11:21.215141301 -0500 >@@ -97,9 +97,12 @@ > * %...r: first line of request > * %...s: status. For requests that got internally redirected, this > * is status of the *original* request --- %...>s for the last. >- * %...t: time, in common log format time format >+ * %...t: time, in common log format time format, in localtime. > * %...{format}t: The time, in the form given by format, which should >- * be in strftime(3) format. >+ * be in strftime(3) format, in localtime. >+ * %...g: time, in common log format time format, in GMT. >+ * %...{format}g: The time, in the form given by format, which should >+ * be in strftime(3) format, in GMT. > * %...T: the time taken to serve the request, in seconds. > * %...D: the time taken to serve the request, in micro seconds. > * %...u: remote user (from auth; may be bogus if return status (%s) is 401) >@@ -148,6 +151,7 @@ > #include "apr_hash.h" > #include "apr_optional.h" > #include "apr_anylock.h" >+#include "apr_atomic.h" > > #define APR_WANT_STRFUNC > #include "apr_want.h" >@@ -569,16 +573,23 @@ > apr_time_exp_t *xt) > { > apr_size_t retcode; >- char tstr[MAX_STRING_LEN]; >- apr_strftime(tstr, &retcode, sizeof(tstr), a, xt); >- return apr_pstrdup(r->pool, tstr); >+#define MAX_TIME_LEN 128 >+ char * const tstr = apr_palloc(r->pool, MAX_TIME_LEN); >+ apr_strftime(tstr, &retcode, MAX_TIME_LEN, a, xt); >+ return retcode ? tstr : NULL; >+ /* Don't return empty string, return NULL instead so caller can >+ * replace with "-". >+ */ > } > >-#define DEFAULT_REQUEST_TIME_SIZE 32 > typedef struct { >- unsigned t; >- char timestr[DEFAULT_REQUEST_TIME_SIZE]; >- unsigned t_validate; >+ char str[32]; >+} timestr_t; >+/* We define it as a struct so that we can use a C89 copy-of-struct, >+ * because we cannot use memcpy for memory marked volatile */ >+typedef struct { >+ timestr_t timestr; /* First for alignment of copies */ >+ apr_uint32_t key; > } cached_request_time; > > #define TIME_FMT_CUSTOM 0 >@@ -589,9 +600,10 @@ > #define TIME_FMT_ABS_MSEC_FRAC 5 > #define TIME_FMT_ABS_USEC_FRAC 6 > >-#define TIME_CACHE_SIZE 4 >-#define TIME_CACHE_MASK 3 >-static cached_request_time request_time_cache[TIME_CACHE_SIZE]; >+#define TIME_CACHE_SIZE ((AP_TIME_RECENT_THRESHOLD) + 1) >+#define TIME_CACHE_MASK (AP_TIME_RECENT_THRESHOLD) >+static cached_request_time request_time_cache_lt[TIME_CACHE_SIZE]; >+static cached_request_time request_time_cache_gmt[TIME_CACHE_SIZE]; > > static apr_time_t get_request_end_time(request_rec *r) > { >@@ -604,7 +616,9 @@ > } > > >-static const char *log_request_time(request_rec *r, char *a) >+static const char *log_request_time(request_rec *r, char *a, >+ cached_request_time *cache, >+ apr_status_t (*explode)(apr_time_exp_t *, apr_time_t)) > { > apr_time_exp_t xt; > apr_time_t request_time = r->request_time; >@@ -695,29 +709,59 @@ > * for the custom format in a separate function. (That's why > * log_request_time_custom is not inlined right here.) > */ >- ap_explode_recent_localtime(&xt, request_time); >+ explode(&xt, request_time); > return log_request_time_custom(r, a, &xt); > } > else { /* CLF format */ >- /* 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. >+ /* This code uses the same technique as cached_explode >+ * from server/util_time.c. > */ >- cached_request_time* cached_time = apr_palloc(r->pool, >- sizeof(*cached_time)); >- unsigned t_seconds = (unsigned)apr_time_sec(request_time); >- unsigned i = t_seconds & TIME_CACHE_MASK; >- *cached_time = request_time_cache[i]; >- if ((t_seconds != cached_time->t) || >- (t_seconds != cached_time->t_validate)) { >- >- /* Invalid or old snapshot, so compute the proper time string >- * and store it in the cache >- */ >+ timestr_t * const timestr_p = apr_palloc(r->pool, sizeof(timestr_t)); >+ /* Above allocates memory from the request pool to return the >+ * time string result in. */ >+#define SECONDS_MASK 0x7FFFFFFF >+ /* High bit is used to indicate invalid cache_element */ >+ const apr_uint32_t seconds = apr_time_sec(request_time) & SECONDS_MASK; >+ volatile cached_request_time * const cache_element = >+ &(cache[seconds & TIME_CACHE_MASK]); >+ /* The cache is implemented as a ring buffer. Each second, >+ * it uses a different element in the buffer. The timestamp >+ * in the element indicates whether the element contains the >+ * time string for the current second (vs the time >+ * 'now - AP_TIME_RECENT_THRESHOLD' seconds ago). If the >+ * cached value is for the current time, we copy the time string. >+ * After copying, we check the cache_element to see if it still has the >+ * same second. If so, the copy is valid, because we always set the key >+ * after copying the time string into the cache, and we're using >+ * memory barriers (implemented with Compare-And-Swap) >+ * that guarantee total memory ordering. >+ */ >+ const apr_uint32_t key = cache_element->key; >+ /* Above is done speculatively, no memory barrier used. >+ * It's doing the same thing as apr_atomic_read32, a read of >+ * memory marked volatile, but without doing the function call. */ >+ if (seconds == key && seconds != 0) { >+ /* seconds==0 may mean cache is uninitialized, so don't use cache */ >+ *timestr_p = cache_element->timestr; >+ /* After copying time string, make sure cache_element >+ * was not marked invalid by another thread beginning an update, >+ * and that cache_element really contained data for our second. >+ * Requires memory barrier, so use CAS. */ >+ if (apr_atomic_cas32(&cache_element->key, seconds, seconds) >+ == seconds) >+ { >+ return timestr_p->str; >+ } >+ } >+ /* Invalid cache element, so calculate the time string value. >+ This is a wait-free algorithm, and we purposely don't spin and >+ retry to get from the cache, we just continue and calculate it >+ and do useful work, instead of spinning. */ >+ do { > char sign; > int timz; > >- ap_explode_recent_localtime(&xt, request_time); >+ explode(&xt, request_time); > timz = xt.tm_gmtoff; > if (timz < 0) { > timz = -timz; >@@ -726,19 +770,60 @@ > else { > sign = '+'; > } >- cached_time->t = t_seconds; >- apr_snprintf(cached_time->timestr, DEFAULT_REQUEST_TIME_SIZE, >+ apr_snprintf(timestr_p->str, sizeof(timestr_p->str), > "[%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)) / 60); >- cached_time->t_validate = t_seconds; >- request_time_cache[i] = *cached_time; >+ } while (0); >+ >+ /* Attempt to update the cache */ >+ >+ /* To prevent ABA problem, don't update the cache unless we have a >+ * newer time value (so that we never go from B->A). >+ * Handle cases where seconds overflows (e.g. year 2038), >+ * and cases where cache is uninitialized. >+ * Handle overflow, otherwise it will stop caching after overflow, >+ * until server process is restarted, which may be months later. >+ */ >+#define OVERFLOW (((SECONDS_MASK)>>1) + 1) >+ if (key <= SECONDS_MASK /* another thread not updating cache_element */ >+ && seconds != 0 /* new key distinguishable from uninitialized */ >+ && ( >+ (seconds > key && seconds - key < OVERFLOW) || /* normal */ >+ (seconds < key && key - seconds > OVERFLOW) || /* overflow */ >+ (key == 0 && seconds < SECONDS_MASK - 0x100))) >+ /* cache is perhaps uninitialized, and not recent overflow */ >+ { >+ if (key == apr_atomic_cas32(&cache_element->key, ~seconds, key)) >+ { /* We won the race to update this cache_element. >+ * Above marks cache_element as invalid by using ~seconds, >+ * because we are starting an update: it's the start of a >+ * transaction. */ >+ cache_element->timestr = *timestr_p; >+ /* Finished copying, now update key with our key, >+ * ending the transaction. Need to use CAS for the >+ * memory barrier. >+ */ >+ apr_atomic_cas32(&cache_element->key, seconds, ~seconds); >+ } > } >- return cached_time->timestr; >+ return timestr_p->str; > } > } > >+static const char *log_request_time_lt(request_rec *r, char *a) >+{ >+ return log_request_time(r, a, >+ request_time_cache_lt, &ap_explode_recent_localtime); >+} >+ >+static const char *log_request_time_gmt(request_rec *r, char *a) >+{ >+ return log_request_time(r, a, >+ request_time_cache_gmt, &ap_explode_recent_gmt); >+} >+ > static const char *log_request_duration(request_rec *r, char *a) > { > apr_time_t duration = get_request_end_time(r) - r->request_time; >@@ -1646,7 +1731,8 @@ > log_pfn_register(p, "A", log_local_address, 0 ); > log_pfn_register(p, "l", log_remote_logname, 0); > log_pfn_register(p, "u", log_remote_user, 0); >- log_pfn_register(p, "t", log_request_time, 0); >+ log_pfn_register(p, "t", log_request_time_lt, 0); >+ log_pfn_register(p, "g", log_request_time_gmt, 0); > log_pfn_register(p, "f", log_request_file, 0); > log_pfn_register(p, "b", clf_log_bytes_sent, 0); > log_pfn_register(p, "B", log_bytes_sent, 0); View Attachment As Diff View Attachment As Raw

This is ASF Bugzilla: the Apache Software Foundation bug system. In case of problems with the functioning of ASF Bugzilla, please contact bugzilla-admin@apache.org. Please Note: this e-mail address is only for reporting problems with ASF Bugzilla. Mail about any other subject will be silently ignored.

• • Home
  • | New
  • | Browse
  • | Search
  • |
    [?]
  • | Reports
  • | Help
  • | New Account
  • | Log In
    Remember [x]
  • | Forgot Password
    Login: [x]