From: Rainer Jung Date: Sun, 25 Jul 2010 21:08:15 +0000 (+0000) Subject: Adding sub second timestamps and request end time to mod_log_config. X-Git-Tag: 2.3.7~55 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=0fa11f3ff947f8345c82d62cdda3b6f284ea7e89;p=apache Adding sub second timestamps and request end time to mod_log_config. Add special format tokens to %{...}t. The extended syntax allows the form: "WHICH:WHAT". WHICH is either: - "begin": use the time when the request started - "end": take "now" as the time You can omit WHICH, default is "begin". If you omit WHICH, the separating column is not allowed. WHAT is either: - "sec": timestamp in Unix seconds - "msec": timestamp in Unix milliseconds - "msec_frac": millisecond fraction of the Unix timestamp, 3 digits, 0-padded - "usec": timestamp in Unix microseconds - "usec_frac": microsecond fraction of the Unix timestamp 6 digits, 0-padded - anything different from those tokens: use strftime() You can omit WHAT, default is the formatted timestamp as used by the Common Log Format. The implementation uses a new request_config for mod_log_config to pass the request end time around between different calls to log formatters, but the end time is only generated if needed. git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@979120 13f79535-47bb-0310-9956-ffa450edef68 --- diff --git a/docs/manual/logs.html.en b/docs/manual/logs.html.en index 55583589ea..1a1826cc77 100644 --- a/docs/manual/logs.html.en +++ b/docs/manual/logs.html.en @@ -285,10 +285,12 @@ second = 2*digit
zone = (`+' | `-') 4*digit

- It is possible to have the time displayed in another format +

It is possible to have the time displayed in another format by specifying %{format}t in the log format - string, where format is as in - strftime(3) from the C standard library. + string, where format is either as in + strftime(3) from the C standard library, + or one of the supported special tokens. For details see + the mod_log_config format strings.

"GET /apache_pb.gif HTTP/1.0" diff --git a/docs/manual/logs.xml b/docs/manual/logs.xml index 54780b65a6..1007e49cb8 100644 --- a/docs/manual/logs.xml +++ b/docs/manual/logs.xml @@ -308,10 +308,13 @@ second = 2*digit
zone = (`+' | `-') 4*digit

- It is possible to have the time displayed in another format +

It is possible to have the time displayed in another format by specifying %{format}t in the log format - string, where format is as in - strftime(3) from the C standard library. + string, where format is either as in + strftime(3) from the C standard library, + or one of the supported special tokens. For details see + the mod_log_config format strings.

"GET /apache_pb.gif HTTP/1.0" diff --git a/docs/manual/mod/mod_log_config.html.en b/docs/manual/mod/mod_log_config.html.en index 7857603ec0..bac89a5720 100644 --- a/docs/manual/mod/mod_log_config.html.en +++ b/docs/manual/mod/mod_log_config.html.en @@ -158,7 +158,24 @@ format) %{format}t The time, in the form given by format, which should be in - strftime(3) format. (potentially localized) + an extended strftime(3) format (potentially localized). + If the format starts with begin: (default) the time is taken + at the beginning of the request processing, if it starts with + end: it is the time when the log entry gets written, so + close to the end of the request processing. In addition to the formats + supported by strftime(3), the following format tokens are + supported: + + + + + + +
secnumber of seconds since the Epoch
msecnumber of milliseconds since the Epoch
usecnumber of microseconds since the Epoch
msec_fracmillisecond fraction
usec_fracmicrosecond fraction
+ These tokens can not be combined with each other or strftime(3) + formatting in the same format string. You can use multiple + %{format}t tokens instead. + %T The time taken to serve the request, in seconds. %u diff --git a/docs/manual/mod/mod_log_config.xml b/docs/manual/mod/mod_log_config.xml index 90753a6c15..b25f30501e 100644 --- a/docs/manual/mod/mod_log_config.xml +++ b/docs/manual/mod/mod_log_config.xml @@ -173,7 +173,24 @@ %{format}t The time, in the form given by format, which should be in - strftime(3) format. (potentially localized) + an extended strftime(3) format (potentially localized). + If the format starts with begin: (default) the time is taken + at the beginning of the request processing, if it starts with + end: it is the time when the log entry gets written, so + close to the end of the request processing. In addition to the formats + supported by strftime(3), the following format tokens are + supported: + + + + + + +
secnumber of seconds since the Epoch
msecnumber of milliseconds since the Epoch
usecnumber of microseconds since the Epoch
msec_fracmillisecond fraction
usec_fracmicrosecond fraction
+ These tokens can not be combined with each other or strftime(3) + formatting in the same format string. You can use multiple + %{format}t tokens instead. + %T The time taken to serve the request, in seconds. diff --git a/modules/loggers/mod_log_config.c b/modules/loggers/mod_log_config.c index 17d0cad307..7f0085f030 100644 --- a/modules/loggers/mod_log_config.c +++ b/modules/loggers/mod_log_config.c @@ -265,6 +265,14 @@ typedef struct { char *condition_var; } config_log_state; +/* + * log_request_state holds request specific log data that is not + * part of the request_rec. + */ +typedef struct { + apr_time_t request_end_time; +} log_request_state; + /* * Format items... * Note that many of these could have ap_sprintfs replaced with static buffers. @@ -555,50 +563,130 @@ typedef struct { unsigned t_validate; } cached_request_time; +#define TIME_FMT_CUSTOM 0 +#define TIME_FMT_CLF 1 +#define TIME_FMT_ABS_SEC 2 +#define TIME_FMT_ABS_MSEC 3 +#define TIME_FMT_ABS_USEC 4 +#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]; +static apr_time_t get_request_end_time(request_rec *r) +{ + log_request_state *state = (log_request_state *)ap_get_module_config(r->request_config, + &log_config_module); + if (state->request_end_time == 0) { + state->request_end_time = apr_time_now(); + } + return state->request_end_time; +} + + static const char *log_request_time(request_rec *r, char *a) { apr_time_exp_t xt; + apr_time_t request_time = r->request_time; + int fmt_type = TIME_FMT_CUSTOM; + char *fmt = a; + + if (fmt && *fmt) { + if (!strncmp(fmt, "begin", 5)) { + fmt += 5; + if (!*fmt) { + fmt_type = TIME_FMT_CLF; + } + else if (*fmt == ':') { + fmt++; + a = fmt; + } + } + else if (!strncmp(fmt, "end", 3)) { + fmt += 3; + if (!*fmt) { + request_time = get_request_end_time(r); + fmt_type = TIME_FMT_CLF; + } + else if (*fmt == ':') { + fmt++; + a = fmt; + request_time = get_request_end_time(r); + } + } + if (!strncmp(fmt, "msec", 4)) { + fmt += 4; + if (!*fmt) { + fmt_type = TIME_FMT_ABS_MSEC; + } + else if (!strcmp(fmt, "_frac")) { + fmt_type = TIME_FMT_ABS_MSEC_FRAC; + } + } + else if (!strncmp(fmt, "usec", 4)) { + fmt += 4; + if (!*fmt) { + fmt_type = TIME_FMT_ABS_USEC; + } + else if (!strcmp(fmt, "_frac")) { + fmt_type = TIME_FMT_ABS_USEC_FRAC; + } + } + else if (!strcmp(fmt, "sec")) { + fmt_type = TIME_FMT_ABS_SEC; + } + else if (!*fmt) { + fmt_type = TIME_FMT_CLF; + } + } + else { + fmt_type = TIME_FMT_CLF; + } - /* ### I think getting the time again at the end of the request - * just for logging is dumb. i know it's "required" for CLF. - * folks writing log parsing tools don't realise that out of order - * times have always been possible (consider what happens if one - * process calculates the time to log, but then there's a context - * switch before it writes and before that process is run again the - * log rotation occurs) and they should just fix their tools rather - * than force the server to pay extra cpu cycles. if you've got - * a problem with this, you can set the define. -djg - */ - if (a && *a) { /* Custom format */ + if (fmt_type >= TIME_FMT_ABS_SEC) { /* Absolute (micro-/milli-)second time + * or msec/usec fraction + */ + char* buf = apr_palloc(r->pool, 20); + switch (fmt_type) { + case TIME_FMT_ABS_SEC: + apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, apr_time_sec(request_time)); + break; + case TIME_FMT_ABS_MSEC: + apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, apr_time_as_msec(request_time)); + break; + case TIME_FMT_ABS_USEC: + apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, request_time); + break; + case TIME_FMT_ABS_MSEC_FRAC: + apr_snprintf(buf, 20, "%03" APR_TIME_T_FMT, apr_time_msec(request_time)); + break; + case TIME_FMT_ABS_USEC_FRAC: + apr_snprintf(buf, 20, "%06" APR_TIME_T_FMT, apr_time_usec(request_time)); + break; + default: + return "-"; + } + return buf; + } + else if (fmt_type == TIME_FMT_CUSTOM) { /* Custom format */ /* The custom time formatting uses a very large temp buffer * on the stack. To avoid using so much stack space in the * common case where we're not using a custom format, the code * 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 + ap_explode_recent_localtime(&xt, request_time); return log_request_time_custom(r, a, &xt); } - else { /* CLF format */ + 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. */ 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 t_seconds = (unsigned)apr_time_sec(request_time); unsigned i = t_seconds & TIME_CACHE_MASK; *cached_time = request_time_cache[i]; @@ -635,14 +723,14 @@ static const char *log_request_time(request_rec *r, char *a) static const char *log_request_duration(request_rec *r, char *a) { - apr_time_t duration = apr_time_now() - r->request_time; + apr_time_t duration = get_request_end_time(r) - r->request_time; return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, apr_time_sec(duration)); } static const char *log_request_duration_microseconds(request_rec *r, char *a) { return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, - (apr_time_now() - r->request_time)); + (get_request_end_time(r) - r->request_time)); } /* These next two routines use the canonical name:port so that log @@ -1021,6 +1109,12 @@ static int multi_log_transaction(request_rec *r) config_log_state *clsarray; int i; + /* + * Initialize per request state + */ + log_request_state *state = apr_pcalloc(r->pool, sizeof(log_request_state)); + ap_set_module_config(r->request_config, &log_config_module, state); + /* * Log this transaction.. */