nginx introduces extra delay when talking to slow backend (probably FreeBSD kevent specific)

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

nginx introduces extra delay when talking to slow backend (probably FreeBSD kevent specific)

Dmitry Marakasov
Hi!

I've noticed strange behavior of nginx with slow uwsgi backend (turned
out to not be uwsgi specific, and acually reproduces with any backend)
on FreeBSD 11.2

If backend replies in less than a second, nginx doesn't introduce any
additional latency and replies in the same time. However if backend
replies no more than around 1.2 seconds, nginx introduces an extra delay
and replies in around 2.2 seconds.

I've gathered some details here, including the graph of nginx reply time
vs. backend reply time:

https://github.com/AMDmi3/nginx-bug-demo

It reproduces on FreeBSD 11.2 and around year old -CURRENT, but not the
recent -CURRENT, so I suspect this may be FreeBSD specific (probably
kevent-related) and already fixed.

Still, I'm posting to both related nginx and FreeBSD lists for this
problem to be known.

--
Dmitry Marakasov   .   55B5 0596 FF1E 8D84 5F56  9510 D35A 80DD F9D2 F77D
[hidden email]  ..:              https://github.com/AMDmi3

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: nginx introduces extra delay when talking to slow backend (probably FreeBSD kevent specific)

Dmitry Marakasov
* Dmitry Marakasov ([hidden email]) wrote:

I've gathered ktrace dumps for both cases, and it really looks that
the problem is related to kevent. After nginx sends response back
to client, it calls kevent(2) on client fd (which is 5).

When there is a bug (FreeBSD 11.2), the following happens:

 49365 nginx    3.099362 CALL  kevent(0x7,0x8022a2000,0,0x8023005c0,0x200,0x7fffffffe598)
 49365 nginx    3.099419 STRU  struct kevent[] = {  }
 49365 nginx    3.194695 STRU  struct kevent[] = { { ident=5, filter=EVFILT_WRITE, flags=0x20<EV_CLEAR>, fflags=0, data=0xbf88, udata=0x8023633d1 } }
 49365 nginx    3.194733 RET   kevent 1
...
 49365 nginx    3.194858 CALL  kevent(0x7,0x8022a2000,0,0x8023005c0,0x200,0x7fffffffe598)
 49365 nginx    3.194875 STRU  struct kevent[] = {  }
 49365 nginx    3.835259 STRU  struct kevent[] = { { ident=5, filter=EVFILT_READ, flags=0x8020<EV_CLEAR|EV_EOF>, fflags=0, data=0, udata=0x802346111 } }
 49365 nginx    3.835299 RET   kevent 1

E.g. read and write events come separately, both with huge delays.

On FreeBSD-CURRENT which doesn't experience the problem, kdump looks this way:

  8049 nginx    3.081367 CALL  kevent(0x7,0x8012d1b40,0,0x8012da040,0x200,0x7fffffffe598)
  8049 nginx    3.081371 STRU  struct kevent[] = {  }
  8049 nginx    3.081492 STRU  struct kevent[] = { { ident=5, filter=EVFILT_WRITE, flags=0x20<EV_CLEAR>, fflags=0, data=0xbf88, udata=0x801341f11 }
             { ident=5, filter=EVFILT_READ, flags=0x8020<EV_CLEAR|EV_EOF>, fflags=0, data=0, udata=0x801324e51 } }
  8049 nginx    3.081498 RET   kevent 2

E.g. both events come immediately and at the same time.

Not sure if that's problem of kevent or something it relies on or the
way nginx uses it.

--
Dmitry Marakasov   .   55B5 0596 FF1E 8D84 5F56  9510 D35A 80DD F9D2 F77D
[hidden email]  ..:              https://github.com/AMDmi3

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: nginx introduces extra delay when talking to slow backend (probably FreeBSD kevent specific)

Maxim Dounin
Hello!

On Fri, Oct 12, 2018 at 11:31:26PM +0300, Dmitry Marakasov wrote:

