From 9eda614d84d8c1102dc66cebb55eca05e6a0c7b8 Mon Sep 17 00:00:00 2001 From: Otto van der Schaaf Date: Mon, 16 Feb 2015 11:53:08 +0100 Subject: [PATCH] shutdown-and-flushing: Improve shutdown, support/test FlushHtml - Improve shutting down both gracefully and quickly - Set the flush flags on buffers when FlushHtml is on for optimized html responses - Add tests for these features - Don't call proxy_fetch->Flush() each time our body filter is called, because that would only make sense if we'd also set buf->flush. --- src/ngx_base_fetch.cc | 126 +++++++++++----- src/ngx_base_fetch.h | 6 +- src/ngx_fetch.cc | 6 +- src/ngx_pagespeed.cc | 109 +++++++------- src/ngx_pagespeed.h | 3 +- test/nginx_system_test.sh | 174 ++++++++++++++++++----- test/nginx_terminate_timeout.diff | 59 ++++++++ test/pagespeed_test.conf.template | 46 ++++++ test/www/slow-flushing-html-response.php | 15 ++ 9 files changed, 413 insertions(+), 131 deletions(-) create mode 100644 test/nginx_terminate_timeout.diff create mode 100644 test/www/slow-flushing-html-response.php diff --git a/src/ngx_base_fetch.cc b/src/ngx_base_fetch.cc index 30f54de2d6..14fb059165 100644 --- a/src/ngx_base_fetch.cc +++ b/src/ngx_base_fetch.cc @@ -16,6 +16,7 @@ // Author: jefftk@google.com (Jeff Kaufman) #include //for usleep +#include // PRId64 #include "ngx_base_fetch.h" #include "ngx_event_connection.h" @@ -36,7 +37,29 @@ const char kFlush = 'F'; const char kDone = 'D'; NgxEventConnection* NgxBaseFetch::event_connection = NULL; -int NgxBaseFetch::active_base_fetches = 0; +// We'll set this event to uncancelable to prevent nginx from exiting before we +// are up for it. See ngx_worker_process_cycle(). +ngx_event_t* NgxBaseFetch::shutdown_event = NULL; +int64 NgxBaseFetch::active_base_fetches = 0; +int64 NgxBaseFetch::request_ctx_count = 0; + + +// Periodically checks whether the conditions are met for ::Terminate() to be +// called: +// - A forced/quick shutdown, e.g. SIGTERM was received. +// - A graceful shutdown, e.g. SIGQUIT was recevied, after all outstanding +// work as been finished. +// When one of those conditions is met, ev->cancelable will have been set to +// false by us, and nginx will end up calling ::Terminate() next after calling +// Done(false) on any outstanding proxy fetches. +// Terminate() will clear out any pending events to make sure we release all +// associated NgxBaseFetch instances. +static void ps_base_fetch_shutdown_event_handler(ngx_event_t *ev) { + NgxBaseFetch::CheckShutdownEvent(); + if (!ev->cancelable) { + ngx_add_timer(ev, 1000); + } +} NgxBaseFetch::NgxBaseFetch(ngx_http_request_t* r, NgxServerContext* server_context, @@ -65,6 +88,17 @@ NgxBaseFetch::~NgxBaseFetch() { bool NgxBaseFetch::Initialize(ngx_cycle_t* cycle) { CHECK(event_connection == NULL) << "event connection already set"; event_connection = new NgxEventConnection(ReadCallback); + + shutdown_event = reinterpret_cast( + ngx_pcalloc(cycle->pool, sizeof(ngx_event_t))); + shutdown_event->handler = ps_base_fetch_shutdown_event_handler; + + shutdown_event->data = cycle; + shutdown_event->log = cycle->log; + // Prevents nginx from exiting until we are up for it. + shutdown_event->cancelable = 0; + ngx_add_timer(shutdown_event, 1000); + return event_connection->Init(cycle); } @@ -72,26 +106,30 @@ void NgxBaseFetch::Terminate() { if (event_connection != NULL) { GoogleMessageHandler handler; PosixTimer timer; - int64 timeout_us = Timer::kSecondUs * 30; + // A second should be more then enough. + int64 timeout_us = Timer::kSecondUs; int64 end_us = timer.NowUs() + timeout_us; static unsigned int sleep_microseconds = 100; handler.Message( - kInfo,"NgxBaseFetch::Terminate rounding up %d active base fetches.", + kInfo,"NgxBaseFetch::Terminate start: %" PRId64 " base fetches.", NgxBaseFetch::active_base_fetches); - // Try to continue processing and get the active base fetch count to 0 - // untill the timeout expires. - // TODO(oschaaf): This needs more work. + // Drain any events after a quick or graceful shutdown to clear out + // associated NgxBaseFetch instances. while (NgxBaseFetch::active_base_fetches > 0 && end_us > timer.NowUs()) { event_connection->Drain(); usleep(sleep_microseconds); } - if (NgxBaseFetch::active_base_fetches != 0) { + DCHECK_EQ(NgxBaseFetch::active_base_fetches, 0); + DCHECK_EQ(NgxBaseFetch::request_ctx_count, 0); + + if (NgxBaseFetch::active_base_fetches != 0 || NgxBaseFetch::request_ctx_count) { handler.Message( - kWarning,"NgxBaseFetch::Terminate timed out with %d active base fetches.", - NgxBaseFetch::active_base_fetches); + kWarning,"NgxBaseFetch::Terminate exit: %" PRId64 " base fetches, " + "%" PRId64 " request contexts", NgxBaseFetch::active_base_fetches, + NgxBaseFetch::request_ctx_count); } // Close down the named pipe. @@ -99,6 +137,7 @@ void NgxBaseFetch::Terminate() { delete event_connection; event_connection = NULL; } + NgxBaseFetch::CheckShutdownEvent(); } const char* BaseFetchTypeToCStr(NgxBaseFetchType type) { @@ -133,36 +172,38 @@ void NgxBaseFetch::ReadCallback(const ps_event_data& data) { // If we ended up destructing the base fetch, or the request context is // detached, skip this event. - if (refcount == 0 || detached) { - return; - } - ps_request_ctx_t* ctx = ps_get_request_context(r); - - CHECK(data.sender == ctx->base_fetch); - CHECK(r->count > 0) << "r->count: " << r->count; - - int rc; - // If we are unlucky enough to have our connection finalized mid-ipro-lookup, - // we must enter a different flow. Also see ps_in_place_check_header_filter(). - if ((ctx->base_fetch->base_fetch_type_ != kIproLookup) - && r->connection->error) { - ngx_log_error(NGX_LOG_DEBUG, ngx_cycle->log, 0, - "pagespeed [%p] request already finalized", r); - rc = NGX_ERROR; - } else { - rc = ps_base_fetch::ps_base_fetch_handler(r); - } - + if (refcount != 0 && !detached) { + ps_request_ctx_t* ctx = ps_get_request_context(r); + + CHECK(data.sender == ctx->base_fetch); + CHECK(r->count > 0) << "r->count: " << r->count; + + int rc; + // If we are unlucky enough to have our connection finalized mid-ipro-lookup, + // we must enter a different flow. Also see ps_in_place_check_header_filter(). + if ((ctx->base_fetch->base_fetch_type_ != kIproLookup) + && r->connection->error) { + ngx_log_error(NGX_LOG_DEBUG, ngx_cycle->log, 0, + "pagespeed [%p] request already finalized", r); + rc = NGX_ERROR; + } else { + rc = ps_base_fetch::ps_base_fetch_handler(r); + } #if (NGX_DEBUG) - ngx_log_error(NGX_LOG_DEBUG, ngx_cycle->log, 0, - "pagespeed [%p] ps_base_fetch_handler() returned %d for %c", - r, rc, data.type); + ngx_log_error(NGX_LOG_DEBUG, ngx_cycle->log, 0, + "pagespeed [%p] ps_base_fetch_handler() returned %d for %c", + r, rc, data.type); #endif + if (ngx_terminate) { + return; + } - ngx_connection_t* c = r->connection; - ngx_http_finalize_request(r, rc); - // See http://forum.nginx.org/read.php?2,253006,253061 - ngx_http_run_posted_requests(c); + ngx_connection_t* c = r->connection; + ngx_http_finalize_request(r, rc); + // See http://forum.nginx.org/read.php?2,253006,253061 + ngx_http_run_posted_requests(c); + } + NgxBaseFetch::CheckShutdownEvent(); } void NgxBaseFetch::Lock() { @@ -193,7 +234,8 @@ ngx_int_t NgxBaseFetch::CopyBufferToNginx(ngx_chain_t** link_ptr) { } int rc = string_piece_to_buffer_chain( - request_->pool, buffer_, link_ptr, done_called_ /* send_last_buf */); + request_->pool, buffer_, link_ptr, done_called_ /* send_last_buf */, + true); if (rc != NGX_OK) { return rc; } @@ -292,6 +334,16 @@ int NgxBaseFetch::DecrefAndDeleteIfUnreferenced() { return r; } +void NgxBaseFetch::CheckShutdownEvent() { + bool quit = ngx_terminate || ((ngx_quit || ngx_exiting) && + NgxBaseFetch::request_ctx_count == 0); + if (NgxBaseFetch::shutdown_event != NULL && quit) { + NgxBaseFetch::shutdown_event->cancelable = 1; + NgxBaseFetch::shutdown_event = NULL; + } +} + + void NgxBaseFetch::HandleDone(bool success) { // TODO(jefftk): it's possible that instead of locking here we can just modify // CopyBufferToNginx to only read done_called_ once. diff --git a/src/ngx_base_fetch.h b/src/ngx_base_fetch.h index 78512fdb7b..f25bd7c17d 100644 --- a/src/ngx_base_fetch.h +++ b/src/ngx_base_fetch.h @@ -118,11 +118,13 @@ class NgxBaseFetch : public AsyncFetch { // this to be able to handle events which nginx request context has been // released while the event was in-flight. void Detach() { detached_ = true; DecrementRefCount(); } + static void CheckShutdownEvent(); bool detached() { return detached_; } ngx_http_request_t* request() { return request_; } NgxBaseFetchType base_fetch_type() { return base_fetch_type_; } + static int64 request_ctx_count; private: virtual bool HandleWrite(const StringPiece& sp, MessageHandler* handler); @@ -149,11 +151,11 @@ class NgxBaseFetch : public AsyncFetch { // Called by Done() and Release(). Decrements our reference count, and if // it's zero we delete ourself. int DecrefAndDeleteIfUnreferenced(); - static NgxEventConnection* event_connection; + static ngx_event_t* shutdown_event; // Live count of NgxBaseFetch instances that are currently in use. - static int active_base_fetches; + static int64 active_base_fetches; ngx_http_request_t* request_; GoogleString buffer_; diff --git a/src/ngx_fetch.cc b/src/ngx_fetch.cc index 33172d736c..a33addbad8 100644 --- a/src/ngx_fetch.cc +++ b/src/ngx_fetch.cc @@ -508,11 +508,13 @@ bool NgxFetch::ParseUrl() { url_.url.len = str_url_.length(); url_.url.data = static_cast(ngx_palloc(pool_, url_.url.len)); if (url_.url.data == NULL) { + DCHECK(false) << "NgxFetch::ParseUrl() without data"; return false; } str_url_.copy(reinterpret_cast(url_.url.data), str_url_.length(), 0); - - return NgxUrlAsyncFetcher::ParseUrl(&url_, pool_); + bool r = NgxUrlAsyncFetcher::ParseUrl(&url_, pool_); + DCHECK(r) << "NgxUrlAsyncFetcher::ParseUrl(&url_, pool_) failed"; + return r; } // Issue a request after the resolver is done diff --git a/src/ngx_pagespeed.cc b/src/ngx_pagespeed.cc index 3011e2b674..ab63612046 100644 --- a/src/ngx_pagespeed.cc +++ b/src/ngx_pagespeed.cc @@ -87,6 +87,8 @@ extern ngx_module_t ngx_pagespeed; net_instaweb::NgxRewriteDriverFactory* active_driver_factory = NULL; +std::vector fetch_factories; + namespace net_instaweb { const char* kInternalEtagName = "@psol-etag"; @@ -124,7 +126,7 @@ char* string_piece_to_pool_string(ngx_pool_t* pool, StringPiece sp) { // (potentially) longer string to nginx and want it to take ownership. ngx_int_t string_piece_to_buffer_chain( ngx_pool_t* pool, StringPiece sp, ngx_chain_t** link_ptr, - bool send_last_buf) { + bool send_last_buf, bool flush) { // Below, *link_ptr will be NULL if we're starting the chain, and the head // chain link. *link_ptr = NULL; @@ -198,6 +200,10 @@ ngx_int_t string_piece_to_buffer_chain( CHECK(tail_link != NULL); + + if (flush) { + tail_link->buf->flush = true; + } if (send_last_buf) { tail_link->buf->last_buf = true; } @@ -225,6 +231,7 @@ void ps_set_buffered(ngx_http_request_t* r, bool on) { namespace { void ps_release_base_fetch(ps_request_ctx_t* ctx); +void ps_release_request_context(void* data); } // namespace @@ -236,24 +243,28 @@ ngx_http_output_body_filter_pt ngx_http_next_body_filter; ngx_int_t ps_base_fetch_filter(ngx_http_request_t* r, ngx_chain_t* in) { ps_request_ctx_t* ctx = ps_get_request_context(r); - if (ctx == NULL || ctx->base_fetch == NULL) { + if (ctx == NULL) { return ngx_http_next_body_filter(r, in); } ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "http pagespeed write filter \"%V\"", &r->uri); + if (in == NULL && ctx->base_fetch != NULL) { + // ps_html_rewrite_body_filter and ps_base_fetch_handler() can call us + // with a NULL chain. No need to wake the downstream for that. + return NGX_AGAIN; + } + // send response body - if (in || r->connection->buffered) { - ngx_int_t rc = ngx_http_next_body_filter(r, in); - // We can't indicate that we are done yet, because we have an active base - // fetch associated to this request. - if (rc != NGX_OK) { - return rc; - } + ngx_int_t rc = ngx_http_next_body_filter(r, in); + + // When we still have ctx->base_fetch set, that means we are not done. + if (ctx->base_fetch && rc == NGX_OK) { + return NGX_AGAIN; } - return NGX_AGAIN; + return rc; } // This runs on the nginx event loop in response to seeing the byte PageSpeed @@ -267,9 +278,8 @@ ngx_int_t ps_base_fetch_handler(ngx_http_request_t* r) { ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "ps fetch handler: %V", &r->uri); - if (ngx_terminate || ngx_exiting) { - ps_set_buffered(r, false); - ps_release_base_fetch(ctx); + if (ngx_terminate) { + ps_release_request_context(ctx); return NGX_ERROR; } @@ -346,16 +356,9 @@ ngx_int_t ps_base_fetch_handler(ngx_http_request_t* r) { ps_set_buffered(r, false); ps_release_base_fetch(ctx); return NGX_HTTP_INTERNAL_SERVER_ERROR; - } - - if (rc == NGX_AGAIN && cl == NULL) { - // there is no body buffer to send now. - return NGX_AGAIN; - } - - if (rc == NGX_OK) { - ps_set_buffered(r, false); + } else if (rc == NGX_OK) { ps_release_base_fetch(ctx); + ps_set_buffered(r, false); } return ps_base_fetch_filter(r, cl); @@ -1561,9 +1564,9 @@ void ps_release_base_fetch(ps_request_ctx_t* ctx) { // TODO(chaizhenhua): merge into NgxBaseFetch ctor void ps_create_base_fetch(ps_request_ctx_t* ctx, - RequestContextPtr request_context, - RequestHeaders* request_headers, - NgxBaseFetchType type) { + RequestContextPtr request_context, + RequestHeaders* request_headers, + NgxBaseFetchType type) { CHECK(ctx->base_fetch == NULL) << "Pre-existing base fetch!"; ngx_http_request_t* r = ctx->r; @@ -1587,7 +1590,10 @@ void ps_release_request_context(void* data) { // // If this is a resource fetch then proxy_fetch was never initialized. if (ctx->proxy_fetch != NULL) { - ctx->proxy_fetch->Done(false /* failure */); + // When ngx_terminate is set, we'll have cleaned up earlier. + if (!ngx_terminate) { + ctx->proxy_fetch->Done(false /* failure */); + } ctx->proxy_fetch = NULL; } @@ -1596,12 +1602,12 @@ void ps_release_request_context(void* data) { ctx->inflater_ = NULL; } - if (ctx->driver != NULL) { + if (ctx->driver != NULL && !ngx_terminate) { ctx->driver->Cleanup(); ctx->driver = NULL; } - if (ctx->recorder != NULL) { + if (ctx->recorder != NULL && !ngx_terminate) { ctx->recorder->Fail(); ctx->recorder->DoneAndSetHeaders(NULL); // Deletes recorder. ctx->recorder = NULL; @@ -1609,6 +1615,7 @@ void ps_release_request_context(void* data) { ps_release_base_fetch(ctx); delete ctx; + NgxBaseFetch::request_ctx_count--; } // Set us up for processing a request. Creates a request context and determines @@ -1620,10 +1627,6 @@ RequestRouting::Response ps_route_request(ngx_http_request_t* r) { // Not enabled for this server block. return RequestRouting::kPagespeedDisabled; } - - if (ngx_terminate || ngx_exiting) { - return RequestRouting::kError; - } if (r->err_status != 0) { return RequestRouting::kErrorResponse; } @@ -1699,17 +1702,6 @@ ngx_int_t ps_resource_handler(ngx_http_request_t* r, ps_srv_conf_t* cfg_s = ps_get_srv_config(r); ps_request_ctx_t* ctx = ps_get_request_context(r); - if (ngx_terminate || ngx_exiting) { - cfg_s->server_context->message_handler()->Message( - kInfo, "ps_resource_handler declining: nginx worker is shutting down"); - - if (ctx == NULL) { - return NGX_DECLINED; - } - ps_release_base_fetch(ctx); - return NGX_DECLINED; - } - CHECK(!(html_rewrite && (ctx == NULL || ctx->html_rewrite == false))); if (!html_rewrite && @@ -1787,10 +1779,11 @@ ngx_int_t ps_resource_handler(ngx_http_request_t* r, // create request ctx CHECK(ctx == NULL); ctx = new ps_request_ctx_t(); - + NgxBaseFetch::request_ctx_count++; ctx->r = r; ctx->html_rewrite = false; ctx->in_place = false; + ctx->follow_flushes = options->follow_flushes(); ctx->preserve_caching_headers = kDontPreserveHeaders; // See build_context_for_request() in mod_instaweb.cc @@ -1988,9 +1981,22 @@ void ps_send_to_pagespeed(ngx_http_request_t* r, ngx_chain_t* in) { ngx_chain_t* cur; int last_buf = 0; + for (cur = in; cur != NULL; cur = cur->next) { last_buf = cur->buf->last_buf; + if (cur->buf->flush && ctx->follow_flushes) { + // Calling ctx->proxy_fetch->Flush(cfg_s->handler) will be a no-op here, + // unless we have follow_flushes or flush_html enabled. Note that PSOL + // might aggregate multiple flushes into 1, and actually flush a little bit + // later due to html parser state and earlier scheduled operations. + // Also, unless we also set the flush flag on the nginx buffers we won't + // actually flush. + // Note that too many flushes could harm optimization over larger html + // fragments as PSOL gets less context to work with, e.g. it can't combine + // two css files if a flush happens in between. + ctx->proxy_fetch->Flush(cfg_s->handler); + } // Buffers are not really the last buffer until they've been through // pagespeed. cur->buf->last_buf = 0; @@ -2023,9 +2029,6 @@ void ps_send_to_pagespeed(ngx_http_request_t* r, if (last_buf) { ctx->proxy_fetch->Done(true /* success */); ctx->proxy_fetch = NULL; // ProxyFetch deletes itself on Done(). - } else { - // TODO(jefftk): Decide whether Flush() is warranted here. - ctx->proxy_fetch->Flush(cfg_s->handler); } } @@ -2235,13 +2238,12 @@ ngx_int_t ps_html_rewrite_body_filter(ngx_http_request_t* r, ngx_chain_t* in) { ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "http pagespeed html rewrite body filter \"%V\"", &r->uri); - if (in != NULL) { // Send all input data to the proxy fetch. ps_send_to_pagespeed(r, ctx, cfg_s, in); } - return ngx_http_next_body_filter(r, NULL); + return NGX_AGAIN; } void ps_html_rewrite_filter_init() { @@ -2441,7 +2443,7 @@ ngx_int_t send_out_headers_and_body( // Send the body. ngx_chain_t* out; rc = string_piece_to_buffer_chain( - r->pool, output, &out, true /* send_last_buf */); + r->pool, output, &out, true /* send_last_buf */, false /* flush */); if (rc == NGX_ERROR) { return NGX_ERROR; } @@ -2741,6 +2743,9 @@ ngx_int_t ps_content_handler(ngx_http_request_t* r) { ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0, "http pagespeed handler \"%V\"", &r->uri); + if (ngx_terminate) { + return NGX_DECLINED; + } RequestRouting::Response response_category = ps_route_request(r); @@ -3020,6 +3025,9 @@ ngx_int_t ps_init_module(ngx_cycle_t* cycle) { void ps_exit_child_process(ngx_cycle_t* cycle) { ps_main_conf_t* cfg_m = static_cast( ngx_http_cycle_get_module_main_conf(cycle, ngx_pagespeed)); + for (size_t i = 0; i < fetch_factories.size(); i++) { + fetch_factories[i]->CancelOutstanding(); + } NgxBaseFetch::Terminate(); cfg_m->driver_factory->ShutDown(); } @@ -3057,6 +3065,7 @@ ngx_int_t ps_init_child_process(ngx_cycle_t* cycle) { // not instantiate a ProxyFetchFactory. if (cfg_s->server_context != NULL) { cfg_s->proxy_fetch_factory = new ProxyFetchFactory(cfg_s->server_context); + fetch_factories.push_back(cfg_s->proxy_fetch_factory); ngx_http_core_loc_conf_t* clcf = static_cast( cscfp[s]->ctx->loc_conf[ngx_http_core_module.ctx_index]); cfg_m->driver_factory->SetServerContextMessageHandler( diff --git a/src/ngx_pagespeed.h b/src/ngx_pagespeed.h index 00fd00e344..b31b64564e 100644 --- a/src/ngx_pagespeed.h +++ b/src/ngx_pagespeed.h @@ -52,7 +52,7 @@ class InPlaceResourceRecorder; // NGX_DECLINED immediately unless send_last_buf. ngx_int_t string_piece_to_buffer_chain( ngx_pool_t* pool, StringPiece sp, - ngx_chain_t** link_ptr, bool send_last_buf); + ngx_chain_t** link_ptr, bool send_last_buf, bool flush); StringPiece str_to_string_piece(ngx_str_t s); @@ -103,6 +103,7 @@ typedef struct { // We need to remember the URL here as well since we may modify what NGX // gets by stripping our special query params and honoring X-Forwarded-Proto. GoogleString url_string; + bool follow_flushes; } ps_request_ctx_t; ps_request_ctx_t* ps_get_request_context(ngx_http_request_t* r); diff --git a/test/nginx_system_test.sh b/test/nginx_system_test.sh index 9d8b99cd64..e9cdb86693 100644 --- a/test/nginx_system_test.sh +++ b/test/nginx_system_test.sh @@ -46,6 +46,10 @@ PRIMARY_HOSTNAME="localhost:$PRIMARY_PORT" SECONDARY_HOSTNAME="localhost:$SECONDARY_PORT" SERVER_ROOT="$MOD_PAGESPEED_DIR/src/install/" +CHILD_TERMINATE_MAX_SECONDS=1 +if $USE_VALGRIND; then + CHILD_TERMINATE_MAX_SECONDS=5 +fi # We need check and check_not before we source SYSTEM_TEST_FILE that provides # them. @@ -77,11 +81,11 @@ function keepalive_test() { for ((i=0; i < 10; i++)); do for accept_encoding in "" "gzip"; do if [ -z "$POST_DATA" ]; then - curl -m 2 -S -s -v -H "Accept-Encoding: $accept_encoding" \ + curl -m 5 -S -s -v -H "Accept-Encoding: $accept_encoding" \ -H "Host: $HOST_NAME" $URL $URL $URL $URL $URL > /dev/null \ 2>>"$TEST_TMP/$CURL_LOG_FILE" || true else - curl -X POST --data "$POST_DATA" -m 2 -S -s -v \ + curl -X POST --data "$POST_DATA" -m 5 -S -s -v \ -H "Accept-Encoding: $accept_encoding" -H "Host: $HOST_NAME"\ $URL $URL $URL $URL $URL > /dev/null \ 2>>"$TEST_TMP/$CURL_LOG_FILE" || true @@ -145,6 +149,7 @@ while pgrep nginx > /dev/null; do sleep 1; done while pgrep memcheck > /dev/null; do sleep 1; done TEST_TMP="$this_dir/tmp" +SUPPRESSIONS="$this_dir/valgrind.sup" rm -r "$TEST_TMP" check_simple mkdir -p "$TEST_TMP" PROXY_CACHE="$TEST_TMP/proxycache" @@ -208,37 +213,41 @@ cat $PAGESPEED_CONF_TEMPLATE \ | sed 's#@@RCPORT5@@#'"$RCPORT5"'#' \ | sed 's#@@RCPORT6@@#'"$RCPORT6"'#' \ | sed 's#@@RCPORT7@@#'"$RCPORT7"'#' \ + | sed 's#@@CHILD_TERMINATE_MAX_SECONDS@@#'"$CHILD_TERMINATE_MAX_SECONDS"'#' \ >> $PAGESPEED_CONF # make sure we substituted all the variables check_not_simple grep @@ $PAGESPEED_CONF # start nginx with new config -if $USE_VALGRIND; then - (valgrind -q --leak-check=full --gen-suppressions=all \ - --show-possibly-lost=no --log-file=$TEST_TMP/valgrind.log \ - --suppressions="$this_dir/valgrind.sup" \ - $NGINX_EXECUTABLE -c $PAGESPEED_CONF) & VALGRIND_PID=$! - trap "echo 'terminating valgrind!' && kill -s sigterm $VALGRIND_PID" EXIT - echo "Wait until nginx is ready to accept connections" - while ! curl -I "http://$PRIMARY_HOSTNAME/mod_pagespeed_example/" 2>/dev/null; do - sleep 0.1; - done - echo "Valgrind (pid:$VALGRIND_PID) is logging to $TEST_TMP/valgrind.log" -else - TRACE_FILE="$TEST_TMP/conf_loading_trace" - $NGINX_EXECUTABLE -c $PAGESPEED_CONF >& "$TRACE_FILE" - if [[ $? -ne 0 ]]; then - echo "FAIL" - cat $TRACE_FILE - if [[ $(grep -c "unknown directive \"proxy_cache_purge\"" $TRACE_FILE) == 1 ]]; then - echo "This test requires proxy_cache_purge. One way to do this:" - echo "Run git clone https://github.com/FRiCKLE/ngx_cache_purge.git" - echo "And compile nginx with the additional ngx_cache_purge module." +function start_nginx() { + if $USE_VALGRIND; then + (valgrind -q --leak-check=full --gen-suppressions=all \ + --show-possibly-lost=no --log-file=$TEST_TMP/valgrind.log \ + --suppressions="$SUPPRESSIONS" \ + $NGINX_EXECUTABLE -c $PAGESPEED_CONF) & VALGRIND_PID=$! + trap "echo 'terminating valgrind!' && kill -s sigterm $VALGRIND_PID" EXIT + echo "Wait until nginx is ready to accept connections" + while ! curl -I "http://$PRIMARY_HOSTNAME/mod_pagespeed_example/" 2>/dev/null; do + sleep 0.1; + done + echo "Valgrind (pid:$VALGRIND_PID) is logging to $TEST_TMP/valgrind.log" + else + TRACE_FILE="$TEST_TMP/conf_loading_trace" + $NGINX_EXECUTABLE -c $PAGESPEED_CONF >& "$TRACE_FILE" + if [[ $? -ne 0 ]]; then + echo "FAIL" + cat $TRACE_FILE + if [[ $(grep -c "unknown directive \"proxy_cache_purge\"" $TRACE_FILE) == 1 ]]; then + echo "This test requires proxy_cache_purge. One way to do this:" + echo "Run git clone https://github.com/FRiCKLE/ngx_cache_purge.git" + echo "And compile nginx with the additional ngx_cache_purge module." + fi + rm $TRACE_FILE + exit 1 fi - rm $TRACE_FILE - exit 1 fi -fi +} +start_nginx # Helper methods used by downstream caching tests. @@ -326,6 +335,8 @@ if $USE_VALGRIND; then ~IPRO flow uses cache as expected.~ ~IPRO flow doesn't copy uncacheable resources multiple times.~ ~inline_unauthorized_resources allows unauthorized css selectors~ +~Follow flushes does what it should do.~ +~Quick shutdown is quick and ungraceful.~ " fi @@ -559,8 +570,6 @@ check test $(scrape_stat image_rewrite_total_original_bytes) -ge 10000 start_test "Reload config" # Fire up some heavy load if ab is available to test a stressed reload. -# TODO(oschaaf): make sure we wait for the new worker to get ready to accept -# requests. fire_ab_load check wget $EXAMPLE_ROOT/styles/W.rewrite_css_images.css.pagespeed.cf.Hash.css \ @@ -1208,29 +1217,112 @@ check_from "$OUT" fgrep -qi '404' MATCHES=$(echo "$OUT" | grep -c "Cache-Control: override") || true check [ $MATCHES -eq 1 ] -start_test Shutting down. +function check_flushing() { + local command="$1" + local threshold_sec="$2" + local expect_chunk_op="$3" + local expect_chunk_count="$4" + local output="" + local start=$(date +%s%N) + local chunk_count=0 + + if $USE_VALGRIND; then + # We can't say much about correctness of timings + # under valgrind, so relax the test for that. + threshold_sec=$(echo "scale=2; $threshold_sec*10" | bc) + fi + + while true; do + start=$(date +%s%N) + # read the http chunk size from the stream. + # this is also the read that we use to check timings. + check_simple read -t $threshold_sec line + line=$(echo $line | tr -d '\n' | tr -d '\r') + if [ $((16#$line)) -eq "0" ] ; then + check [ $chunk_count $3 $expect_chunk_count ] + return + fi + let chunk_count=chunk_count+1 + # read the actual data from the stream, using the amount indicated in + # the previous read. this read should be fast. + check_simple read -N $((16#$line)) line + echo $line + # Read trailing \r\n - should be fast. + check_simple read -N 2 line + done < <($command) + check 0 +} + +start_test Follow flushes does what it should do. +echo "Check that FollowFlushes on outputs timely chunks" +URL="http://flush.example.com/slow-flushing-html-response.php" +# The php file will write 6 chunks, but the last two often get aggregated +# into one. Hence 5 or 6 is what we want to see. +check_flushing "curl -N --raw --silent --proxy $SECONDARY_HOSTNAME $URL" \ + 1.1 -ge 5 + +echo "Check that FollowFlushes off outputs a single chunk" +URL="http://noflush.example.com/slow-flushing-html-response.php" +check_flushing "curl -N --raw --silent --proxy $SECONDARY_HOSTNAME $URL" \ + 5.2 -eq 1 + +function wait_for_server_exit() { + if $USE_VALGRIND; then + while pgrep memcheck > /dev/null; do sleep 1; done + # Clear the previously set trap, we don't need it anymore. + trap - EXIT + echo "Checking for valgrind complaints." + check_not [ -s "$TEST_TMP/valgrind.log" ] + else + while pgrep nginx > /dev/null; do sleep 1; done + fi +} + +start_test Shutting down gracefully. # Fire up some heavy load if ab is available to test a stressed shutdown fire_ab_load -if $USE_VALGRIND; then - kill -s quit $VALGRIND_PID - while pgrep memcheck > /dev/null; do sleep 1; done - # Clear the previously set trap, we don't need it anymore. - trap - EXIT +SLOW_URL="http://flush.example.com/slow-flushing-html-response.php" +sleep 1 +# Fire a single slow request -- php-cgi will serialize execution, and +# testing more would take too long. The quit signal should be received +# while we are busy transforming the html response. +OUTFILE="$TEST_TMP/curl_out" +check_simple curl -N --silent --proxy $SECONDARY_HOSTNAME $SLOW_URL > "$OUTFILE" & - start_test No Valgrind complaints. - check_not [ -s "$TEST_TMP/valgrind.log" ] -else - check_simple "$NGINX_EXECUTABLE" -s quit -c "$PAGESPEED_CONF" - while pgrep nginx > /dev/null; do sleep 1; done +check_simple "$NGINX_EXECUTABLE" -s quit -c "$PAGESPEED_CONF" + +if [ "$AB_PID" != "0" ]; then + echo "Kill ab (pid: $AB_PID)" + killall -s KILL $AB_PID &>/dev/null || true fi +wait_for_server_exit + +check [ $(grep -c "" $OUTFILE) -eq 1 ] + +start_test Quick shutdown is quick and ungraceful. +start_nginx +check_not_simple curl -N --silent --proxy $SECONDARY_HOSTNAME $SLOW_URL > "$OUTFILE" & +# Fire up some heavy load if ab is available to test a stressed shutdown +fire_ab_load + +# We wait 4 seconds, while the script needs about 5 to finish up. +sleep 3 +check_simple "$NGINX_EXECUTABLE" -s stop -c "$PAGESPEED_CONF" +wait_for_server_exit if [ "$AB_PID" != "0" ]; then echo "Kill ab (pid: $AB_PID)" killall -s KILL $AB_PID &>/dev/null || true fi +# Check we received some of the data. +check [ $(grep -c "bar:1" $OUTFILE) -eq 1 ] +# The shutdown should be quick enough for us to not receive the last +# chunk of body data containing the closing body/html tags. +check [ $(grep -c "" $OUTFILE) -eq 0 ] + start_test Logged output looks healthy. # TODO(oschaaf): Sanity check for all the warnings/errors here. @@ -1280,6 +1372,10 @@ OUT=$(cat "$ERROR_LOG" \ | grep -v "\\[warn\\].*remote\.cfg.*" \ | grep -v "\\[warn\\].*end token not received.*" \ | grep -v "\\[warn\\].*failed to hook next event.*" \ + | grep -v "\\[warn\\].*Adding function to sequence.*after shutdown.*" \ + | grep -v "\\[warn\\].*Fetch timed out:.*/mod_pagespeed_example/images/pagespeed_logo.png.*" \ + | grep -v "\\[warn\\].*RateController: drop fetch of.*/mod_pagespeed_example/images/pagespeed_logo.png.*" \ + | grep -v "\\[warn\\].*serf_url_async_fetcher.cc.*Aborting fetch of.*/mod_pagespeed_example/images/pagespeed_logo.png.*" \ || true) check [ -z "$OUT" ] diff --git a/test/nginx_terminate_timeout.diff b/test/nginx_terminate_timeout.diff new file mode 100644 index 0000000000..d303b266b8 --- /dev/null +++ b/test/nginx_terminate_timeout.diff @@ -0,0 +1,59 @@ +diff --git a/src/core/nginx.c b/src/core/nginx.c +index c75ee4f..2b8f959 100644 +--- a/src/core/nginx.c ++++ b/src/core/nginx.c +@@ -125,6 +125,13 @@ static ngx_command_t ngx_core_commands[] = { + offsetof(ngx_core_conf_t, rlimit_sigpending), + NULL }, + ++ { ngx_string("child_terminate_timeout"), ++ NGX_MAIN_CONF|NGX_DIRECT_CONF|NGX_CONF_TAKE1, ++ ngx_conf_set_msec_slot, ++ 0, ++ offsetof(ngx_core_conf_t, child_terminate_timeout), ++ NULL }, ++ + { ngx_string("working_directory"), + NGX_MAIN_CONF|NGX_DIRECT_CONF|NGX_CONF_TAKE1, + ngx_conf_set_str_slot, +@@ -955,6 +962,7 @@ ngx_core_module_create_conf(ngx_cycle_t *cycle) + ccf->rlimit_nofile = NGX_CONF_UNSET; + ccf->rlimit_core = NGX_CONF_UNSET; + ccf->rlimit_sigpending = NGX_CONF_UNSET; ++ ccf->child_terminate_timeout = NGX_CONF_UNSET_MSEC; + + ccf->user = (ngx_uid_t) NGX_CONF_UNSET_UINT; + ccf->group = (ngx_gid_t) NGX_CONF_UNSET_UINT; +@@ -985,6 +993,7 @@ ngx_core_module_init_conf(ngx_cycle_t *cycle, void *conf) + + ngx_conf_init_value(ccf->worker_processes, 1); + ngx_conf_init_value(ccf->debug_points, 0); ++ ngx_conf_init_value(ccf->child_terminate_timeout, 1000); + + #if (NGX_HAVE_CPU_AFFINITY) + +diff --git a/src/core/ngx_cycle.h b/src/core/ngx_cycle.h +index 21bf5ca..cd983ff 100644 +--- a/src/core/ngx_cycle.h ++++ b/src/core/ngx_cycle.h +@@ -85,6 +85,7 @@ typedef struct { + ngx_int_t rlimit_sigpending; + off_t rlimit_core; + ++ ngx_msec_t child_terminate_timeout; + int priority; + + ngx_uint_t cpu_affinity_n; +diff --git a/src/os/unix/ngx_process_cycle.c b/src/os/unix/ngx_process_cycle.c +index 51cf725..7d2f4c2 100644 +--- a/src/os/unix/ngx_process_cycle.c ++++ b/src/os/unix/ngx_process_cycle.c +@@ -200,7 +200,7 @@ ngx_master_process_cycle(ngx_cycle_t *cycle) + + sigio = ccf->worker_processes + 2 /* cache processes */; + +- if (delay > 1000) { ++ if (delay > ccf->child_terminate_timeout) { + ngx_signal_worker_processes(cycle, SIGKILL); + } else { + ngx_signal_worker_processes(cycle, diff --git a/test/pagespeed_test.conf.template b/test/pagespeed_test.conf.template index ebd8f69b41..a4c465c5a9 100644 --- a/test/pagespeed_test.conf.template +++ b/test/pagespeed_test.conf.template @@ -6,6 +6,10 @@ worker_processes 1; daemon @@DAEMON@@; master_process on; +child_terminate_timeout @@CHILD_TERMINATE_MAX_SECONDS@@s; + +worker_rlimit_core 1024M; +working_directory "@@TEST_TMP@@/"; error_log "@@ERROR_LOG@@" debug; pid "@@TEST_TMP@@/nginx.pid"; @@ -1210,6 +1214,48 @@ http { root "@@SERVER_ROOT@@"; } + server { + pagespeed on; + listen @@SECONDARY_PORT@@; + listen [::]:@@SECONDARY_PORT@@; + server_name flush.example.com; + pagespeed FileCachePath "@@FILE_CACHE@@"; + pagespeed RewriteLevel PassThrough; + root "@@TEST_TMP@@/../www/"; + pagespeed RewriteDeadlinePerFlushMs 1; + pagespeed FollowFlushes on; + + location ~ \.php$ { + fastcgi_param SCRIPT_FILENAME $request_filename; + fastcgi_param QUERY_STRING $query_string; + fastcgi_param REQUEST_METHOD $request_method; + fastcgi_param CONTENT_TYPE $content_type; + fastcgi_param CONTENT_LENGTH $content_length; + fastcgi_pass 127.0.0.1:9000; + fastcgi_buffering off; + } + } + server { + pagespeed on; + listen @@SECONDARY_PORT@@; + listen [::]:@@SECONDARY_PORT@@; + server_name noflush.example.com; + pagespeed FileCachePath "@@FILE_CACHE@@"; + pagespeed RewriteLevel PassThrough; + root "@@TEST_TMP@@/../www/"; + pagespeed FollowFlushes off; + + location ~ \.php$ { + fastcgi_param SCRIPT_FILENAME $request_filename; + fastcgi_param QUERY_STRING $query_string; + fastcgi_param REQUEST_METHOD $request_method; + fastcgi_param CONTENT_TYPE $content_type; + fastcgi_param CONTENT_LENGTH $content_length; + fastcgi_pass 127.0.0.1:9000; + fastcgi_buffering off; + } + } + server { # Write all post data to temp files client_body_in_file_only clean; diff --git a/test/www/slow-flushing-html-response.php b/test/www/slow-flushing-html-response.php new file mode 100644 index 0000000000..030cd31678 --- /dev/null +++ b/test/www/slow-flushing-html-response.php @@ -0,0 +1,15 @@ +\n"; +$size = 5; + +for($i = 1; $i <= $size; $i++) { + echo "

foo

bar:" . $i . "
\n"; + ob_flush(); + flush(); + sleep(1); +} + +echo "\n"; +?> \ No newline at end of file