proxy_cache_background_update leads to 200 ms delay

[stephan13360]

I recently set proxy_cache_valid 200 to 1 second, down from 15 minutes to
refresh the content more often (With proxy_cache_background_update on;
already activated long before that).
Our Web monitoring, checking our site every minute, showed an increase in
response time following this change.

After some investigating I pinned it down to a ~200 ms delay coming from
using proxy_cache_background_update.

With an EXPIRED cache and proxy_cache_background_update disabled the site
takes around 500 ms to load.
With a cache HIT its takes around ~5 ms.
Then I stopped php-fpm, disabled proxy_cache_background_update and got a
STALE response (proxy_cache_use_stale error) taking ~6 ms.
The I started php-fpm again and enabled proxy_cache_background_update, wehen
the cache expired I get a STALE response taking around ~200 ms

I got the times I measured using curl's time_total on localhost, so network
delay is out of the picture. I ran the tests dozens of times and the
milliseconds are very consistent.

I have a few sites / server showing this behavior and some that don't.
The server in this example is an AWS EC2 t2.small with SSD storage. Only
NGINX and the cache is running on this Instance, PHP ist running on a
different server.

Currently I don't now why this is happening an would appreciate any hints.

Example Output from cURL:

================EXPIRED================
HTTP/1.1 200 OK
Server: nginx
Date: Fri, 06 Jul 2018 12:00:46 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 112834
Connection: keep-alive
Vary: Accept-Encoding
Vary: Accept-Encoding
Content-Language: de
X-Cache: EXPIRED

Status Code:    200
Lookup time:    0.004181 s
Connect time (TCP):     0.004236 s
Connect time (SSL):     0.000000 s
Pretransfer time:       0.004259 s
Starttransfer time:     0.503897 s
Size download:  112834 bytes
Speed download: 223248.000 bytes/s

Total time:     0.505418 s

================HIT================
HTTP/1.1 200 OK
Server: nginx
Date: Fri, 06 Jul 2018 12:01:23 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 112834
Connection: keep-alive
Vary: Accept-Encoding
Vary: Accept-Encoding
Content-Language: de
X-Cache: HIT

Status Code:    200
Lookup time:    0.004200 s
Connect time (TCP):     0.004257 s
Connect time (SSL):     0.000000 s
Pretransfer time:       0.004281 s
Starttransfer time:     0.005348 s
Size download:  112834 bytes
Speed download: 20642883.000 bytes/s

Total time:     0.005466 s

================STALE (proxy_cache_background_update on)================
HTTP/1.1 200 OK
Server: nginx
Date: Fri, 06 Jul 2018 12:02:28 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 112834
Connection: keep-alive
Vary: Accept-Encoding
Vary: Accept-Encoding
Content-Language: de
X-Cache: STALE

Status Code:    200
Lookup time:    0.004203 s
Connect time (TCP):     0.004267 s
Connect time (SSL):     0.000000 s
Pretransfer time:       0.004294 s
Starttransfer time:     0.004870 s
Size download:  112834 bytes
Speed download: 537563.000 bytes/s

Total time:     0.209899 s

================STALE (proxy_cache_background_update off)================
HTTP/1.1 200 OK
Server: nginx
Date: Fri, 06 Jul 2018 12:03:03 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 112834
Connection: keep-alive
Vary: Accept-Encoding
Vary: Accept-Encoding
Content-Language: de
X-Cache: STALE

Status Code:    200
Lookup time:    0.004204 s
Connect time (TCP):     0.004262 s
Connect time (SSL):     0.000000 s
Pretransfer time:       0.004289 s
Starttransfer time:     0.005906 s
Size download:  112834 bytes
Speed download: 18752534.000 bytes/s

Total time:     0.006017 s

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,280434,280434#msg-280434