2

A few times a day our nginx (1.1.19 ubuntu 12.04 lts) stalls for some seconds (longest was 53 seconds so far) and waits to serve data. There is no error for the client, the request just takes the stalling amount of time longer. This applies to all requests in this time period (cgi or status module) and all requests will be served as soon as the stall is over.

I have a screen session on the server and curl every second the status page:

{"time":"2016-09-02T10:10:21+02:00","host":"app1","data":"nginx","reading":1,"writing":4,"waiting":0}
{"time":"2016-09-02T10:10:22+02:00","host":"app1","data":"nginx","reading":1,"writing":4,"waiting":0}
{"time":"2016-09-02T10:10:50+02:00","host":"app1","data":"nginx","reading":3,"writing":9,"waiting":0}
{"time":"2016-09-02T10:11:43+02:00","host":"app1","data":"nginx","reading":5,"writing":98,"waiting":0}
{"time":"2016-09-02T10:11:44+02:00","host":"app1","data":"nginx","reading":0,"writing":25,"waiting":0}
{"time":"2016-09-02T10:11:45+02:00","host":"app1","data":"nginx","reading":3,"writing":7,"waiting":0}

The gap is not due to errors but the request is having a longer outer duration than normal. In the access log there are no faulty requests logged. You can just notice the gap.

127.0.0.1 - - [02/Sep/2016:10:10:17 +0200] "GET /basic_status HTTP/1.1" 200 121 "-" "curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3"
127.0.0.1 - - [02/Sep/2016:10:10:18 +0200] "GET /basic_status HTTP/1.1" 200 121 "-" "curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3"
127.0.0.1 - - [02/Sep/2016:10:10:20 +0200] "GET /basic_status HTTP/1.1" 200 121 "-" "curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3"
127.0.0.1 - - [02/Sep/2016:10:10:21 +0200] "GET /basic_status HTTP/1.1" 200 121 "-" "curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3"
127.0.0.1 - - [02/Sep/2016:10:10:22 +0200] "GET /basic_status HTTP/1.1" 200 121 "-" "curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3"

I checked for nginx error log and fpm log etc but no errors at this time.

user www-data;
worker_processes 4;
pid /var/run/nginx.pid;

events {
        worker_connections 768;
}

http {

        sendfile on;
        tcp_nopush on;
        tcp_nodelay on;
        keepalive_timeout 65;
        types_hash_max_size 2048;
        include /etc/nginx/mime.types;
        default_type application/octet-stream;
        large_client_header_buffers 4 80k;
        access_log /var/log/nginx/access.log;
        error_log /var/log/nginx/error.log;
        gzip on;
        gzip_disable "msie6";
        include /etc/nginx/conf.d/*.conf;
        include /etc/nginx/sites-enabled/*;
}

server {
    listen 80;

    server_name app1;

    access_log /var/log/nginx/access.log;
    error_log  /var/log/nginx/error.log;

    root /var/www;

    location /basic_status {
        stub_status on;
    }
}

I am also logging the number of TIME_WAIT-Quadruples but no high number either:

{"time":"2016-09-02T10:10:54+02:00","host":"app1","data":"time_wait","httpFromLB":1153,"httpFromLocal":604,"mysqlToDb":1988,"memcacheToLocal":250, "cgiToLocal":1527}
{"time":"2016-09-02T10:10:55+02:00","host":"app1","data":"time_wait","httpFromLB":1153,"httpFromLocal":604,"mysqlToDb":1991,"memcacheToLocal":251, "cgiToLocal":1527}
{"time":"2016-09-02T10:10:56+02:00","host":"app1","data":"time_wait","httpFromLB":1153,"httpFromLocal":604,"mysqlToDb":1992,"memcacheToLocal":252, "cgiToLocal":1527}
{"time":"2016-09-02T10:10:57+02:00","host":"app1","data":"time_wait","httpFromLB":902,"httpFromLocal":496,"mysqlToDb":1628,"memcacheToLocal":213, "cgiToLocal":1236}
{"time":"2016-09-02T10:10:58+02:00","host":"app1","data":"time_wait","httpFromLB":902,"httpFromLocal":496,"mysqlToDb":1629,"memcacheToLocal":214, "cgiToLocal":1236}
{"time":"2016-09-02T10:10:59+02:00","host":"app1","data":"time_wait","httpFromLB":902,"httpFromLocal":496,"mysqlToDb":1631,"memcacheToLocal":215, "cgiToLocal":1236}
{"time":"2016-09-02T10:11:00+02:00","host":"app1","data":"time_wait","httpFromLB":902,"httpFromLocal":496,"mysqlToDb":1632,"memcacheToLocal":216, "cgiToLocal":1236}
{"time":"2016-09-02T10:11:01+02:00","host":"app1","data":"time_wait","httpFromLB":902,"httpFromLocal":496,"mysqlToDb":1633,"memcacheToLocal":217, "cgiToLocal":1236}
{"time":"2016-09-02T10:11:03+02:00","host":"app1","data":"time_wait","httpFromLB":902,"httpFromLocal":496,"mysqlToDb":1636,"memcacheToLocal":218, "cgiToLocal":1236}
{"time":"2016-09-02T10:11:04+02:00","host":"app1","data":"time_wait","httpFromLB":902,"httpFromLocal":496,"mysqlToDb":1637,"memcacheToLocal":219, "cgiToLocal":1236}

The application itself I excluded from my investigations as the first line of code will log the timestamp and it is the time at the end of the stall.

I have no clue where to investigate further. Any ideas?

  • Interesting problem. To confirm- the stall is happening at request receipt, that is, the application is not being given the request until after the stall? – Jonah Benton Sep 2 '16 at 17:27
  • Yes, in the application log I see the starting time of the request after the stall. – DaSteph Sep 2 '16 at 21:17
  • Does the application, if visited directly during the stalls, respond? – Jonah Benton Sep 2 '16 at 22:10
  • Yes it is stuck and the request is waiting for the response - no error just slowed down. Right after the stall all requests get answered. In the application the recorded timestamp is the time after the stall. – DaSteph Sep 4 '16 at 18:10
  • To confirm, the application itself is stuck? Or the application, hit directly not going through nginx, responds immediately during a stall? – Jonah Benton Sep 4 '16 at 18:40

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.