From owner-freebsd-current@freebsd.org Fri Oct 12 20:40:02 2018 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 18A3510C9F68 for ; Fri, 12 Oct 2018 20:40:02 +0000 (UTC) (envelope-from amdmi3@amdmi3.ru) Received: from ihor-3.amdmi3.ru (ihor-3.amdmi3.ru [185.117.152.228]) by mx1.freebsd.org (Postfix) with ESMTP id A765475248 for ; Fri, 12 Oct 2018 20:40:01 +0000 (UTC) (envelope-from amdmi3@amdmi3.ru) Received: from amdmi3.ru (localhost [127.0.0.1]) by ihor-3.amdmi3.ru (Postfix) with SMTP id 5ECE61AF11D; Fri, 12 Oct 2018 23:40:00 +0300 (MSK) Received: by amdmi3.ru (nbSMTP-1.00) for uid 1000 amdmi3@amdmi3.ru; Fri, 12 Oct 2018 23:40:00 +0300 (MSK) Date: Fri, 12 Oct 2018 23:31:26 +0300 From: Dmitry Marakasov To: nginx@nginx.org, freebsd-current@FreeBSD.org Subject: Re: nginx introduces extra delay when talking to slow backend (probably FreeBSD kevent specific) Message-ID: <20181012203126.GH79805@hades.panopticon> References: <20181012195101.GG79805@hades.panopticon> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline In-Reply-To: <20181012195101.GG79805@hades.panopticon> User-Agent: Mutt/1.10.1 (2018-07-13) X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.27 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 12 Oct 2018 20:40:02 -0000 * 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, 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, 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, fflags=0, data=0xbf88, udata=0x801341f11 } { ident=5, filter=EVFILT_READ, flags=0x8020, 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 amdmi3@amdmi3.ru ..: https://github.com/AMDmi3