Forum: NGINX Big dispersion in requests execution time.

2974d09ac2541e892966b762aad84943?d=identicon&s=25 yury_y (Guest)
on 2014-08-19 13:31
(Received via mailing list)
Hi,

I faced the following problem. Our server works under the constant load
of
300-400 requests per second.
From request execution time statistics I see that in some cases "fast"
request(that normally executes in few milliseconds) may hang for
seconds.

Here is an illustration of this problem.
I execute the following GET request
"http://127.0.0.1:777/fcgi/auth..."(no
ssl, no dns lookup, just http on localhost) from local client(on the
same
sever).
Usually this request executes in less then 1 millisecond, but in this
case
execution time is 130 milliseconds.

From tcpdump I can conclude following:
16:18:43.095716 - client sent request to nginx
16:18:43.225903 - nginx sent request to upstream
16:18:43.226178 - upstream replied to nginx
16:18:43.226235 - nginx replied to client

So request was processed by upstream in less then 1 millisecond, but it
took
about 130 microseconds to read request from client and pass it to
upstream.
I observe similar behavior both for fcgi upstreams and for static
requests.

Does anybody have similar problems? In which direction should I
investigate?




<--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.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;
    }
}
<---------------------------------------------------->

Posted at Nginx Forum:
http://forum.nginx.org/read.php?2,252668,252668#msg-252668
A8108a0961c6087c43cda32c8616dcba?d=identicon&s=25 Maxim Dounin (Guest)
on 2014-08-25 19:58
(Received via mailing list)
Hello!

On Tue, Aug 19, 2014 at 07:31:21AM -0400, yury_y wrote:

> sever).
> about 130 microseconds to read request from client and pass it to upstream.
> I observe similar behavior both for fcgi upstreams and for static requests.
>
> Does anybody have similar problems? In which direction should I
> investigate?

Most likely, the reason for such delays is that all nginx workers
were busy doing some other work.  In particular, this may happen
with disk-bound workloads due to blocking on disk.  You may try
looking into top(1) output for states of nginx worker processes,
it usually makes things much clearer.

Some additional reading:

http://nginx.org/r/sendfile_max_chunk
http://nginx.org/r/aio
http://nginx.org/r/output_buffers

--
Maxim Dounin
http://nginx.org/
Please log in before posting. Registration is free and takes only a minute.
Existing account

NEW: Do you have a Google/GoogleMail, Yahoo or Facebook account? No registration required!
Log in with Google account | Log in with Yahoo account | Log in with Facebook account
No account? Register here.