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 (amdmi3 at amdmi3.ru) 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/