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 6f3dac62df90050b88fae87ebceb67f13aae76a5..4bbabc753d3d1e953a55b6cf198c18d4264e100f 100644 (file)
--- 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 <Chaosed0 gmail.com>]
 
+  *) 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 <sthen openbsd.org>]

diff --git a/STATUS b/STATUS
index 949e03ebf7184cb2a27aa55e7e5f8d41a8906ceb..6185342395608abedc238fe7b0e6af1913adb303 100644 (file)
--- 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 553ec2b5b75931c93198489c80c18d337d87bb13..1c24ed592412dfab99626d025c3234681d0128fb 100644 (file)
--- 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 359d467359359ea7fb53d5d5993ee8a873eb9c77..ab922e30c62d5d595983990d9d4015c371de07bc 100644 (file)
--- 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 */
 };