<html><body><div style="font-family: Arial; font-size: 12pt; color: #000000"><div>Hello,<br></div><div><br></div><div>The definition of the gunicorn time I mentioned is 'request time in microseconds'. Because Gunicorn only talks to Nginx, this would be the time Gunicorn needs (after having received the request) to generate the response and send it back to nginx, I would say. In most cases, this time matches the nginx upstream response time closely. There is a few milliseconds overhead, usually.<br></div><div><br></div><div>I haven't tried a tcpdump. This is going to require some time to setup, because the long delay time is not reproducible. I need to log a day's worth of data and then devise some useful filter. I'll try to set something up.<br></div><div><br></div><div>As for Maxim's response about packet loss; it would have to be packet loss on a file socket. Is this even possible?<br></div><div><br></div><div>- Wiebe<br></div><div><br></div><div><br></div><hr id="zwchr"><blockquote style="border-left:2px solid #1010FF;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt;" data-mce-style="border-left: 2px solid #1010FF; margin-left: 5px; padding-left: 5px; color: #000; font-weight: normal; font-style: normal; text-decoration: none; font-family: Helvetica,Arial,sans-serif; font-size: 12pt;"><b>From: </b>"B.R." <reallfqq-nginx@yahoo.fr><br><b>To: </b>"nginx ML" <nginx@nginx.org><br><b>Sent: </b>Tuesday, 10 March, 2015 1:28:03 PM<br><b>Subject: </b>Re: Nginx upstream delays<br><div><br></div><div dir="ltr"><div class="gmail_default" style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">Then it means nginx waited 3.042 seconds after having finished sending the request to the backend (ie time waiting for an answer).<br><a href="http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_response_time" target="_blank" data-mce-href="http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_response_time">http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_response_time</a><br><div><br></div></div><div class="gmail_default" style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">Try to get the definition of the time you mention from Gunicorn. Times could be completely different from what you think they mean.<br><div><br></div></div><div class="gmail_default" style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">Have you tried to use tcpdump on the frontend/backend communication? Does it show anything interesting?<br></div><div class="gmail_default" style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">If the latency comes from neither ends specifically but from the communication channel itself, you will need to dig further.<br></div><div class="gmail_default" style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">If it comes fro mthe backend, it might also be some waiting time (database? buffering?), which might not taken into account in the time you mentioned.<br><div><br></div></div><div class="gmail_default" style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">The only certainty is: nginx is responsible for an overhead of 56ms on this request. Definitely not a problem on its side, I would conclude.<br></div><div class="gmail_extra"><div><div class="gmail_signature"><span style="font-size: xx-small;" data-mce-style="font-size: xx-small;" size="1"><span style="color:rgb(102,102,102)" data-mce-style="color: #666666;">---<br></span><b><span style="color:rgb(102,102,102)" data-mce-style="color: #666666;">B. R.</span></b><span style="color:rgb(102,102,102)" data-mce-style="color: #666666;"></span></span></div></div><br><div class="gmail_quote">On Tue, Mar 10, 2015 at 10:23 AM, Wiebe Cazemier <span dir="ltr"><<a href="mailto:wiebe@halfgaar.net" target="_blank" data-mce-href="mailto:wiebe@halfgaar.net">wiebe@halfgaar.net</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex" data-mce-style="margin: 0 0 0 .8ex; border-left: 1px #ccc solid; padding-left: 1ex;"><div><div style="font-family:Arial;font-size:12pt;color:#000000" data-mce-style="font-family: Arial; font-size: 12pt; color: #000000;"><div>Hello,</div><div><br></div><div>The <span style="color:rgb(0,0,255)" data-mce-style="color: #0000ff;">$request_time</span> and <span style="color:rgb(0,0,255)" data-mce-style="color: #0000ff;">$upstream_request_time</span> are already included. In the log below it says '<span style="color:#cc0000" data-mce-style="color: #cc0000;">3.042 <span style="color:#000000" data-mce-style="color: #000000;">3.098</span></span>'. The latter is the request time, the former the upstream request time. It doesn't seem to be an issue of slow clients (also not for other log entries, they're similar).<br></div><div><br></div><div>It's going to be hard to diagnose if Gunicorn says the request takes 40 ms, but Nginx says it takes 3042 ms.<br></div><div><br></div><div>Hunting on...<br></div><div><br></div><div>- Wiebe<br></div><div><br></div><div><br></div><hr><blockquote style="border-left:2px solid #1010ff;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt" data-mce-style="border-left: 2px solid #1010ff; margin-left: 5px; padding-left: 5px; color: #000; font-weight: normal; font-style: normal; text-decoration: none; font-family: Helvetica,Arial,sans-serif; font-size: 12pt;"><b>From: </b>"Wandenberg Peixoto" <<a href="mailto:wandenberg@gmail.com" target="_blank" data-mce-href="mailto:wandenberg@gmail.com">wandenberg@gmail.com</a>><br><b>To: </b><a href="mailto:nginx@nginx.org" target="_blank" data-mce-href="mailto:nginx@nginx.org">nginx@nginx.org</a><br><b>Sent: </b>Tuesday, 10 March, 2015 1:37:09 AM<br><b>Subject: </b>Re: Nginx upstream delays<div><div class="h5"><br><div><br></div><div dir="ltr">You also have to consider the rate your client get data from the server.<div>The request time is the entire time spent from the beginning of the request until the end of response.</div><div>So you may not have a problem on your server, just a lazy client :)</div><div class="gmail_extra"><br><div class="gmail_quote">On Mon, Mar 9, 2015 at 1:05 PM, B.R. <span dir="ltr"><<a href="mailto:reallfqq-nginx@yahoo.fr" target="_blank" data-mce-href="mailto:reallfqq-nginx@yahoo.fr">reallfqq-nginx@yahoo.fr</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex" data-mce-style="margin: 0 0 0 .8ex; border-left: 1px #ccc solid; padding-left: 1ex;"><div dir="ltr"><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">You are on a nginx mailing list, thus I will reply on the nginx side of the problem.<br><div><br></div></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">You can diagnose further to tell if the problem comes from nginx or from the backend by using 2 different variables in your log message:<br></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;"><a href="http://nginx.org/en/docs/http/ngx_http_log_module.html#var_request_time" target="_blank" data-mce-href="http://nginx.org/en/docs/http/ngx_http_log_module.html#var_request_time">$request_time</a><br></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;"><a href="http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_response_time" target="_blank" data-mce-href="http://nginx.org/en/docs/http/ngx_http_upstream_module.html#var_upstream_response_time">$upstream_response_time</a><br><div><br></div></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">If those values are close enough (most of the time equal), you might then conclude that the trouble does not come from nginx, but rather from the backend (or communication between those).<br><div><br></div></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">If you want to investigate the communication level, you can set up some tcpdump listening on the communication between nginx and the backend. You will need to use TCP ports to do that.<br></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">Since you are using UNIX sockets, you might want to monitor file descriptors, but I would (totally out of thin air) suppose it might not be the source of your trouble, since you would have seen much more impact if it was.<br><div><br></div></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">I guess you will have to trace/dump stuff on your backend. PHP has some slowlog capability firing up tracing in a code which takes too long to finish. I do not know anything about Python servers, but you are not at the right location for questions related to those anyway.<br><div><br></div></div><div style="font-size:small;color:rgb(51,51,153)" data-mce-style="font-size: small; color: #333399;">Happy hunting,<br clear="all"><div><div><span style="font-size:xx-small" data-mce-style="font-size: xx-small;"><span style="color:rgb(102,102,102)" data-mce-style="color: #666666;">---<br></span><b><span style="color:rgb(102,102,102)" data-mce-style="color: #666666;">B. R.</span></b><span style="color:rgb(102,102,102)" data-mce-style="color: #666666;"></span></span></div></div><br><div><br></div></div><div class="gmail_quote"><div><div>On Mon, Mar 9, 2015 at 4:28 PM, Wiebe Cazemier <span dir="ltr"><<a href="mailto:wiebe@halfgaar.net" target="_blank" data-mce-href="mailto:wiebe@halfgaar.net">wiebe@halfgaar.net</a>></span> wrote:<br></div></div><blockquote style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex" class="gmail_quote" data-mce-style="margin: 0 0 0 .8ex; border-left: 1px #ccc solid; padding-left: 1ex;"><div><div><div><div style="font-family:Arial;font-size:12pt;color:#000000" data-mce-style="font-family: Arial; font-size: 12pt; color: #000000;"><div>Hello,<br></div><div><br></div><div>I have a question about sporadic long upstream response times I'm seeing on (two of) our Nginx servers. It's kind of hard to show and quantify, but I'll do my best.<br></div><div><br></div><div>One is a Django Gunicorn server. We included the upstream response time in the Nginx access log and wrote a script to analyze them. What we see, is that on the login page of a website (a page that does almost nothing) 95%-99% of 'GET /customer/login/' requests are processed within about 50 ms. The other few percent can take several seconds. Sometimes even 5s. Our Munin graphs show no correlation in disk latency, cpu time, memory use, etc.<br></div><div><br></div><div>I also added an access log to Gunicorn, so that I can see how long Gunicorn takes to process requests that Nginx thinks take long. Gunicorn has 8 workers. It can be seen that there is actually no delay in Gunicorn. For instance, Nginx sees this (the long upstream response time is marked red, 3.042s):<br></div><div><br></div><blockquote><div>11.22.33.44 - - [06/Mar/2015:10:27:46 +0100] "GET /customer/login/ HTTP/1.1" 200 8310 0.061 0.121 "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:48 +0100] "GET /customer/login/ HTTP/1.1" 200 8310 0.035 0.092 "-" "Echoping/6.0.2"<br>11.22.33.44 - - [<span style="color:rgb(0,0,255)" data-mce-style="color: #0000ff;">06/Mar/2015:10:27:52</span> +0100] "GET /customer/login/ HTTP/1.1" 200 8310 <span style="color:#cc0000" data-mce-style="color: #cc0000;">3.042 <span style="color:rgb(0,0,0)" data-mce-style="color: #000000;">3.098</span></span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:53 +0100] "GET /customer/login/ HTTP/1.1" 200 8310 0.051 0.108 "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:54 +0100] "GET /customer/login/ HTTP/1.1" 200 8310 0.038 0.096 "-" "Echoping/6.0.2"</div><div>x.x.x.x - - [06/Mar/2015:10:27:58 +0100] "POST /customer/login/?next=/customer/home/ HTTP/1.1" 302 5 0.123 0.123</div></blockquote><div><br></div><div>But then the corresponding Gunicorn logs shows normal response times (the figure after 'None', in µs) (Corresponding line marked blue):<br></div><blockquote><div><br></div><div>11.22.33.44 - - [06/Mar/2015:10:27:41] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">41686</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:42] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">27629</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:43] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">28143</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:44] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">41846</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:45] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">30192</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:46] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">59382</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:48] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">33308</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [<span style="color:rgb(0,0,255)" data-mce-style="color: #0000ff;">06/Mar/2015:10:27:52</span>] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">39849</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:53] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">48321</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:27:54] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">36484</span> "-" "Echoping/6.0.2"<br>x.x.x.x - - [06/Mar/2015:10:27:58] "POST /customer/login/?next=/customer/home/ HTTP/1.0" 302 None 122295<br>y.y.y.y - - [06/Mar/2015:10:28:02] "GET /customer/login/?next=/customer/home/ HTTP/1.0" 200 None 97824<br>y.y.y.y - - [06/Mar/2015:10:28:03] "GET /customer/login/?next=/customer/home/ HTTP/1.0" 200 None 78162<br>11.22.33.44 - - [06/Mar/2015:10:28:26] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">38350</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:28:27] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">31076</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:28:28] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">28536</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:28:30] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">30981</span> "-" "Echoping/6.0.2"<br>11.22.33.44 - - [06/Mar/2015:10:28:31] "GET /customer/login/ HTTP/1.0" 200 None <span style="color:rgb(51,153,102)" data-mce-style="color: #339966;">29920</span> "-" "Echoping/6.0.2"</div></blockquote><div><br></div><div>As I said, there are currently 8 workers. I already increased them from 4. The log above shows that there are enough seconds between each request that 8 workers should be able to handle it. I also created a MySQL slow log, which doesn't show the delays. MySQL is always fast.<br></div><div><br></div><div>Another server we have is Nginx with PHP-FPM (with 150 PHP children in the pool), no database access. On one particular recent log of a few hundred thousand entries, 99% of requests is done in 129ms. But one response even took 3170ms. Its PHP proxy settings are:<br></div><div><br></div><blockquote><div>location ~ \.php$ {<br> fastcgi_split_path_info ^(.+\.php)(/.+)$;<br> # NOTE: You should have "cgi.fix_pathinfo = 0;" in php.ini<br><div><br></div> # With php5-fpm:<br> fastcgi_pass unix:/var/run/php5-fpm.sock;<br> fastcgi_index index.php;<br> include fastcgi_params;<br>}<br></div></blockquote><div><br></div><div>It seems something in the communication between Nginx and the service behind it slows down sometimes, but I can't figure out what it might be. Any idea what it might be or how to diagnose it better?<br></div><div><br></div><div>Regards,<br></div><div><br></div><div>Wiebe Cazemier<br></div><div><br></div></div></div><br></div></div></blockquote></div></div></blockquote></div></div></div></div></div></blockquote><br></div></div></blockquote></div></div></div></blockquote></div></body></html>