Date: Sun, 14 Oct 2018 09:40:06 +0300 From: Maxim Dounin <mdounin@mdounin.ru> To: nginx@nginx.org Cc: freebsd-current@FreeBSD.org Subject: Re: nginx introduces extra delay when talking to slow backend (probably FreeBSD kevent specific) Message-ID: <20181014064006.GB56558@mdounin.ru> In-Reply-To: <20181012203126.GH79805@hades.panopticon> References: <20181012195101.GG79805@hades.panopticon> <20181012203126.GH79805@hades.panopticon>
next in thread | previous in thread | raw e-mail | index | archive | help
Hello!
On Fri, Oct 12, 2018 at 11:31:26PM +0300, Dmitry Marakasov wrote:
> * Dmitry Marakasov (amdmi3@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/
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20181014064006.GB56558>