On Wed, Nov 16, 2011 at 11:51 AM, Jeff Trawick <[email protected]> wrote:
> On Wed, Nov 16, 2011 at 11:20 AM, Paul Querna <[email protected]> wrote:
>> On Wed, Nov 16, 2011 at 2:44 AM, Rainer Jung <[email protected]> wrote:
>>> On 15.11.2011 20:57, Jeff Trawick wrote:
>>>>
>>>> On Tue, Nov 15, 2011 at 2:32 PM, William A. Rowe Jr.
>>>> <[email protected]> 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<[email protected]>
>>>>>>
>>>>>> wrote:
>>>>>>>>
>>>>>>>> On Tue, 15 Nov 2011, [email protected] 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
*/
