Commit 17779bd7 authored by Eric Covener's avatar Eric Covener
Browse files

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
parent 24e7df37

CHANGES

+3 −0
Changes for CHANGES: 3 added lines, 0 removed lines.
Original line number Diff line number Diff line
@@ -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>]

STATUS

+0 −6
Changes for STATUS: 0 added lines, 6 removed lines.
Original line number Diff line number Diff line
@@ -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.

docs/manual/mod/mod_logio.xml

+23 −0
Changes for docs/manual/mod/mod_logio.xml: 23 added lines, 0 removed lines.
Original line number Diff line number Diff line
@@ -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>

modules/loggers/mod_logio.c

+72 −3
Changes for modules/loggers/mod_logio.c: 72 added lines, 3 removed lines.
Original line number Diff line number Diff line
@@ -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 */

};