Re: [PATCH 57300] mod_session save optimization
On 8/20/2015 4:58 PM, Paul Spangler wrote: Hello, The bug report contains a more detailed explanation of the patch, but there are some points I thought might lead to some discussion. First a quick summary of the issue: mod_session writes out the session every request even if there aren't any changes to the data. This makes some sense when the session has a max age and the expiry value needs to be refreshed. However, there isn't likely to be much benefit in repeatedly refreshing the expiry by a few milliseconds, possibly generating database traffic each time. This patch proposes a new directive to define an interval of time where the expiry doesn't need to be refreshed if there are no session data changes. 1. We had a hard time coming up with a name for the directive. The patch goes with SessionExpiryUpdateInterval, being the interval of time that may pass before updating the expiry value is required. I don't know if there are any existing directives with a similar function that we should mimic instead. 2. The patch includes a behavior change independent of the new directive when using sessions without a max age: if the data hasn't changed, don't write out the session. Most noticeably, this means new sessions that never get data are discarded without being saved. 3. I wasn't sure how best to add tests for a new directive since the test server won't start if the directive is missing. The patch that includes the test changes look for the 2.5 version to know the new directive is there, and will require a modification if/when the directive is back-ported to 2.4 to enable the new tests. https://bz.apache.org/bugzilla/show_bug.cgi?id=57300 Thanks for your consideration. Quick ping on this. -- Paul Spangler LabVIEW R&D National Instruments
logio problem with SSL
I am seeing that small responses over SSL get logged before they're flushed, couldn't this flushing be done when we see the EOR bucket in the SSL output filter (which will cause log_transaction to run)? Breakpoint 2, ap_logio_add_bytes_out (c=0x7fc688005428, bytes=249) at mod_logio.c:66 66 logio_config_t *cf = ap_get_module_config(c->conn_config, &logio_module); (gdb) where #0 ap_logio_add_bytes_out (c=0x7fc688005428, bytes=249) at mod_logio.c:66 #1 0x00456875 in writev_nonblocking (s=0x7fc688005210, vec=0x7fc68cbe1590, nvec=1, bb=0x7fc678003198, cumulative_bytes_written=0x7fc674003758, c=0x7fc688005428) at core_filters.c:848 #2 0x00456393 in send_brigade_nonblocking (s=0x7fc688005210, bb=0x7fc678003198, bytes_written=0x7fc674003758, c=0x7fc688005428) at core_filters.c:738 #3 0x00456495 in send_brigade_blocking (s=0x7fc688005210, bb=0x7fc678003198, bytes_written=0x7fc674003758, c=0x7fc688005428) at core_filters.c:767 #4 0x00455a4c in ap_core_output_filter (f=0x7fc6740036b0, new_bb=0x7fc678003198) at core_filters.c:556 #5 0x0043a78e in ap_pass_brigade (next=0x7fc6740036b0, bb=0x7fc678003198) at util_filter.c:590 #6 0x7fc6929c19c3 in bio_filter_out_pass (outctx=0x7fc678003178) at ssl_engine_io.c:139 #7 0x7fc6929c1ada in bio_filter_out_flush (bio=0x7fc6740014e0) at ssl_engine_io.c:160 #8 0x7fc6929c2438 in bio_filter_in_read (bio=0x7fc674004570, in=0x7fc670009ea3 "", inlen=5) at ssl_engine_io.c:477 #9 0x7fc6923f49db in BIO_read () from /home/covener/SRC/openssl/built/lib/libcrypto.so.1.0.0 #10 0x7fc692760bfc in ssl3_read_n () from /home/covener/SRC/openssl/built/lib/libssl.so.1.0.0 #11 0x7fc692762a0d in ssl3_read_bytes () from /home/covener/SRC/openssl/built/lib/libssl.so.1.0.0 #12 0x7fc69275f0db in ssl3_read () from /home/covener/SRC/openssl/built/lib/libssl.so.1.0.0 #13 0x7fc6929c2b43 in ssl_io_input_read (inctx=0x7fc674001588, buf=0x7fc6740015d0 "GET /index.shtml HTTP/1.1\r\nUser-Agent: curl/7.35.0\r\nHost: localhost\r\nAccept: */*\r\n\r\n", '\356' , ..., len=0x7fc68cbe1b10) at ssl_engine_io.c:647 #14 0x7fc6929c4c8f in ssl_io_filter_input (f=0x7fc6740035e0, bb=0x7fc674004118, mode=AP_MODE_SPECULATIVE, block=APR_NONBLOCK_READ, readbytes=1) at ssl_engine_io.c:1443 #15 0x0043a6c9 in ap_get_brigade (next=0x7fc6740035e0, bb=0x7fc674004118, mode=AP_MODE_SPECULATIVE, block=APR_NONBLOCK_READ, readbytes=1) at util_filter.c:553 #16 0x004851f0 in check_pipeline (c=0x7fc688005428, bb=0x7fc674004118) at http_request.c:237 #17 0x00485307 in ap_process_request_after_handler (r=0x7fc6780129f0) at http_request.c:282 #18 0x0048564e in ap_process_async_request (r=0x7fc6780129f0) at http_request.c:363 #19 0x00485679 in ap_process_request (r=0x7fc6780129f0) at http_request.c:373 #20 0x0048190f in ap_process_http_sync_connection (c=0x7fc688005428) at http_core.c:210 #21 0x00481a1b in ap_process_http_connection (c=0x7fc688005428) at http_core.c:251 #22 0x00474977 in ap_run_process_connection (c=0x7fc688005428) at connection.c:41 #23 0x00474ea9 in ap_process_connection (c=0x7fc688005428, csd=0x7fc688005210) at connection.c:206 #24 0x7fc6916c9742 in process_socket (thd=0x18d09f8, p=0x7fc688005188, sock=0x7fc688005210, my_child_num=0, my_thread_num=2, bucket_alloc=0x7fc6780008e8) at worker.c:632 #25 0x7fc6916ca534 in worker_thread (thd=0x18d09f8, dummy=0x7fc688000b80) at worker.c:992 #26 0x7fc6a1e8cfe3 in dummy_worker (opaque=0x18d09f8) at threadproc/unix/thread.c:142 #27 0x7fc6a1c47182 in start_thread (arg=0x7fc68cbe2700) at pthread_create.c:312 #28 0x7fc6a197447d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 (gdb) cont Continuing. -- Eric Covener cove...@gmail.com
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 11:00 AM, Eric Covener wrote: > I am seeing that small responses over SSL get logged before they're > flushed, couldn't this flushing be done when we see the EOR bucket in > the SSL output filter (which will cause log_transaction to run)? Or maybe when the EOR is added, slip a flush bucket in front of it? -- Eric Covener cove...@gmail.com
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 5:06 PM, Eric Covener wrote: > On Thu, Sep 24, 2015 at 11:00 AM, Eric Covener wrote: >> I am seeing that small responses over SSL get logged before they're >> flushed, couldn't this flushing be done when we see the EOR bucket in >> the SSL output filter (which will cause log_transaction to run)? > > > Or maybe when the EOR is added, slip a flush bucket in front of it? Wouldn't disable pipelining (and EOR purpose)? It seems that the culprit is rather bio_filter_out_flush() called from bio_filter_in_read()... Regards, Yann.
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 11:14 AM, Yann Ylavic wrote: > Wouldn't disable pipelining (and EOR purpose)? Didn't consider it / never understood it well. After doing the minimum amt of homework -- maybe check_pipeline could somehow be called early in the EOR cleanup so this kind of flush would occur before the transaction is logged, rather than in ap_process_request_after_handler?
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 5:32 PM, Eric Covener wrote:
> On Thu, Sep 24, 2015 at 11:14 AM, Yann Ylavic wrote:
>> Wouldn't disable pipelining (and EOR purpose)?
>
> Didn't consider it / never understood it well. After doing the minimum
> amt of homework -- maybe check_pipeline could somehow be called early
> in the EOR cleanup so this kind of flush would occur before the
> transaction is logged, rather than in
> ap_process_request_after_handler?
How about:
Index: modules/ssl/ssl_engine_io.c
===
--- modules/ssl/ssl_engine_io.c (revision 1704850)
+++ modules/ssl/ssl_engine_io.c (working copy)
@@ -474,7 +474,8 @@
* output is buffered) so the performance impact of doing it
* unconditionally should be minimal.
*/
-if (bio_filter_out_flush(inctx->bio_out) < 0) {
+if (block == APR_BLOCK_READ &&
+bio_filter_out_flush(inctx->bio_out) < 0) {
bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
inctx->rc = outctx->rc;
return -1;
?
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 11:45 AM, Yann Ylavic wrote:
> On Thu, Sep 24, 2015 at 5:32 PM, Eric Covener wrote:
>> On Thu, Sep 24, 2015 at 11:14 AM, Yann Ylavic wrote:
>>> Wouldn't disable pipelining (and EOR purpose)?
>>
>> Didn't consider it / never understood it well. After doing the minimum
>> amt of homework -- maybe check_pipeline could somehow be called early
>> in the EOR cleanup so this kind of flush would occur before the
>> transaction is logged, rather than in
>> ap_process_request_after_handler?
>
> How about:
> Index: modules/ssl/ssl_engine_io.c
> ===
> --- modules/ssl/ssl_engine_io.c (revision 1704850)
> +++ modules/ssl/ssl_engine_io.c (working copy)
> @@ -474,7 +474,8 @@
> * output is buffered) so the performance impact of doing it
> * unconditionally should be minimal.
> */
> -if (bio_filter_out_flush(inctx->bio_out) < 0) {
> +if (block == APR_BLOCK_READ &&
> +bio_filter_out_flush(inctx->bio_out) < 0) {
> bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
> inctx->rc = outctx->rc;
> return -1;
> ?
I guess I understand your previous comment better, but wouldn't this
mean further delaying the flush, which makes it even farther away from
when the transaction was logged?
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 5:51 PM, Eric Covener wrote:
> On Thu, Sep 24, 2015 at 11:45 AM, Yann Ylavic wrote:
>>
>> How about:
>> Index: modules/ssl/ssl_engine_io.c
>> ===
>> --- modules/ssl/ssl_engine_io.c (revision 1704850)
>> +++ modules/ssl/ssl_engine_io.c (working copy)
>> @@ -474,7 +474,8 @@
>> * output is buffered) so the performance impact of doing it
>> * unconditionally should be minimal.
>> */
>> -if (bio_filter_out_flush(inctx->bio_out) < 0) {
>> +if (block == APR_BLOCK_READ &&
>> +bio_filter_out_flush(inctx->bio_out) < 0) {
>> bio_filter_out_ctx_t *outctx = inctx->bio_out->ptr;
>> inctx->rc = outctx->rc;
>> return -1;
>> ?
>
> I guess I understand your previous comment better, but wouldn't this
> mean further delaying the flush, which makes it even farther away from
> when the transaction was logged?
Yes, this is unrelated to the issue I guess (looks sensible, though).
What I think is destroying the EOR before the flush is the
first/leading remove_empty_buckets() in send_brigade_nonblocking().
Looking if we can get rid of it...
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 11:55 AM, Yann Ylavic wrote: > Yes, this is unrelated to the issue I guess (looks sensible, though). > What I think is destroying the EOR before the flush is the > first/leading remove_empty_buckets() in send_brigade_nonblocking(). > Looking if we can get rid of it... I initially thought this as well, and it resembles something potentially fishy I thought I saw in mod_h2, but I convinced myself it's actually the EOR bucket being read/written in order (but our response bytes are still buffered in openssl) -- Eric Covener cove...@gmail.com
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 5:57 PM, Eric Covener wrote: > > I initially thought this as well, and it resembles something > potentially fishy I thought I saw in mod_h2, but I convinced myself > it's actually the EOR bucket being read/written in order (but our > response bytes are still buffered in openssl) The EOR is supposed to live until the response is flushed (all buffered/previous buckets sent). Until then, the request is still alive and waiting to be logged, yet all its response bytes are accounted with ap_logio_add_bytes() *after* the corresponding apr_socket_send*(). The problem is that mod_logio's cfg->r is not (anymore) reliable when r is in the flush queue, since it may have been replaced by the next request's post_read_request()...
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 6:57 PM, Yann Ylavic wrote: > > The problem is that mod_logio's cfg->r is not (anymore) reliable when > r is in the flush queue, since it may have been replaced by the next > request's post_read_request()... 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.
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 1:04 PM, Yann Ylavic 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)
Re: logio problem with SSL
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 wrote: > On Thu, Sep 24, 2015 at 1:04 PM, Yann Ylavic 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) -- Eric Covener cove...@gmail.com
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 2:07 PM, Eric Covener 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 wrote: >> On Thu, Sep 24, 2015 at 1:04 PM, Yann Ylavic 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
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 10:22 PM, Eric Covener wrote:
> On Thu, Sep 24, 2015 at 2:07 PM, Eric Covener 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 wrote:
>>> On Thu, Sep 24, 2015 at 1:04 PM, Yann Ylavic 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);
--
Re: logio problem with SSL
On Thu, Sep 24, 2015 at 5:13 PM, Yann Ylavic wrote:
> On Thu, Sep 24, 2015 at 10:22 PM, Eric Covener wrote:
>> On Thu, Sep 24, 2015 at 2:07 PM, Eric Covener 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 wrote:
On Thu, Sep 24, 2015 at 1:04 PM, Yann Ylavic 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.
Re: logio problem with SSL
On Fri, Sep 25, 2015 at 12:22 AM, Eric Covener wrote:
>
> 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.
Looks like mod_ssl should also forward EOR buckets.
Does this work:
Index: modules/ssl/ssl_engine_io.c
===
--- modules/ssl/ssl_engine_io.c(revision 1705160)
+++ modules/ssl/ssl_engine_io.c(working copy)
@@ -1707,12 +1707,12 @@ static apr_status_t ssl_io_filter_output(ap_filter
/* If it is a flush or EOS, we need to pass this down.
* These types do not require translation by OpenSSL.
*/
-if (APR_BUCKET_IS_EOS(bucket)) {
+if (APR_BUCKET_IS_EOS(bucket) || AP_BUCKET_IS_EOR(bucket)) {
/*
- * By definition, nothing can come after EOS.
+ * By definition, nothing can come after EOS/EOR.
* which also means we can pass the rest of this brigade
* without creating a new one since it only contains the
- * EOS bucket.
+ * EOS/EOR bucket.
*/
if ((status = ap_pass_brigade(f->next, bb)) != APR_SUCCESS) {
?
