www/apache
1
0
Fork 0
mirror of https://github.com/apache/httpd.git synced 2026-01-06 09:01:14 +03:00
Code Activity

Adding sub second timestamps and request end time to mod_log_config.

Browse Source 
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
This commit is contained in:
Rainer Jung
2010-07-25 21:08:15 +00:00
parent 74c494fbf2
commit 0fa11f3ff9
5 changed files with 165 additions and 32 deletions
Download Patch File Download Diff File Expand all files Collapse all files

8
docs/manual/logs.html.en
View File

@@ -285,10 +285,12 @@
second = 2*digit<br />
zone = (`+' | `-') 4*digit</code>
</p>
It is possible to have the time displayed in another format
<p>It is possible to have the time displayed in another format
by specifying <code>%{format}t</code> in the log format
string, where <code>format</code> is as in
<code>strftime(3)</code> from the C standard library.
string, where <code>format</code> is either as in
<code>strftime(3)</code> from the C standard library,
or one of the supported special tokens. For details see
the <code class="module"><a href="./mod/mod_log_config.html">mod_log_config</a></code> <a href="mod/mod_log_config.html#formats">format strings</a>.</p>
</dd>
<dt><code>"GET /apache_pb.gif HTTP/1.0"</code>

9
docs/manual/logs.xml
View File

@@ -308,10 +308,13 @@
second = 2*digit<br />
zone = (`+' | `-') 4*digit</code>
</p>
It is possible to have the time displayed in another format
<p>It is possible to have the time displayed in another format
by specifying <code>%{format}t</code> in the log format
string, where <code>format</code> is as in
<code>strftime(3)</code> from the C standard library.
string, where <code>format</code> is either as in
<code>strftime(3)</code> from the C standard library,
or one of the supported special tokens. For details see
the <module>mod_log_config</module> <a
href="mod/mod_log_config.html#formats">format strings</a>.</p>
</dd>
<dt><code>"GET /apache_pb.gif HTTP/1.0"</code>

19
docs/manual/mod/mod_log_config.html.en
View File

@@ -158,7 +158,24 @@
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>

19
docs/manual/mod/mod_log_config.xml
View File

@@ -173,7 +173,24 @@
<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>

142
modules/loggers/mod_log_config.c
View File

@@ -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;
/* ### 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 && *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;
}
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..
*/