From ef2d04f0f3f1f3752bbfaf877cf2f8b9057dd56b Mon Sep 17 00:00:00 2001 From: Eric Covener Date: Tue, 7 Apr 2015 19:01:16 +0000 Subject: [PATCH] allow time to first byte (of response headers) to be logged by mod_logio. mod_logio was just a conveninent place to do this w/o writing a new filter or complicating an existing important one. git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1671918 13f79535-47bb-0310-9956-ffa450edef68 --- CHANGES | 3 ++ docs/manual/mod/mod_logio.xml | 23 +++++++++++ modules/loggers/mod_logio.c | 75 +++++++++++++++++++++++++++++++++-- 3 files changed, 98 insertions(+), 3 deletions(-) diff --git a/CHANGES b/CHANGES index 2f1276771e..4aec913aa7 100644 --- a/CHANGES +++ b/CHANGES @@ -1,6 +1,9 @@ -*- coding: utf-8 -*- Changes with Apache 2.5.0 + *) mod_logio: Add LogIOTrackTTFB and %^FB logformat to log the time + taken to start writing response headers. [Eric Covener] + *) http: Add support for RFC2324/RFC7168. [Graham Leggett] *) mod_proxy_wstunnel: Avoid an empty response by failing with 502 (Bad diff --git a/docs/manual/mod/mod_logio.xml b/docs/manual/mod/mod_logio.xml index 553ec2b5b7..1c24ed5924 100644 --- a/docs/manual/mod/mod_logio.xml +++ b/docs/manual/mod/mod_logio.xml @@ -72,6 +72,12 @@ Bytes transferred (received and sent), including request and headers, cannot be zero. This is the combination of %I and %O.
Available in Apache 2.4.7 and later + + %^FB + Delay in microseconds between when the request arrived and the + first byte of the response headers are written. Only available if + LogIOTrackTTFB is set to ON. +

Usually, the functionality is used like this:

@@ -83,4 +89,21 @@ + +LogIOTrackTTFB +Enable tracking of time to first byte (TTFB) +LogIOTrackTTFB ON|OFF +LogIOTrackTTFB OFF +server configvirtual host +directory.htaccess +none + + +

This directive configures whether this module tracks the delay + between the request being read and the first byte of the response + headers being written. The resulting value may be logged with the + %^FB format.

+ + + diff --git a/modules/loggers/mod_logio.c b/modules/loggers/mod_logio.c index 359d467359..77071f405c 100644 --- a/modules/loggers/mod_logio.c +++ b/modules/loggers/mod_logio.c @@ -33,6 +33,7 @@ #include "http_config.h" #include "http_connection.h" #include "http_protocol.h" +#include "http_request.h" module AP_MODULE_DECLARE_DATA logio_module; @@ -46,8 +47,15 @@ typedef struct logio_config_t { apr_off_t bytes_in; apr_off_t bytes_out; apr_off_t bytes_last_request; + apr_time_t ttfb; + request_rec *r; /* Use for TTFB only */ + int first_byte_seen:1; } logio_config_t; +typedef struct logio_dirconf_t { + int track_ttfb:1; +} logio_dirconf_t; + /* * Optional function for the core to add to bytes_out */ @@ -55,8 +63,20 @@ typedef struct logio_config_t { static void ap_logio_add_bytes_out(conn_rec *c, apr_off_t bytes) { logio_config_t *cf = ap_get_module_config(c->conn_config, &logio_module); - cf->bytes_out += bytes; + + if (!cf->first_byte_seen) { + /* cleared during log_transaction, after mod_log_config */ + cf->first_byte_seen = 1; + + if (cf->r) { + logio_dirconf_t *conf = (logio_dirconf_t*) + ap_get_module_config(cf->r->per_dir_config, &logio_module); + if (conf && conf->track_ttfb) { + cf->ttfb = apr_time_now() - cf->r->request_time; + } + } + } } /* @@ -110,6 +130,17 @@ static const char *log_bytes_combined(request_rec *r, char *a) return apr_off_t_toa(r->pool, cf->bytes_out + cf->bytes_in); } +static const char *log_ttfb(request_rec *r, char *a) +{ + logio_config_t *cf = ap_get_module_config(r->connection->conn_config, + &logio_module); + + if (!cf->first_byte_seen || !cf->ttfb) { + return "-"; + } + + return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, cf->ttfb); +} /* * Reset counters after logging... */ @@ -123,6 +154,20 @@ static int logio_transaction(request_rec *r) cf->bytes_last_request = cf->bytes_in + cf->bytes_out; cf->bytes_in = cf->bytes_out = 0; + cf->r = NULL; + cf->ttfb = 0; + cf->first_byte_seen = 0; + + return OK; +} + +static int logio_post_read_request(request_rec *r) +{ + logio_config_t *cf = ap_get_module_config(r->connection->conn_config, + &logio_module); + if (cf) { + cf->r = r; + } return OK; } @@ -175,17 +220,41 @@ static int logio_pre_config(apr_pool_t *p, apr_pool_t *plog, apr_pool_t *ptemp) log_pfn_register(p, "I", log_bytes_in, 0); log_pfn_register(p, "O", log_bytes_out, 0); log_pfn_register(p, "S", log_bytes_combined, 0); + log_pfn_register(p, "^FB", log_ttfb, 0); } return OK; } +static const char *logio_track_ttfb(cmd_parms *cmd, void *in_dir_config, int arg) +{ + logio_dirconf_t *dir_config = in_dir_config; + dir_config->track_ttfb = arg; + return NULL; +} + +static void *create_logio_dirconf (apr_pool_t *p, char *dummy) +{ + logio_dirconf_t *new = + (logio_dirconf_t *) apr_pcalloc(p, sizeof(logio_dirconf_t)); + return (void *) new; +} + + +static const command_rec logio_cmds[] = { + AP_INIT_FLAG ("LogIOTrackTTFB", logio_track_ttfb, NULL, OR_ALL, + "Set to 'ON' to enable tracking time to first byte"), + {NULL} +}; + + static void register_hooks(apr_pool_t *p) { static const char *pre[] = { "mod_log_config.c", NULL }; ap_hook_pre_connection(logio_pre_conn, NULL, NULL, APR_HOOK_MIDDLE); ap_hook_pre_config(logio_pre_config, NULL, NULL, APR_HOOK_REALLY_FIRST); + ap_hook_post_read_request(logio_post_read_request, NULL, NULL, APR_HOOK_MIDDLE); ap_hook_log_transaction(logio_transaction, pre, NULL, APR_HOOK_MIDDLE); ap_register_input_filter(logio_filter_name, logio_in_filter, NULL, @@ -199,10 +268,10 @@ static void register_hooks(apr_pool_t *p) AP_DECLARE_MODULE(logio) = { STANDARD20_MODULE_STUFF, - NULL, /* create per-dir config */ + create_logio_dirconf, /* create per-dir config */ NULL, /* merge per-dir config */ NULL, /* server config */ NULL, /* merge server config */ - NULL, /* command apr_table_t */ + logio_cmds, /* command apr_table_t */ register_hooks /* register hooks */ }; -- 2.40.0