Opened 8 months ago

Closed 6 months ago

#1723 closed defect (wontfix)

proxy_cache_background_update does not really do updates in the background

Reported by: nathou@… Owned by:
Priority: minor Milestone:
Component: nginx-module Version: 1.14.x
Keywords: cache Cc:
uname -a: Linux test-cache-host 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.14.1 built with OpenSSL 1.1.0f 25 May 2017 (running with OpenSSL 1.1.0j 20 Nov 2018) TLS SNI support enabled configure arguments: --with-cc-opt='-g -O2 -fdebug-prefix-map=/build/nginx-jqo7Nx/nginx-1.14.1=. -fstack-protector-strong -Wformat -Werror=format-security -fPIC -Wdate-time -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-z,relro -Wl,-z,now -fPIC' --prefix=/usr/share/nginx --conf-path=/etc/nginx/nginx.conf --http-log-path=/var/log/nginx/access.log --error-log-path=/var/log/nginx/error.log --lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid --modules-path=/usr/lib/nginx/modules --http-client-body-temp-path=/var/lib/nginx/body --http-fastcgi-temp-path=/var/lib/nginx/fastcgi --http-proxy-temp-path=/var/lib/nginx/proxy --http-scgi-temp-path=/var/lib/nginx/scgi --http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug --with-pcre-jit --with-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_v2_module --with-http_dav_module --with-http_slice_module --with-threads --with-http_addition_module --with-http_geoip_module=dynamic --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module=dynamic --with-http_sub_module --with-http_xslt_module=dynamic --with-stream=dynamic --with-stream_ssl_module --with-stream_ssl_preread_module --with-mail=dynamic --with-mail_ssl_module --add-dynamic-module=/build/nginx-jqo7Nx/nginx-1.14.1/debian/modules/http-auth-pam --add-dynamic-module=/build/nginx-jqo7Nx/nginx-1.14.1/debian/modules/http-dav-ext --add-dynamic-module=/build/nginx-jqo7Nx/nginx-1.14.1/debian/modules/http-echo --add-dynamic-module=/build/nginx-jqo7Nx/nginx-1.14.1/debian/modules/http-upstream-fair --add-dynamic-module=/build/nginx-jqo7Nx/nginx-1.14.1/debian/modules/http-subs-filter

Description

When successively requesting multiple stale urls using the same connection on a location with proxy_cache_background_update on, the update time of each request delays the processing of the next one.

To reproduce, you can use this simple site configuration:

proxy_cache_path  /srv/test_cache
                  keys_zone=keyz:32m
                  inactive=30s
                  max_size=1g;

server {
    listen 8080 default_server;

    location / {
        proxy_pass http://httpbin.org;
        proxy_set_header Host httpbin.org;

        proxy_cache keyz;
        proxy_cache_valid 200 10s;
        proxy_cache_background_update on;
        proxy_cache_use_stale updating;

        add_header X-Cache-Status $upstream_cache_status;
    }
}

And the following test script:

CURL_OPTIONS='-so /dev/null -w "%{time_total} %{http_code} %{url_effective}\n"'
NGINX_HOST='test-cache-host:8080'

# Populate cache
eval "curl ${CURL_OPTIONS} http://${NGINX_HOST}/delay/2 ${CURL_OPTIONS} http://${NGINX_HOST}/delay/3"
echo "Waiting for the cache to become stale..."
sleep 11
# Make the same requests (using a unique session)
eval "curl ${CURL_OPTIONS} http://${NGINX_HOST}/delay/2 ${CURL_OPTIONS} http://${NGINX_HOST}/delay/3"

Running the script against this configuration gives an output like the following. For the sake of brevity headers are not included in the output, but the cache status is correct: MISS for the 2 first requests, STALE for the others.

2,182513 200 http://test-cache-host:8080/delay/2
3,223398 200 http://test-cache-host:8080/delay/3
Waiting for the cache to become stale...
0,208964 200 http://test-cache-host:8080/delay/2
2,184092 200 http://test-cache-host:8080/delay/3

As you can see, the last request took 2 seconds to get an answer even though the stale version was used!

From the debug log and the client behavior, it looks like the following is happening:

  • the client requests http://test-cache-host:8080/delay/2
  • nginx immediately serves the stale version
  • nginx "background" updates its cache - but in fact, it is still "processing" the first request and it won't start looking into the next one until it is finished
  • the client requests http://test-cache-host:8080/delay/3 in the same session
  • nginx is still updating its cache
  • http://httpbin.org/delay/2 answers after 2 seconds
  • the cache for the first request is up to date
  • nginx finally starts processing the second request
  • ...

Adding keepalive_timeout 0; in the location of the above configuration forces the client to setup a new session after getting the first response. As the 2 requests come from different sessions, the second request is not delayed:

2,180887 200 http://test-cache-host:8080/delay/2
3,179635 200 http://test-cache-host:8080/delay/3
Waiting for the cache to become stale...
0,208349 200 http://test-cache-host:8080/delay/2
0,203867 200 http://test-cache-host:8080/delay/3

Change History (5)

comment:1 Changed 8 months ago by mdounin

  • Resolution set to wontfix
  • Status changed from new to closed

This is expected behaviour. Quoting docs:

Allows starting a background subrequest to update an expired cache item, while a stale cached response is returned to the client.

That is, background subrequest updates an expired cache item at the same time the response is returned to the client. If updating takes more time than returning the response, it can delay further requests on the same connection when using HTTP/1.x, since no additional requests on the connection will be processed till previous request is finished, with all related subrequests, much like when processing multiple pipelined HTTP requests.

comment:2 Changed 8 months ago by nathou@…

The documentation would benefit from clarifying what a background request is. In particular, is background referring to:

  1. returning a response without waiting for the end of the subrequest ?
  2. doing the subrequest 'outside of the request scope' ?

It surely looks like (1) has been implemented, but it is not specified in the documentation, or at least I did not find it.

From a user point of view, enabling proxy_cache_background_update means that you care more about performance than freshness. Delaying the next request is probably not what you want.

comment:3 Changed 8 months ago by mdounin

See also #1738.

comment:4 Changed 6 months ago by rulatir@…

  • Resolution wontfix deleted
  • Status changed from closed to reopened

@mdounin, this is a non sequitur. The behavior you describe after "That is, ..." does not follow logically from the documentation passage you quoted. Your claim that "this is the expected behavior" is unsupported, and the bug should be reopened.

Version 0, edited 6 months ago by rulatir@… (next)

comment:5 Changed 6 months ago by mdounin

  • Resolution set to wontfix
  • Status changed from reopened to closed

The behaviour I describe follows from the documentation quoted and how background subrequests work. While this may not be immediately clear for ones not familiar with background subrequests, and may need additional clarification in the docs, this is how it works and how it is expected to work.

Note: See TracTickets for help on using tickets.