format)</td></tr>
<tr><td><code>%{<var>format</var>}t</code></td>
<td>The time, in the form given by format, which should be in
- <code>strftime(3)</code> format. (potentially localized)</td></tr>
+ an extended <code>strftime(3)</code> format (potentially localized).
+ If the format starts with <code>begin:</code> (default) the time is taken
+ at the beginning of the request processing, if it starts with
+ <code>end:</code> 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 <code>strftime(3)</code>, the following format tokens are
+ supported:
+ <table>
+ <tr><td><code>sec</code></td><td>number of seconds since the Epoch</td></tr>
+ <tr><td><code>msec</code></td><td>number of milliseconds since the Epoch</td></tr>
+ <tr><td><code>usec</code></td><td>number of microseconds since the Epoch</td></tr>
+ <tr><td><code>msec_frac</code></td><td>millisecond fraction</td></tr>
+ <tr><td><code>usec_frac</code></td><td>microsecond fraction</td></tr>
+ </table>
+ These tokens can not be combined with each other or <code>strftime(3)</code>
+ formatting in the same format string. You can use multiple
+ <code>%{<var>format</var>}t</code> tokens instead.
+ </td></tr>
<tr class="odd"><td><code>%T</code></td>
<td>The time taken to serve the request, in seconds.</td></tr>
<tr><td><code>%u</code></td>
<tr><td><code>%{<var>format</var>}t</code></td>
<td>The time, in the form given by format, which should be in
- <code>strftime(3)</code> format. (potentially localized)</td></tr>
+ an extended <code>strftime(3)</code> format (potentially localized).
+ If the format starts with <code>begin:</code> (default) the time is taken
+ at the beginning of the request processing, if it starts with
+ <code>end:</code> 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 <code>strftime(3)</code>, the following format tokens are
+ supported:
+ <table>
+ <tr><td><code>sec</code></td><td>number of seconds since the Epoch</td></tr>
+ <tr><td><code>msec</code></td><td>number of milliseconds since the Epoch</td></tr>
+ <tr><td><code>usec</code></td><td>number of microseconds since the Epoch</td></tr>
+ <tr><td><code>msec_frac</code></td><td>millisecond fraction</td></tr>
+ <tr><td><code>usec_frac</code></td><td>microsecond fraction</td></tr>
+ </table>
+ These tokens can not be combined with each other or <code>strftime(3)</code>
+ formatting in the same format string. You can use multiple
+ <code>%{<var>format</var>}t</code> tokens instead.
+ </td></tr>
<tr><td><code>%T</code></td>
<td>The time taken to serve the request, in seconds.</td></tr>
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.
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];
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
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..
*/
projects / apache / commitdiff