From owner-freebsd-stable@freebsd.org Thu Sep 22 09:28:43 2016 Return-Path: Delivered-To: freebsd-stable@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 049ABBE3674 for ; Thu, 22 Sep 2016 09:28:43 +0000 (UTC) (envelope-from julien.charbon@gmail.com) Received: from mail-wm0-f46.google.com (mail-wm0-f46.google.com [74.125.82.46]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id A9956F31 for ; Thu, 22 Sep 2016 09:28:42 +0000 (UTC) (envelope-from julien.charbon@gmail.com) Received: by mail-wm0-f46.google.com with SMTP id l132so137147795wmf.1 for ; Thu, 22 Sep 2016 02:28:42 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:subject:to:references:cc:message-id:date :user-agent:mime-version:in-reply-to; bh=I+QrymTMW6wvBJPlMH8F7dtMRM+p/6TjIqvPHG92LGo=; b=NxNasZyap0f5cKoh+GE5w80UltWSiqqOFzgeT8M9SvGW7VPN6+ITchDXs1kmX8Z4mJ G5R2ROgFJEJa/QsJGYIHDIKCM3zlwt+oenyEa7ZM9JcsXgx91OBkJat6W+VJmYX+mff9 ooAwja7sNUXlYwEGEjdklTGhhmotiwBAN4tPaXRDW6juVGu5YJXBsz7SXvGpF6vV37hZ 9cfMG3AgqnWSHcnkDtKM0CvaQlSG1C6e5bz1K+Y/8e5dPh8kz1D+dvmIKJfWVBe0BbXd A+lgJ2RMuq6QDGfjinr4YfT1lH6YOCIjHrwIp+zEZD2nypx5uweOLo/t/kG9w22oWJxp PiUg== X-Gm-Message-State: AE9vXwO+WFNSA/wmmT25jME/UF/JFRGe/x8BxAb4dENVQYHXfTKr59BK7pNXvyEtv6wRCg== X-Received: by 10.28.215.67 with SMTP id o64mr1430067wmg.98.1474536520885; Thu, 22 Sep 2016 02:28:40 -0700 (PDT) Received: from [10.100.64.44] ([217.30.88.7]) by smtp.gmail.com with ESMTPSA id 137sm36795859wmi.16.2016.09.22.02.28.39 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 22 Sep 2016 02:28:40 -0700 (PDT) From: Julien Charbon Subject: Re: 11.0 stuck on high network load To: Slawa Olhovchenkov References: <20160915085938.GN38409@kib.kiev.ua> <20160915090633.GS2840@zxy.spb.ru> <20160916181839.GC2960@zxy.spb.ru> <20160916183053.GL9397@strugglingcoder.info> <20160916190330.GG2840@zxy.spb.ru> <78cbcdc9-f565-1046-c157-2ddd8fcccc62@freebsd.org> <20160919204328.GN2840@zxy.spb.ru> <8ba75d6e-4f01-895e-0aed-53c6c6692cb9@freebsd.org> <20160920202633.GQ2840@zxy.spb.ru> <20160921083148.GU2840@zxy.spb.ru> X-Mozilla-News-Host: news://news.gmane.org Cc: Konstantin Belousov , freebsd-stable@FreeBSD.org, hiren panchasara Message-ID: <05ba1a3a-2d99-f8e2-40a1-4c1fca317db3@freebsd.org> Date: Thu, 22 Sep 2016 11:28:38 +0200 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:45.0) Gecko/20100101 Thunderbird/45.2.0 MIME-Version: 1.0 In-Reply-To: <20160921083148.GU2840@zxy.spb.ru> Content-Type: multipart/signed; micalg=pgp-sha512; protocol="application/pgp-signature"; boundary="5WrnxOFLdULVi1adJj9CXBnKvjsw6ABrP" X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 22 Sep 2016 09:28:43 -0000 This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --5WrnxOFLdULVi1adJj9CXBnKvjsw6ABrP Content-Type: multipart/mixed; boundary="nDdrl8RqBsaIktWKwGtj7FQJva3SNWuwD"; protected-headers="v1" From: Julien Charbon To: Slawa Olhovchenkov Cc: Konstantin Belousov , freebsd-stable@FreeBSD.org, hiren panchasara Message-ID: <05ba1a3a-2d99-f8e2-40a1-4c1fca317db3@freebsd.org> Subject: Re: 11.0 stuck on high network load References: <20160915085938.GN38409@kib.kiev.ua> <20160915090633.GS2840@zxy.spb.ru> <20160916181839.GC2960@zxy.spb.ru> <20160916183053.GL9397@strugglingcoder.info> <20160916190330.GG2840@zxy.spb.ru> <78cbcdc9-f565-1046-c157-2ddd8fcccc62@freebsd.org> <20160919204328.GN2840@zxy.spb.ru> <8ba75d6e-4f01-895e-0aed-53c6c6692cb9@freebsd.org> <20160920202633.GQ2840@zxy.spb.ru> <20160921083148.GU2840@zxy.spb.ru> In-Reply-To: <20160921083148.GU2840@zxy.spb.ru> --nDdrl8RqBsaIktWKwGtj7FQJva3SNWuwD Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: quoted-printable Hi Slawa, On 9/21/16 10:31 AM, Slawa Olhovchenkov wrote: > On Wed, Sep 21, 2016 at 09:11:24AM +0200, Julien Charbon wrote: >> On 9/20/16 10:26 PM, Slawa Olhovchenkov wrote: >>> On Tue, Sep 20, 2016 at 10:00:25PM +0200, Julien Charbon wrote: >>>> On 9/19/16 10:43 PM, Slawa Olhovchenkov wrote: >>>>> On Mon, Sep 19, 2016 at 10:32:13PM +0200, Julien Charbon wrote: >>>>>> >>>>>>> @ CPU_CLK_UNHALTED_CORE [4653445 samples] >>>>>>> >>>>>>> 51.86% [2413083] lock_delay @ /boot/kernel.VSTREAM/kernel >>>>>>> 100.0% [2413083] __rw_wlock_hard >>>>>>> 100.0% [2413083] tcp_tw_2msl_scan >>>>>>> 99.99% [2412958] pfslowtimo >>>>>>> 100.0% [2412958] softclock_call_cc >>>>>>> 100.0% [2412958] softclock >>>>>>> 100.0% [2412958] intr_event_execute_handlers >>>>>>> 100.0% [2412958] ithread_loop >>>>>>> 100.0% [2412958] fork_exit >>>>>>> 00.01% [125] tcp_twstart >>>>>>> 100.0% [125] tcp_do_segment >>>>>>> 100.0% [125] tcp_input >>>>>>> 100.0% [125] ip_input >>>>>>> 100.0% [125] swi_net >>>>>>> 100.0% [125] intr_event_execute_handlers >>>>>>> 100.0% [125] ithread_loop >>>>>>> 100.0% [125] fork_exit >>>>>> >>>>>> The only write lock tcp_tw_2msl_scan() tries to get is a >>>>>> INP_WLOCK(inp). Thus here, tcp_tw_2msl_scan() seems to be stuck >>>>>> spinning on INP_WLOCK (or pfslowtimo() is going crazy and calls >>>>>> tcp_tw_2msl_scan() at high rate but this will be quite unexpected)= =2E >>>>>> >>>>>> Thus my hypothesis is that something is holding the INP_WLOCK and= not >>>>>> releasing it, and tcp_tw_2msl_scan() is spinning on it. >>>>>> >>>>>> If you can, could you compile the kernel with below options: >>>>>> >>>>>> options DDB # Support DDB. >>>>>> options DEADLKRES # Enable the deadlock resol= ver >>>>>> options INVARIANTS # Enable calls of extra san= ity >>>>>> checking >>>>>> options INVARIANT_SUPPORT # Extra sanity checks of in= ternal >>>>>> structures, required by INVARIANTS >>>>>> options WITNESS # Enable checks to detect >>>>>> deadlocks and cycles >>>>>> options WITNESS_SKIPSPIN # Don't run witness on spin= locks >>>>>> for speed >>>>> >>>>> Currently this host run with 100% CPU load (on all cores), i.e. >>>>> enabling WITNESS will be significant drop performance. >>>>> Can I use only some subset of options? >>>>> >>>>> Also, I can some troubles to DDB enter in this case. >>>>> May be kgdb will be success (not tryed yet)? >>>> >>>> If these kernel options will certainly slow down your kernel, they = also >>>> might found the root cause of your issue before reaching the point w= here >>>> you have 100% cpu load on all cores (thanks to INVARIANTS). I would= >>>> suggest: >>> >>> Hmmm, may be I am not clarified. >>> This host run at peak hours with 100% CPU load as normal operation, >>> this is for servering 2x10G, this is CPU load not result of lock >>> issuse, this is not us case. And this is because I am fear to enable >>> WITNESS -- I am fear drop performance. >>> >>> This lock issuse happen irregulary and may be caused by other issuse >>> (nginx crashed). In this case about 1/3 cores have 100% cpu load, >>> perhaps by this lock -- I am can trace only from one core and need >>> more then hour for this (may be on other cores different trace, I >>> can't guaranted anything). >> >> I see, especially if you are running in production WITNESS might inde= ed >> be not practical for you. In this case, I would suggest before doing >> WITNESS and still get more information to: >> >> #0: Do a lock profiling: >> >> https://www.freebsd.org/cgi/man.cgi?query=3DLOCK_PROFILING >> >> options LOCK_PROFILING >> >> Example of usage: >> >> # Run >> $ sudo sysctl debug.lock.prof.enable=3D1 >> $ sleep 10 >> $ sudo sysctl debug.lock.prof.enable=3D0 >> >> # Get results >> $ sysctl debug.lock.prof.stats | head -2; sysctl debug.lock.prof.stats= | >> sort -n -k 4 -r >=20 > OK, but in case of leak lock (why inp lock too long for > tcp_tw_2msl_scan?) I can't see cause of this lock running this > commands after stuck happen? >=20 >>> What purpose to not skip locked tcptw in this loop? >> >> If I understand your question correctly: According to your pmcstat >> result, tcp_tw_2msl_scan() currently struggles with a write lock >> (__rw_wlock_hard) and the only write lock used tcp_tw_2msl_scan() is >> INP_WLOCK. No sign of contention on TW_RLOCK(V_tw_lock) currently. >=20 > As I see in code, tcp_tw_2msl_scan got first node from V_twq_2msl and > need got RW lock on inp w/o alternates. Can tcp_tw_2msl_scan skip curre= nt node > and go to next node in V_twq_2msl list if current node locked by some > reasson? Interesting question indeed: It is not optimal that all simultaneous calls to tcp_tw_2msl_scan() compete for the same oldest tcptw. The next tcptws in the list are certainly old enough also. Let me see if I can make a simple change that makes kernel threads calling tcp_tw_2msl_scan() at same time to work on a different old enough tcptws. So far, I found only solutions quite complex to implement= =2E -- Julien --nDdrl8RqBsaIktWKwGtj7FQJva3SNWuwD-- --5WrnxOFLdULVi1adJj9CXBnKvjsw6ABrP Content-Type: application/pgp-signature; name="signature.asc" Content-Description: OpenPGP digital signature Content-Disposition: attachment; filename="signature.asc" -----BEGIN PGP SIGNATURE----- Comment: GPGTools - https://gpgtools.org iQEcBAEBCgAGBQJX46RHAAoJEKVlQ5Je6dhx/kAIAJ5JeWeAmgBn4vyYboMP2XIL h7rqNrTtGfFYxkjp03TgHk27iCUCUTJHfMpsZ0hoFKypi4n648bvFFZadrfVZZxq 1dzDfJm5DJcHgKu0iL7NDw2pGHx3NwLPPVCiP/1kMxuzHTTfHW5Pm/2+FxKUZYKg SZian0jdtxXkZTsYTtOXo2Gug3h/FA9PgPCJHPt3T6Nzwdlk4r4ou1OVh0Cxq/fn JjLMc8AM2YFtZj1us9RAPo2cShbR3RgJlt5K7Rwa9OMmstX3IFHr+MmO1ZHSVzjh 4IwfYwBFyrxpwN815Q+H3BIP7mAOVGFytNMRi4zg5XdlX7gNaHVJeUS0+sLJlzM= =ixjt -----END PGP SIGNATURE----- --5WrnxOFLdULVi1adJj9CXBnKvjsw6ABrP--