From: Eric Covener Date: Wed, 15 Apr 2015 17:59:42 +0000 (+0000) Subject: Merge r1671918, r1673113 from trunk: X-Git-Tag: 2.4.13~222 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=cacc36b234de0d1faf7dc5ad726ed701017e7913;p=apache Merge r1671918, r1673113 from trunk: 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. Use 'unsigned int' in bitfield git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/branches/2.4.x@1673904 13f79535-47bb-0310-9956-ffa450edef68 --- diff --git a/CHANGES b/CHANGES index 6f3dac62df..4bbabc753d 100644 --- a/CHANGES +++ b/CHANGES @@ -12,6 +12,9 @@ Changes with Apache 2.4.13 calls r:wsupgrade() can cause a child process crash. [Edward Lu ] + *) mod_logio: Add LogIOTrackTTFB and %^FB logformat to log the time + taken to start writing response headers. [Eric Covener] + *) mod_ssl: Avoid compilation errors with LibreSSL related to the use of ENGINE_CTRL_CHIL_SET_FORKCHECK. [Stuart Henderson ] diff --git a/STATUS b/STATUS index 949e03ebf7..6185342395 100644 --- a/STATUS +++ b/STATUS @@ -111,12 +111,6 @@ PATCHES ACCEPTED TO BACKPORT FROM TRUNK: 2.4.x patch: trunk works (modulo CHANGES) +1: ylavic, rjung, trawick - *) mod_logio: Log time-to-first-byte via %^FB - trunk patch: http://svn.apache.org/r1671918 - http://svn.apache.org/r1673113 - 2.4.x patch: trunk works (modulo CHANGES) - +1: covener, ylavic, trawick - *) mod_cgi, mod_cgid: If both modules get installed, use IfModule for MPM to LoadModule mod_cgi for prefork and mod_cgid for all other MPMs. PR 57379. 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..ab922e30c6 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 */ + unsigned int first_byte_seen:1; } logio_config_t; +typedef struct logio_dirconf_t { + unsigned 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 */ };