Добрый день,

столкнулся со следующей проблемой. Сервер работает под нагрузкой порядка 300-400 запросов в минуту.
Из статистики времени выполнения запросов видно, что в некоторых случаях "быстрые" запросы, которые обычно занимают несколько миллисекунд, могут выполняться по несколько секунд.
Для иллюстрации проблемы можно рассмотреть такой пример.

Выполняется GET запрос "http://127.0.0.1:777/fcgi/auth..."(без ssl, без поиска в dns, сервер слушает на localhost) с локального клиента(на том же сервере).
Запрос, который обычно занимает меньше миллисекунды, в данном случае занимает 130 миллисекунд.

Здесь краткая хронология событий из tcpdump-а:
16:18:43.095716 - клиент отправляет запрос nginx-у
16:18:43.225903 - nginx отправляет запрос upstream-у
16:18:43.226178 - upstream отвечает nginx-у
16:18:43.226235 - nginx отвечает клиенту

Таким образом upstream отвечает по запрос менее чем за миллисекунду, но 130 миллисекунд уходит на то чтобы прочесть клиентский запрос и переслать его в upstream.
Такое же поведение наблюдается и при отдаче статики.

Кто-нибудь сталкивался с подобными проблемами? В каком направлении можно копать?


С уважением,
Юрий


<--nginx to client tcpdump--------------------->
2014-08-15 16:18:43.095653 IP 127.0.0.1.17573 > 127.0.0.1.777: Flags [S], seq 2328271692, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 2588746027 ecr 0], length 0
2014-08-15 16:18:43.095673 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [S.], seq 1912981495, ack 2328271693, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 858797424 ecr 2588746027], length 0
2014-08-15 16:18:43.095687 IP 127.0.0.1.17573 > 127.0.0.1.777: Flags [.], ack 1, win 1275, options [nop,nop,TS val 2588746027 ecr 858797424], length 0
2014-08-15 16:18:43.095716 IP 127.0.0.1.17573 > 127.0.0.1.777: Flags [P.], seq 1:133, ack 1, win 1275, options [nop,nop,TS val 2588746027 ecr 858797424], length 132
2014-08-15 16:18:43.195641 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [.], ack 133, win 1273, options [nop,nop,TS val 858797524 ecr 2588746027], length 0
2014-08-15 16:18:43.226235 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [P.], seq 1:250, ack 133, win 1275, options [nop,nop,TS val 858797554 ecr 2588746027], length 249
2014-08-15 16:18:43.226412 IP 127.0.0.1.17573 > 127.0.0.1.777: Flags [F.], seq 133, ack 250, win 1275, options [nop,nop,TS val 2588746157 ecr 858797554], length 0
2014-08-15 16:18:43.226440 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [.], ack 134, win 1275, options [nop,nop,TS val 858797554 ecr 2588746157], length 0
2014-08-15 16:18:43.226450 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [F.], seq 250, ack 134, win 1275, options [nop,nop,TS val 858797554 ecr 2588746157], length 0
2014-08-15 16:18:43.455652 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [F.], seq 250, ack 134, win 1275, options [nop,nop,TS val 858797784 ecr 2588746157], length 0
2014-08-15 16:18:43.715642 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [F.], seq 250, ack 134, win 1275, options [nop,nop,TS val 858798044 ecr 2588746157], length 0
2014-08-15 16:18:44.035649 IP 127.0.0.1.777 > 127.0.0.1.17573: Flags [F.], seq 250, ack 134, win 1275, options [nop,nop,TS val 858798364 ecr 2588746157], length 0
<------------------------------------------------------------->

<--nginx to upstream tcpdump------------------->
2014-08-15 16:18:43.225762 IP 127.0.0.1.17591 > 127.0.0.1.1300: Flags [S], seq 1606422700, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 2588746157 ecr 0], length 0
2014-08-15 16:18:43.225785 IP 127.0.0.1.1300 > 127.0.0.1.17591: Flags [S.], seq 212542195, ack 1606422701, win 65535, options [mss 16344,nop,wscale 6,sackOK,TS val 3738538996 ecr 2588746157], length 0
2014-08-15 16:18:43.225793 IP 127.0.0.1.17591 > 127.0.0.1.1300: Flags [.], ack 1, win 1275, options [nop,nop,TS val 2588746157 ecr 3738538996], length 0
2014-08-15 16:18:43.225903 IP 127.0.0.1.17591 > 127.0.0.1.1300: Flags [P.], seq 1:577, ack 1, win 1275, options [nop,nop,TS val 2588746157 ecr 3738538996], length 576
2014-08-15 16:18:43.226178 IP 127.0.0.1.1300 > 127.0.0.1.17591: Flags [P.], seq 1:121, ack 577, win 1275, options [nop,nop,TS val 3738538996 ecr 2588746157], length 120
2014-08-15 16:18:43.226187 IP 127.0.0.1.1300 > 127.0.0.1.17591: Flags [F.], seq 121, ack 577, win 1275, options [nop,nop,TS val 3738538996 ecr 2588746157], length 0
2014-08-15 16:18:43.226198 IP 127.0.0.1.17591 > 127.0.0.1.1300: Flags [.], ack 122, win 1274, options [nop,nop,TS val 2588746157 ecr 3738538996], length 0
2014-08-15 16:18:43.226222 IP 127.0.0.1.17591 > 127.0.0.1.1300: Flags [F.], seq 577, ack 122, win 1275, options [nop,nop,TS val 2588746157 ecr 3738538996], length 0
2014-08-15 16:18:43.455643 IP 127.0.0.1.17591 > 127.0.0.1.1300: Flags [F.], seq 577, ack 122, win 1275, options [nop,nop,TS val 2588746387 ecr 3738538996], length 0
2014-08-15 16:18:43.455661 IP 127.0.0.1.1300 > 127.0.0.1.17591: Flags [R], seq 212542317, win 0, length 0
<--------------------------------------------------->

<--server info---------------------------------->
os: FreeBSD 9.2-RELEASE-p3
arch: amd64
number of cores: 48
ram merory size: 32GB
nginx verson: 1.6.0
nginx workers count: 32
<---------------------------------------------------->

<---nginx.conf---------------------------------->
user datauser;
daemon off;
worker_processes 32;

events
{
worker_connections 1024;
}

http
{
include .../mime.types;

gzip on;
gzip_http_version 1.0;
gzip_comp_level 2;
gzip_proxied any;
gzip_min_length 1100;
gzip_buffers 16 8k;
gzip_types text/plain text/css application/x-javascript text/xml application/xml application/xml+rss text/javascript;
gzip_disable "MSIE [1-6].(?!.*SV1)";
gzip_vary on;

client_max_body_size 65m;
client_body_buffer_size 128k;
client_body_temp_path /tmp/nginx/client_body_temp;
default_type application/octet-stream;
sendfile on;

...
upstreams
...

...
servers
...

server
{
listen 127.0.0.1:777;

location ~* ^/fcgi/(.*)$ {
fastcgi_pass 127.0.0.1:1300;
include fastcgi_params;
rewrite ^/fcgi/(.*)$ /$1 break;
}
}
<---------------------------------------------->