> * Dmitry Marakasov ([hidden email]) wrote:
>
> I've gathered ktrace dumps for both cases, and it really looks that
> the problem is related to kevent. After nginx sends response back
> to client, it calls kevent(2) on client fd (which is 5).
>
> When there is a bug (FreeBSD 11.2), the following happens:
>
>  49365 nginx    3.099362 CALL  kevent(0x7,0x8022a2000,0,0x8023005c0,0x200,0x7fffffffe598)
>  49365 nginx    3.099419 STRU  struct kevent[] = {  }
>  49365 nginx    3.194695 STRU  struct kevent[] = { { ident=5, filter=EVFILT_WRITE, flags=0x20<EV_CLEAR>, fflags=0, data=0xbf88, udata=0x8023633d1 } }
>  49365 nginx    3.194733 RET   kevent 1
> ...
>  49365 nginx    3.194858 CALL  kevent(0x7,0x8022a2000,0,0x8023005c0,0x200,0x7fffffffe598)
>  49365 nginx    3.194875 STRU  struct kevent[] = {  }
>  49365 nginx    3.835259 STRU  struct kevent[] = { { ident=5, filter=EVFILT_READ, flags=0x8020<EV_CLEAR|EV_EOF>, fflags=0, data=0, udata=0x802346111 } }
>  49365 nginx    3.835299 RET   kevent 1
>
> E.g. read and write events come separately, both with huge delays.
>
> On FreeBSD-CURRENT which doesn't experience the problem, kdump looks this way:
>
>   8049 nginx    3.081367 CALL  kevent(0x7,0x8012d1b40,0,0x8012da040,0x200,0x7fffffffe598)
>   8049 nginx    3.081371 STRU  struct kevent[] = {  }
>   8049 nginx    3.081492 STRU  struct kevent[] = { { ident=5, filter=EVFILT_WRITE, flags=0x20<EV_CLEAR>, fflags=0, data=0xbf88, udata=0x801341f11 }
>              { ident=5, filter=EVFILT_READ, flags=0x8020<EV_CLEAR|EV_EOF>, fflags=0, data=0, udata=0x801324e51 } }
>   8049 nginx    3.081498 RET   kevent 2
>
> E.g. both events come immediately and at the same time.
>
> Not sure if that's problem of kevent or something it relies on or the
> way nginx uses it.

Have you tried looking into what happens in the client?  These
events are client-related, and seems to match what client does as
per tcpdump of traffic between nginx and the client.

Also, at least on my box (FreeBSD 10.4) this issue can be
reproduced with curl, but not with fetch or wget.  Seems to be
something curl-specific.  I'm not familiar with curl source code,
but it seems to be sitting in a poll() call without any file
descriptors for some reason:

  8862 curl     0.013972 GIO   fd 3 wrote 78 bytes
       "GET / HTTP/1.1\r
        Host: localhost:8080\r
        User-Agent: curl/7.61.0\r
        Accept: */*\r
        \r
       "
  8862 curl     0.013977 RET   sendto 78/0x4e
  8862 curl     0.013984 CALL  poll(0xbfbfe610,0x1,0)
  8862 curl     0.013987 RET   poll 0
  8862 curl     0.013992 CALL  poll(0xbfbfe768,0x1,0x1)
  8862 curl     0.016042 RET   poll 0
  8862 curl     0.016118 CALL  poll(0xbfbfe610,0x1,0)
  8862 curl     0.016137 RET   poll 0
  8862 curl     0.016197 CALL  poll(0xbfbfe768,0x1,0xc5)
  8862 curl     0.228557 RET   poll 0
  8862 curl     0.228605 CALL  poll(0xbfbfe610,0x1,0)
  8862 curl     0.228617 RET   poll 0
  8862 curl     0.228631 CALL  poll(0xbfbfe768,0x1,0x3e8)
  8862 curl     1.246374 RET   poll 0
  8862 curl     1.246420 CALL  poll(0,0,0x3e8)
  8862 curl     2.298297 RET   poll 0
  8862 curl     2.298410 CALL  poll(0xbfbfe610,0x1,0)
  8862 curl     2.298452 RET   poll 1
  8862 curl     2.298517 CALL  recvfrom(0x3,0x28ca0000,0x19000,0,0,0)
  8862 curl     2.298584 GIO   fd 3 read 171 bytes
       "HTTP/1.1 200 OK\r
        Server: nginx/1.15.5\r

Note these lines:

  8862 curl     1.246420 CALL  poll(0,0,0x3e8)
  8862 curl     2.298297 RET   poll 0

This is a call without any file descriptors and with 1000
millisecond timeout, so it will result in an unconditional 1
second delay.

Not sure why you are seeing the problem with some FreeBSD version
but not others, but different curl versions or curl compilation
flags may explain things.  In my case curl version is as follows:

$ curl --version
curl 7.61.0 (i386-portbld-freebsd10.4) libcurl/7.61.0 OpenSSL/1.0.1u zlib/1.2.11 nghttp2/1.32.0
Release-Date: 2018-07-11
Protocols: dict file ftp ftps gopher http https imap imaps pop3 pop3s rtsp smtp smtps telnet tftp
Features: AsynchDNS IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy

Upgrading curl to 7.61.1 doesn't fix things.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx