Часть запросов с анамольно большим $request time

[malaf]

Добрый день.

Есть такая конфигурация:
- фронтенд c nginx
- бэкенды с php
- для динамических запросов настроено php fastcgi между nginx и php-fpm
через tcp порт с кешированием ответов
- log_format выглядит примерно так- '$remote_addr # $upstream_addr #
$request # $status # $uri # $upstream_response_time # $upstream_cache_status
# $request_time
- проект высоконагруженный

Столкнулся с такой проблемой, судя по логам, то часть запросов имеет
существенно большее значение  $request_time чем $upstream_response_time,
может быть больше как на 1 секунду так и 2, 5 и даже более 30.  Особенно это
заметно на страницах из кеша, у которых upstream_cache_status = HIT,
upstream_response_time = 0 и c большим request_time, хотя для подавляющего
большинства этот параметр имеет значение 0-0.01s 

Влияние "медленных клиентов" на значение $request_time вроде отсёк, проверив
лог после обращения к странице в кеше с помощью curl --limit-rate 20K
example.com > /dev/null, время ответа было 4 секунды, в лог request_time
записался со значение 0.

Проблема тоже не fastcgi или кеш-менеджере, так как такое же наблюдается и
для запросов, которые обрабатываются с помощью  nginx+redis через
redis_pass.
 
Подскажите, в чём может быть проблема, на что ещё обратить внимание, что
проверить?

nginx -V

nginx version: nginx/1.8.1
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-11) (GCC) 
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx
--conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log
--http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid
--lock-path=/var/run/nginx.lock
--http-client-body-temp-path=/var/cache/nginx/client_temp
--http-proxy-temp-path=/var/cache/nginx/proxy_temp
--http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp
--http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp
--http-scgi-temp-path=/var/cache/nginx/scgi_temp --with-http_ssl_module
--with-http_realip_module --with-http_addition_module --with-http_sub_module
--with-http_gunzip_module --with-http_gzip_static_module
--with-http_random_index_module --with-http_secure_link_module
--without-http_memcached_module --without-http_uwsgi_module
--without-http_scgi_module --with-http_stub_status_module
--add-module=/root/rpmbuild/SOURCES/nginx_modules/ngx_cache_purge
--add-module=/root/rpmbuild/SOURCES/nginx_modules/ngx_http_redis
--add-module=/root/rpmbuild/SOURCES/nginx_modules/redis2-nginx-module
--add-module=/root/rpmbuild/SOURCES/nginx_modules/lua-nginx-module
--add-module=/root/rpmbuild/SOURCES/nginx_modules/ngx_devel_kit
--add-module=/root/rpmbuild/SOURCES/nginx_modules/set-misc-nginx-module
--with-file-aio --with-http_spdy_module --with-cc-opt='-O2 -g -pipe -Wall
-Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector
--param=ssp-buffer-size=4 -m64 -mtune=generic'

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