On Wed, Nov 16, 2011 at 11:51 AM, Jeff Trawick <traw...@gmail.com> wrote: > On Wed, Nov 16, 2011 at 11:20 AM, Paul Querna <p...@querna.org> wrote: >> On Wed, Nov 16, 2011 at 2:44 AM, Rainer Jung <rainer.j...@kippdata.de> wrote: >>> On 15.11.2011 20:57, Jeff Trawick wrote: >>>> >>>> On Tue, Nov 15, 2011 at 2:32 PM, William A. Rowe Jr. >>>> <wr...@rowe-clan.net> wrote: >>>>> >>>>> On 11/15/2011 12:33 PM, Stefan Fritsch wrote: >>>>>> >>>>>> On Tuesday 15 November 2011, Paul Querna wrote: >>>>>>> >>>>>>> On Tue, Nov 15, 2011 at 9:17 AM, Stefan Fritsch<s...@sfritsch.de> >>>>>> >>>>>> wrote: >>>>>>>> >>>>>>>> On Tue, 15 Nov 2011, pque...@apache.org wrote: >>>>>>>>> >>>>>>>>> Author: pquerna >>>>>>>>> Date: Tue Nov 15 15:49:19 2011 >>>>>>>>> New Revision: 1202255 >>>>>>>>> >>>>>>>>> URL: http://svn.apache.org/viewvc?rev=1202255&view=rev >>>>>>>>> Log: >>>>>>>>> disable mod_reqtimeout if not configured >>>>>>>> >>>>>>>> Why that? We have just changed the default to be enabled in >>>>>>>> r1199447 and several developers at the hackathon agreed to this >>>>>>>> change. >>>>>>> >>>>>>> Didn't know it was discussed in depth at the hackathon, and there >>>>>>> wasn't any discussion on the list.... >>>>>>> >>>>>>> It showed up quite quickly in my profiling of the Event MPM, >>>>>>> because every pull/push on the filters would cause a >>>>>>> apr_time_now() call. >>>>>>> >>>>>>> I don't really like that just by loading the module, it changes the >>>>>>> behavior and performance of the server so drastically. >>>>>> >>>>>> It only acts on reads from the client. Normal non-POST requests arrive >>>>>> in one or two packets, which would mean approx. 3 additional >>>>>> apr_time_now calls per request. I haven't done benchmarks, but I can't >>>>>> imagine that this has a drastic impact on performance. And if it costs >>>>>> 1-2%, then that's a small cost compared to the impact of slowloris >>>>>> type attacks which eat lots of memory. >>>>>> >>>>>> The general intention of the recent changes in default configs and >>>>>> module selection/loading was to make it easier to only load those >>>>>> modules that are really needed, have a reasonable default config, and >>>>>> have the compiled-in default values be the same as those in the >>>>>> example config files. >>>>> >>>>> Which means, build by default, disable by default. I think that keeps >>>>> everyone happy. When abuse arrives, it's trivial to load. >>>> >>>> Timeout 60 isn't nearly as bad as the old Timeout 300 that is probably >>>> still in wide use, but mod_reqtimeout can provide a much more >>>> reasonable out of the box configuration. I think we should keep it in >>>> place by default. >>> >>> +1 >>> >> >> What I am really opposed to is that the LoadModule causes such a >> degradation in performance. >> >> I am 100% +1 to adding conf commands to the default configuration in >> the httpd.conf, but what I do not like is that having just a >> LoadModule with nothing else causes reqtimeout to do work. It is too >> trivial for people to have accidental load modules in many distros. > > How many distinct concerns are there? (Cut through the detail that > the implementation of request phase-specific timeouts is in a module, > and hence conflicts with thoughts for what it means to have code > loaded by LoadModule but not explicitly configured.) I see at least > two raised. > > 1) performance degradation out of the box with no explicit configuration* > 2) any processing at all out of the box with no explicit configuration > 3) relatively complex-to-understand timeout mechanism out of the box > with no explicit configuration (independent of whether it is core or > mod_) > 4) disagreement that the mod_reqtimeout defaults are "generally > better" across arbitrary situations than Timeout <somenumber> > 5) ??? > > (I assume that the performance issue related to the apr_time_now() > calls in mod_reqtimeout is addressable, and probably in a way that > helps other modules that don't need to know the time with high > precision.)
See attached patch for one possible fix (completely untested :) ). It should be determined (even if by changing code) that event's listener thread can update the timestamp in the child at least every 200ms. ap_time_around_now(), ap_roughly_time_now(), etc. might be better API names. Over the long term it might be helpful to have a couple of versions with different requirements, as some MPMs will simply punt to apr_time_now() if asked to provide something within 200ms.
Index: server/mpm/event/event.c =================================================================== --- server/mpm/event/event.c (revision 1202829) +++ server/mpm/event/event.c (working copy) @@ -1381,6 +1381,18 @@ } } +static apr_time_t roughly_now; /* set only by listener thread */ + +static int event_get_time_200(apr_time_t *now) +{ + if (roughly_now == 0) { + return DECLINED; + } + + *now = roughly_now; + return OK; +} + static void * APR_THREAD_FUNC listener_thread(apr_thread_t * thd, void *dummy) { timer_event_t *ep; @@ -1397,7 +1409,7 @@ const apr_pollfd_t *out_pfd; apr_int32_t num = 0; apr_interval_time_t timeout_interval; - apr_time_t timeout_time = 0, now, last_log; + apr_time_t timeout_time = 0, last_log; listener_poll_type *pt; int closed = 0, listeners_disabled = 0; @@ -1440,11 +1452,11 @@ check_infinite_requests(); } - now = apr_time_now(); + roughly_now = apr_time_now(); if (APLOGtrace6(ap_server_conf)) { /* trace log status every second */ - if (now - last_log > apr_time_from_msec(1000)) { - last_log = now; + if (roughly_now - last_log > apr_time_from_msec(1000)) { + last_log = roughly_now; ap_log_error(APLOG_MARK, APLOG_TRACE6, 0, ap_server_conf, "connections: %d (write-completion: %d " "keep-alive: %d lingering: %d)", @@ -1457,8 +1469,8 @@ apr_thread_mutex_lock(g_timer_ring_mtx); if (!APR_RING_EMPTY(&timer_ring, timer_event_t, link)) { te = APR_RING_FIRST(&timer_ring); - if (te->when > now) { - timeout_interval = te->when - now; + if (te->when > roughly_now) { + timeout_interval = te->when - roughly_now; } else { timeout_interval = 1; @@ -1495,14 +1507,14 @@ break; } - now = apr_time_now(); + roughly_now = apr_time_now(); apr_thread_mutex_lock(g_timer_ring_mtx); for (ep = APR_RING_FIRST(&timer_ring); ep != APR_RING_SENTINEL(&timer_ring, timer_event_t, link); ep = APR_RING_FIRST(&timer_ring)) { - if (ep->when < now + EVENT_FUDGE_FACTOR) { + if (ep->when < roughly_now + EVENT_FUDGE_FACTOR) { APR_RING_REMOVE(ep, link); push_timer2worker(ep); } @@ -1692,11 +1704,11 @@ /* XXX possible optimization: stash the current time for use as * r->request_time for new requests */ - now = apr_time_now(); + roughly_now = apr_time_now(); /* we only do this once per 0.1s (TIMEOUT_FUDGE_FACTOR) */ - if (now > timeout_time) { + if (roughly_now > timeout_time) { struct process_score *ps; - timeout_time = now + TIMEOUT_FUDGE_FACTOR; + timeout_time = roughly_now + TIMEOUT_FUDGE_FACTOR; /* handle timed out sockets */ @@ -3154,6 +3166,7 @@ ap_hook_check_config(event_check_config, NULL, NULL, APR_HOOK_MIDDLE); ap_hook_mpm(event_run, NULL, NULL, APR_HOOK_MIDDLE); ap_hook_mpm_query(event_query, NULL, NULL, APR_HOOK_MIDDLE); + ap_hook_mpm_get_time_200(event_get_time_200, NULL, NULL, APR_HOOK_MIDDLE); ap_hook_mpm_register_timed_callback(event_register_timed_callback, NULL, NULL, APR_HOOK_MIDDLE); ap_hook_mpm_get_name(event_get_name, NULL, NULL, APR_HOOK_MIDDLE); Index: server/mpm_common.c =================================================================== --- server/mpm_common.c (revision 1202829) +++ server/mpm_common.c (working copy) @@ -69,6 +69,7 @@ APR_HOOK_LINK(drop_privileges) APR_HOOK_LINK(mpm) APR_HOOK_LINK(mpm_query) + APR_HOOK_LINK(mpm_get_time_200) APR_HOOK_LINK(mpm_register_timed_callback) APR_HOOK_LINK(mpm_get_name) APR_HOOK_LINK(end_generation) @@ -82,6 +83,7 @@ APR_HOOK_LINK(drop_privileges) APR_HOOK_LINK(mpm) APR_HOOK_LINK(mpm_query) + APR_HOOK_LINK(mpm_get_time_200) APR_HOOK_LINK(mpm_register_timed_callback) APR_HOOK_LINK(mpm_get_name) APR_HOOK_LINK(end_generation) @@ -99,6 +101,9 @@ AP_IMPLEMENT_HOOK_RUN_FIRST(int, mpm_query, (int query_code, int *result, apr_status_t *_rv), (query_code, result, _rv), DECLINED) +AP_IMPLEMENT_HOOK_RUN_FIRST(int, mpm_get_time_200, + (apr_time_t *now), + (now), DECLINED) AP_IMPLEMENT_HOOK_RUN_FIRST(apr_status_t, mpm_register_timed_callback, (apr_time_t t, ap_mpm_callback_fn_t *cbfn, void *baton), (t, cbfn, baton), APR_ENOTIMPL) Index: server/util_time.c =================================================================== --- server/util_time.c (revision 1202829) +++ server/util_time.c (working copy) @@ -15,8 +15,8 @@ */ #include "util_time.h" +#include "mpm_common.h" - /* Number of characters needed to format the microsecond part of a timestamp. * Microseconds have 6 digits plus one separator character makes 7. * */ @@ -304,3 +304,13 @@ *date_str++ = 0; return APR_SUCCESS; } + +AP_DECLARE(apr_time_t) ap_get_time_200(void) { + apr_time_t now; + + if (ap_run_mpm_get_time_200(&now) == DECLINED) { + now = apr_time_now(); + } + + return now; +} Index: modules/filters/mod_reqtimeout.c =================================================================== --- modules/filters/mod_reqtimeout.c (revision 1202829) +++ modules/filters/mod_reqtimeout.c (working copy) @@ -22,6 +22,7 @@ #include "http_log.h" #include "http_core.h" #include "util_filter.h" +#include "util_time.h" #define APR_WANT_STRFUNC #include "apr_strings.h" #include "apr_version.h" @@ -87,7 +88,7 @@ static apr_status_t check_time_left(reqtimeout_con_cfg *ccfg, apr_time_t *time_left_p) { - *time_left_p = ccfg->timeout_at - apr_time_now(); + *time_left_p = ccfg->timeout_at - ap_get_time_200(); if (*time_left_p <= 0) return APR_TIMEUP; @@ -180,7 +181,7 @@ return ap_get_brigade(f->next, bb, mode, block, readbytes); } - now = apr_time_now(); + now = ap_get_time_200(); if (ccfg->new_timeout > 0) { /* set new timeout */ ccfg->timeout_at = now + apr_time_from_sec(ccfg->new_timeout); Index: include/util_time.h =================================================================== --- include/util_time.h (revision 1202829) +++ include/util_time.h (working copy) @@ -109,6 +109,11 @@ */ AP_DECLARE(apr_status_t) ap_recent_rfc822_date(char *date_str, apr_time_t t); +/* + * get the recent time, with an accuracy goal of around 200ms + */ +AP_DECLARE(apr_time_t) ap_get_time_200(void); + #ifdef __cplusplus } #endif Index: include/mpm_common.h =================================================================== --- include/mpm_common.h (revision 1202829) +++ include/mpm_common.h (working copy) @@ -359,6 +359,9 @@ /* get MPM name (e.g., "prefork" or "event") */ AP_DECLARE_HOOK(const char *,mpm_get_name,(void)) +/* get current time within 200ms or so */ +AP_DECLARE_HOOK(int, mpm_get_time_200, (apr_time_t *now)) + /* mutex type string for accept mutex, if any; MPMs should use the * same mutex type for ease of configuration */