Hello!

On Mon, Feb 13, 2017 at 07:16:00AM -0500, MichaelLogutov wrote:

> Maxim Dounin Wrote:
> -------------------------------------------------------
> > Hello!
> >
> > On Sat, Feb 11, 2017 at 04:06:29PM -0500, MichaelLogutov wrote:
> >
> > > Hello.
> > > We have some strange issues when requests seems to stall inside
> > nginx - in
> > > nginx log we see that request took 1 second (and was terminated by
> > client
> > > timeout), while excactly the same request (we have special unique
> > headers to
> > > mark them) from the uwsgi logs took only 100ms to complete.
> >
> > It is not clear how do you measure that request took 1 second.
> > Note well that request time as seen by nginx is unlikely to be
> > less that the time seen by your backend, but can easily be much
> > longer: for example, nginx has to read the request from client,
> > and it sometimes takes significant time.
> >
> > > We also saw some very strange pauses in nginx debug log:
> >
> > [...]
> >
> > I don't see any "strange pauses" in the logs provided. If you
> > think there are any - please elaborate.
> >
> > Note well that it's almost impossible to analize debug logs for
> > pauses if these logs doesn't contain information about processing
> > of events. To make sure all needed information is present it is
> > important to configure debug logs at global level, as recommended
> > at http://nginx.org/en/docs/debugging_log.html.
>
> Thank you.
> I was talking about 3 seconds gap here:
>
> 2017/01/26 20:17:51 [debug] 2749#0: *75780960 http upstream recv(): -1 (11:
> Resource temporarily unavailable)
> 2017/01/26 20:17:54 [debug] 2749#0: *75780960 http upstream request:
> "/api/info/account/type/278933/?"

Ah, sorry, I didn't notice this.

The time gap here looks like waiting of connect() to complete. It
follows connect():

2017/01/26 20:17:51 [debug] 2749#0: *75780960 connect to 10.0.0.176:80, fd:500 #75780961

and in turn it is followed by sending the request to the upstream
server:

2017/01/26 20:17:54 [debug] 2749#0: *75780960 http upstream send request handler

(The "http upstream recv()" message is a part of checking if the
client closed the connection, and is unrelated.)

The 3 seconds here suggests that there is a packet loss somewhere
between nginx and the backend. Most likely the backend is simply
overloaded, and its listen socket queue overflows and drops
packets. On Linux it may be a good idea to use
net.ipv4.tcp_abort_on_overflows=1 to better diagnose such
problems. Examining listen queue via "ss -nltp" on the backend
might also help.

--
Maxim Dounin
http://nginx.org/
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx