Mailing-List: contact dev-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@httpd.apache.org
MIME-Version: 1.0
In-Reply-To: 
 <CAKQ1sVOYWfQKy_7xeMQu5b4oF_K5gTFk-MVhyWfZFxwtJWNKow@mail.gmail.com>
References: 
 <CALK=YjNBfLP+U6Ct5332RHQ9HkdfLENgoANF3ifoYwjkhT4O2g@mail.gmail.com>
	<CALK=YjMPKAZH3L3iR8x06c9iSVg9NyiOKPp3iSs7Cnk4Mzjw1A@mail.gmail.com>
	<CAKQ1sVN_4RCp+3W1ucpgNmRAyEiEffSQfxGbLCwc303b8oz9yw@mail.gmail.com>
	<CALK=YjMTGyjxN_Ag3avmYF2-mnm3ctRi16QyxpjB3q6YcF-waw@mail.gmail.com>
	<CAKQ1sVMA-0KjWUUohQnwfC0xLFi_4Vd_+ORySER=k4KpWzgPhQ@mail.gmail.com>
	<CALK=YjOySY5pkBCCEC96CKvsNufiBD5fqT-1Ba_6k4cLzKfiZA@mail.gmail.com>
	<CAKQ1sVNUfvP2s=7p=UWPNCm79DYTjMw7z2pBwB9jKYyG=pm+Fg@mail.gmail.com>
	<CALK=YjMaEvJgyQyPSOcdpP-hEwitR+O2JEs36gLd+YXipwsr7Q@mail.gmail.com>
	<CAKQ1sVPErPK_XeChmOTmvKPEdR4kd3QYxgQSL5UzF0HVEetkzw@mail.gmail.com>
	<CAKQ1sVNFi1fmrGoA1QkFmWF1AH4xFMnQCr9=aR-cer2QgM_9GA@mail.gmail.com>
	<CALK=YjO9UzwFaY5tGGy=tv1TLHgzYgY2RO06hQtBfWd3ow9hKA@mail.gmail.com>
	<CALK=YjM1VwAJC9SDEdwOjrvXx99KH5+BW8MeRE=KisY=uRLGHw@mail.gmail.com>
	<CALK=YjOyZZDATkV5rAVof0Ab6MCyVsnSQaLBRrGYQ0uDtOq2tQ@mail.gmail.com>
	<CAKQ1sVOYWfQKy_7xeMQu5b4oF_K5gTFk-MVhyWfZFxwtJWNKow@mail.gmail.com>
Date: Thu, 24 Sep 2015 18:22:16 -0400
Message-ID: 
 <CALK=YjPGOqHRfB1w+1iTMsxDwRzbnkrcLJppmLekmzWNTnDP8A@mail.gmail.com>
Subject: Re: logio problem with SSL
From: Eric Covener <covener@gmail.com>
To: Apache HTTP Server Development List <dev@httpd.apache.org>
Content-Type: text/plain; charset=UTF-8

On Thu, Sep 24, 2015 at 5:13 PM, Yann Ylavic <ylavic.dev@gmail.com> wrote:
> On Thu, Sep 24, 2015 at 10:22 PM, Eric Covener <covener@gmail.com> wrote:
>> On Thu, Sep 24, 2015 at 2:07 PM, Eric Covener <covener@gmail.com> wrote:
>>> First pass at removing having that stuff live in conn_rec by a filter
>>> that removes itself the first time it's called:
>>>
>>> http://people.apache.org/~covener/patches/logio-filter.c
>>>
>>> Does not affect the status quo ordering problem where we might log a
>>> transaction, then see the first bytes of the response go out.
>>>
>>> On Thu, Sep 24, 2015 at 1:50 PM, Eric Covener <covener@gmail.com> wrote:
>>>> On Thu, Sep 24, 2015 at 1:04 PM, Yann Ylavic <ylavic.dev@gmail.com> wrote:
>>>>> And likewise cf->r = NULL in the logio_transaction() of the
>>>>> queued/destroyed request may kill the cfg->r set by the new request's
>>>>> logio_post_read_request() in the meantime.
>>>>
>>>> I guess this is broken without an output filter (vs re-using the
>>>> add_bytes optional function)
>>
>> tried to improve here: http://svn.apache.org/viewvc?rev=1705134&view=rev
>
> Nice patch, I was thinking: too bad we need a mutex here :)
>
> How you measure things, network traces vs some custom log timestamp?
> What does the following say?
>
> Index: server/core_filters.c
> ===================================================================
> --- server/core_filters.c    (revision 1705125)
> +++ server/core_filters.c    (working copy)
> @@ -792,6 +792,19 @@ static apr_status_t send_brigade_blocking(apr_sock
>      return rv;
>  }
>
> +static request_rec *get_r(apr_bucket_brigade *bb)
> +{
> +    apr_bucket *e;
> +    for (e = APR_BRIGADE_FIRST(bb);
> +         e != APR_BRIGADE_SENTINEL(bb);
> +         e = APR_BUCKET_NEXT(e)) {
> +        if (AP_BUCKET_IS_EOR(e)) {
> +            return e->data;
> +        }
> +    }
> +    return NULL;
> +}
> +
>  static apr_status_t writev_nonblocking(apr_socket_t *s,
>                                         struct iovec *vec, apr_size_t nvec,
>                                         apr_bucket_brigade *bb,
> @@ -819,6 +832,9 @@ static apr_status_t writev_nonblocking(apr_socket_
>      while (bytes_written < bytes_to_write) {
>          apr_size_t n = 0;
>          rv = apr_socket_sendv(s, vec + offset, nvec - offset, &n);
> +        ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, c,
> +                      "req:%pp: sent %" APR_SIZE_T_FMT " bytes",
> +                      get_r(bb), n);
>          if (n > 0) {
>              bytes_written += n;
>              for (i = offset; i < nvec; ) {
> Index: server/eor_bucket.c
> ===================================================================
> --- server/eor_bucket.c    (revision 1705125)
> +++ server/eor_bucket.c    (working copy)
> @@ -32,6 +32,8 @@ static apr_status_t eor_bucket_cleanup(void *data)
>          b->data = NULL;
>          /* Update child status and log the transaction */
>          ap_update_child_status(r->connection->sbh, SERVER_BUSY_LOG, r);
> +        ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, r->connection,
> +                      "req:%pp: log_transaction", r);
>          ap_run_log_transaction(r);
>          if (ap_extended_status) {
>              ap_increment_counts(r->connection->sbh, r);
> --

two logs (http/https) sorted to top of autoindex here:
http://people.apache.org/~covener/

Narrow logio issue working good now, because our first filter
invocation is not delayed like the "addbytes" callback was.