Skip to content

Commit 1a5f7c2

Browse files
rainerjungrainerjung
committed
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
1 parent 63db365 commit 1a5f7c2

5 files changed

Lines changed: 165 additions & 32 deletions

File tree

‎docs/manual/logs.html.en‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -285,10 +285,12 @@
285285
second = 2*digit<br />
286286
zone = (`+' | `-') 4*digit</code>
287287
</p>
288-
It is possible to have the time displayed in another format
288+
<p>It is possible to have the time displayed in another format
289289
by specifying <code>%{format}t</code> in the log format
290-
string, where <code>format</code> is as in
291-
<code>strftime(3)</code> from the C standard library.
290+
string, where <code>format</code> is either as in
291+
<code>strftime(3)</code> from the C standard library,
292+
or one of the supported special tokens. For details see
293+
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>
292294
</dd>
293295

294296
<dt><code>"GET /apache_pb.gif HTTP/1.0"</code>

‎docs/manual/logs.xml‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -308,10 +308,13 @@
308308
second = 2*digit<br />
309309
zone = (`+' | `-') 4*digit</code>
310310
</p>
311-
It is possible to have the time displayed in another format
311+
<p>It is possible to have the time displayed in another format
312312
by specifying <code>%{format}t</code> in the log format
313-
string, where <code>format</code> is as in
314-
<code>strftime(3)</code> from the C standard library.
313+
string, where <code>format</code> is either as in
314+
<code>strftime(3)</code> from the C standard library,
315+
or one of the supported special tokens. For details see
316+
the <module>mod_log_config</module> <a
317+
href="mod/mod_log_config.html#formats">format strings</a>.</p>
315318
</dd>
316319

317320
<dt><code>"GET /apache_pb.gif HTTP/1.0"</code>

‎docs/manual/mod/mod_log_config.html.en‎

Lines changed: 18 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -158,7 +158,24 @@
158158
format)</td></tr>
159159
<tr><td><code>%{<var>format</var>}t</code></td>
160160
<td>The time, in the form given by format, which should be in
161-
<code>strftime(3)</code> format. (potentially localized)</td></tr>
161+
an extended <code>strftime(3)</code> format (potentially localized).
162+
If the format starts with <code>begin:</code> (default) the time is taken
163+
at the beginning of the request processing, if it starts with
164+
<code>end:</code> it is the time when the log entry gets written, so
165+
close to the end of the request processing. In addition to the formats
166+
supported by <code>strftime(3)</code>, the following format tokens are
167+
supported:
168+
<table>
169+
<tr><td><code>sec</code></td><td>number of seconds since the Epoch</td></tr>
170+
<tr><td><code>msec</code></td><td>number of milliseconds since the Epoch</td></tr>
171+
<tr><td><code>usec</code></td><td>number of microseconds since the Epoch</td></tr>
172+
<tr><td><code>msec_frac</code></td><td>millisecond fraction</td></tr>
173+
<tr><td><code>usec_frac</code></td><td>microsecond fraction</td></tr>
174+
</table>
175+
These tokens can not be combined with each other or <code>strftime(3)</code>
176+
formatting in the same format string. You can use multiple
177+
<code>%{<var>format</var>}t</code> tokens instead.
178+
</td></tr>
162179
<tr class="odd"><td><code>%T</code></td>
163180
<td>The time taken to serve the request, in seconds.</td></tr>
164181
<tr><td><code>%u</code></td>

‎docs/manual/mod/mod_log_config.xml‎

Lines changed: 18 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -173,7 +173,24 @@
173173

174174
<tr><td><code>%{<var>format</var>}t</code></td>
175175
<td>The time, in the form given by format, which should be in
176-
<code>strftime(3)</code> format. (potentially localized)</td></tr>
176+
an extended <code>strftime(3)</code> format (potentially localized).
177+
If the format starts with <code>begin:</code> (default) the time is taken
178+
at the beginning of the request processing, if it starts with
179+
<code>end:</code> it is the time when the log entry gets written, so
180+
close to the end of the request processing. In addition to the formats
181+
supported by <code>strftime(3)</code>, the following format tokens are
182+
supported:
183+
<table>
184+
<tr><td><code>sec</code></td><td>number of seconds since the Epoch</td></tr>
185+
<tr><td><code>msec</code></td><td>number of milliseconds since the Epoch</td></tr>
186+
<tr><td><code>usec</code></td><td>number of microseconds since the Epoch</td></tr>
187+
<tr><td><code>msec_frac</code></td><td>millisecond fraction</td></tr>
188+
<tr><td><code>usec_frac</code></td><td>microsecond fraction</td></tr>
189+
</table>
190+
These tokens can not be combined with each other or <code>strftime(3)</code>
191+
formatting in the same format string. You can use multiple
192+
<code>%{<var>format</var>}t</code> tokens instead.
193+
</td></tr>
177194

178195
<tr><td><code>%T</code></td>
179196
<td>The time taken to serve the request, in seconds.</td></tr>

‎modules/loggers/mod_log_config.c‎

Lines changed: 118 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -265,6 +265,14 @@ typedef struct {
265265
char *condition_var;
266266
} config_log_state;
267267

268+
/*
269+
* log_request_state holds request specific log data that is not
270+
* part of the request_rec.
271+
*/
272+
typedef struct {
273+
apr_time_t request_end_time;
274+
} log_request_state;
275+
268276
/*
269277
* Format items...
270278
* Note that many of these could have ap_sprintfs replaced with static buffers.
@@ -555,50 +563,130 @@ typedef struct {
555563
unsigned t_validate;
556564
} cached_request_time;
557565

566+
#define TIME_FMT_CUSTOM 0
567+
#define TIME_FMT_CLF 1
568+
#define TIME_FMT_ABS_SEC 2
569+
#define TIME_FMT_ABS_MSEC 3
570+
#define TIME_FMT_ABS_USEC 4
571+
#define TIME_FMT_ABS_MSEC_FRAC 5
572+
#define TIME_FMT_ABS_USEC_FRAC 6
573+
558574
#define TIME_CACHE_SIZE 4
559575
#define TIME_CACHE_MASK 3
560576
static cached_request_time request_time_cache[TIME_CACHE_SIZE];
561577

578+
static apr_time_t get_request_end_time(request_rec *r)
579+
{
580+
log_request_state *state = (log_request_state *)ap_get_module_config(r->request_config,
581+
&log_config_module);
582+
if (state->request_end_time == 0) {
583+
state->request_end_time = apr_time_now();
584+
}
585+
return state->request_end_time;
586+
}
587+
588+
562589
static const char *log_request_time(request_rec *r, char *a)
563590
{
564591
apr_time_exp_t xt;
592+
apr_time_t request_time = r->request_time;
593+
int fmt_type = TIME_FMT_CUSTOM;
594+
char *fmt = a;
595+
596+
if (fmt && *fmt) {
597+
if (!strncmp(fmt, "begin", 5)) {
598+
fmt += 5;
599+
if (!*fmt) {
600+
fmt_type = TIME_FMT_CLF;
601+
}
602+
else if (*fmt == ':') {
603+
fmt++;
604+
a = fmt;
605+
}
606+
}
607+
else if (!strncmp(fmt, "end", 3)) {
608+
fmt += 3;
609+
if (!*fmt) {
610+
request_time = get_request_end_time(r);
611+
fmt_type = TIME_FMT_CLF;
612+
}
613+
else if (*fmt == ':') {
614+
fmt++;
615+
a = fmt;
616+
request_time = get_request_end_time(r);
617+
}
618+
}
619+
if (!strncmp(fmt, "msec", 4)) {
620+
fmt += 4;
621+
if (!*fmt) {
622+
fmt_type = TIME_FMT_ABS_MSEC;
623+
}
624+
else if (!strcmp(fmt, "_frac")) {
625+
fmt_type = TIME_FMT_ABS_MSEC_FRAC;
626+
}
627+
}
628+
else if (!strncmp(fmt, "usec", 4)) {
629+
fmt += 4;
630+
if (!*fmt) {
631+
fmt_type = TIME_FMT_ABS_USEC;
632+
}
633+
else if (!strcmp(fmt, "_frac")) {
634+
fmt_type = TIME_FMT_ABS_USEC_FRAC;
635+
}
636+
}
637+
else if (!strcmp(fmt, "sec")) {
638+
fmt_type = TIME_FMT_ABS_SEC;
639+
}
640+
else if (!*fmt) {
641+
fmt_type = TIME_FMT_CLF;
642+
}
643+
}
644+
else {
645+
fmt_type = TIME_FMT_CLF;
646+
}
565647

566-
/* ### I think getting the time again at the end of the request
567-
* just for logging is dumb. i know it's "required" for CLF.
568-
* folks writing log parsing tools don't realise that out of order
569-
* times have always been possible (consider what happens if one
570-
* process calculates the time to log, but then there's a context
571-
* switch before it writes and before that process is run again the
572-
* log rotation occurs) and they should just fix their tools rather
573-
* than force the server to pay extra cpu cycles. if you've got
574-
* a problem with this, you can set the define. -djg
575-
*/
576-
if (a && *a) { /* Custom format */
648+
if (fmt_type >= TIME_FMT_ABS_SEC) { /* Absolute (micro-/milli-)second time
649+
* or msec/usec fraction
650+
*/
651+
char* buf = apr_palloc(r->pool, 20);
652+
switch (fmt_type) {
653+
case TIME_FMT_ABS_SEC:
654+
apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, apr_time_sec(request_time));
655+
break;
656+
case TIME_FMT_ABS_MSEC:
657+
apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, apr_time_as_msec(request_time));
658+
break;
659+
case TIME_FMT_ABS_USEC:
660+
apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, request_time);
661+
break;
662+
case TIME_FMT_ABS_MSEC_FRAC:
663+
apr_snprintf(buf, 20, "%03" APR_TIME_T_FMT, apr_time_msec(request_time));
664+
break;
665+
case TIME_FMT_ABS_USEC_FRAC:
666+
apr_snprintf(buf, 20, "%06" APR_TIME_T_FMT, apr_time_usec(request_time));
667+
break;
668+
default:
669+
return "-";
670+
}
671+
return buf;
672+
}
673+
else if (fmt_type == TIME_FMT_CUSTOM) { /* Custom format */
577674
/* The custom time formatting uses a very large temp buffer
578675
* on the stack. To avoid using so much stack space in the
579676
* common case where we're not using a custom format, the code
580677
* for the custom format in a separate function. (That's why
581678
* log_request_time_custom is not inlined right here.)
582679
*/
583-
#ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
584-
ap_explode_recent_localtime(&xt, apr_time_now());
585-
#else
586-
ap_explode_recent_localtime(&xt, r->request_time);
587-
#endif
680+
ap_explode_recent_localtime(&xt, request_time);
588681
return log_request_time_custom(r, a, &xt);
589682
}
590-
else { /* CLF format */
683+
else { /* CLF format */
591684
/* This code uses the same technique as ap_explode_recent_localtime():
592685
* optimistic caching with logic to detect and correct race conditions.
593686
* See the comments in server/util_time.c for more information.
594687
*/
595688
cached_request_time* cached_time = apr_palloc(r->pool,
596689
sizeof(*cached_time));
597-
#ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
598-
apr_time_t request_time = apr_time_now();
599-
#else
600-
apr_time_t request_time = r->request_time;
601-
#endif
602690
unsigned t_seconds = (unsigned)apr_time_sec(request_time);
603691
unsigned i = t_seconds & TIME_CACHE_MASK;
604692
*cached_time = request_time_cache[i];
@@ -635,14 +723,14 @@ static const char *log_request_time(request_rec *r, char *a)
635723

636724
static const char *log_request_duration(request_rec *r, char *a)
637725
{
638-
apr_time_t duration = apr_time_now() - r->request_time;
726+
apr_time_t duration = get_request_end_time(r) - r->request_time;
639727
return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, apr_time_sec(duration));
640728
}
641729

642730
static const char *log_request_duration_microseconds(request_rec *r, char *a)
643731
{
644732
return apr_psprintf(r->pool, "%" APR_TIME_T_FMT,
645-
(apr_time_now() - r->request_time));
733+
(get_request_end_time(r) - r->request_time));
646734
}
647735

648736
/* These next two routines use the canonical name:port so that log
@@ -1021,6 +1109,12 @@ static int multi_log_transaction(request_rec *r)
10211109
config_log_state *clsarray;
10221110
int i;
10231111

1112+
/*
1113+
* Initialize per request state
1114+
*/
1115+
log_request_state *state = apr_pcalloc(r->pool, sizeof(log_request_state));
1116+
ap_set_module_config(r->request_config, &log_config_module, state);
1117+
10241118
/*
10251119
* Log this transaction..
10261120
*/

0 commit comments

Comments
 (0)