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

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 @@
         <td>Bytes transferred (received and sent), including request and headers,
         cannot be zero. This is the combination of %I and %O.<br />
         Available in Apache 2.4.7 and later</td></tr>
+
+    <tr><td><code>%^FB</code></td>
+        <td>Delay in microseconds between when the request arrived and the
+        first byte of the response headers are written.  Only available if 
+        <directive>LogIOTrackTTFB</directive> is set to ON.
+        </td></tr>
     </table>
 
     <p>Usually, the functionality is used like this:</p>
@@ -83,4 +89,21 @@
     </dl>
 </section>
 
+<directivesynopsis>
+<name>LogIOTrackTTFB</name>
+<description>Enable tracking of time to first byte (TTFB)</description>
+<syntax>LogIOTrackTTFB ON|OFF</syntax>
+<default>LogIOTrackTTFB OFF</default>
+<contextlist><context>server config</context><context>virtual host</context>
+<context>directory</context><context>.htaccess</context></contextlist>
+<override>none</override>
+
+<usage>
+    <p>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 
+    <code>%^FB</code> format.</p>
+</usage>
+</directivesynopsis>
+
 </modulesynopsis>
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 */
 };