Date: Mon, 26 Sep 2016 09:03:42 +0200 From: Julien Charbon <jch@freebsd.org> To: Slawa Olhovchenkov <slw@zxy.spb.ru> Cc: Konstantin Belousov <kostikbel@gmail.com>, freebsd-stable@FreeBSD.org, hiren panchasara <hiren@strugglingcoder.info> Subject: Re: 11.0 stuck on high network load Message-ID: <0a1522c0-bf23-8862-7785-94076e2e8d70@freebsd.org> In-Reply-To: <20160923191656.GF2840@zxy.spb.ru> References: <78cbcdc9-f565-1046-c157-2ddd8fcccc62@freebsd.org> <20160919204328.GN2840@zxy.spb.ru> <8ba75d6e-4f01-895e-0aed-53c6c6692cb9@freebsd.org> <20160920202633.GQ2840@zxy.spb.ru> <f644cd52-4377-aa90-123a-3a2887972bbc@freebsd.org> <20160921195155.GW2840@zxy.spb.ru> <e4e0188c-b22b-29af-ed15-b650c3ec4553@gmail.com> <20160922095331.GB2840@zxy.spb.ru> <67862b33-63c0-2f23-d254-5ddc55dbb554@freebsd.org> <20160922102045.GC2840@zxy.spb.ru> <20160923191656.GF2840@zxy.spb.ru>
next in thread | previous in thread | raw e-mail | index | archive | help
This is an OpenPGP/MIME signed message (RFC 4880 and 3156)
--4UdjdloAavhgGhlDNQTC5rJuu8bdjFenc
Content-Type: multipart/mixed; boundary="GOI7f8WkMNfWtsDtwWXMNSIBf9GVuUV42";
protected-headers="v1"
From: Julien Charbon <jch@freebsd.org>
To: Slawa Olhovchenkov <slw@zxy.spb.ru>
Cc: Konstantin Belousov <kostikbel@gmail.com>, freebsd-stable@FreeBSD.org,
hiren panchasara <hiren@strugglingcoder.info>
Message-ID: <0a1522c0-bf23-8862-7785-94076e2e8d70@freebsd.org>
Subject: Re: 11.0 stuck on high network load
References: <78cbcdc9-f565-1046-c157-2ddd8fcccc62@freebsd.org>
<20160919204328.GN2840@zxy.spb.ru>
<8ba75d6e-4f01-895e-0aed-53c6c6692cb9@freebsd.org>
<20160920202633.GQ2840@zxy.spb.ru>
<f644cd52-4377-aa90-123a-3a2887972bbc@freebsd.org>
<20160921195155.GW2840@zxy.spb.ru>
<e4e0188c-b22b-29af-ed15-b650c3ec4553@gmail.com>
<20160922095331.GB2840@zxy.spb.ru>
<67862b33-63c0-2f23-d254-5ddc55dbb554@freebsd.org>
<20160922102045.GC2840@zxy.spb.ru> <20160923191656.GF2840@zxy.spb.ru>
In-Reply-To: <20160923191656.GF2840@zxy.spb.ru>
--GOI7f8WkMNfWtsDtwWXMNSIBf9GVuUV42
Content-Type: text/plain; charset=windows-1252
Content-Transfer-Encoding: quoted-printable
Hi Slawa,
On 9/23/16 9:16 PM, Slawa Olhovchenkov wrote:
> On Thu, Sep 22, 2016 at 01:20:45PM +0300, Slawa Olhovchenkov wrote:
>=20
>> On Thu, Sep 22, 2016 at 12:04:40PM +0200, Julien Charbon wrote:
>>
>>>>> These paths can indeed compete for the same INP lock, as both
>>>>> tcp_tw_2msl_scan() calls always start with the first inp found in
>>>>> twq_2msl list. But in both cases, this first inp should be quickly=
used
>>>>> and its lock released anyway, thus that could explain your situatio=
n it
>>>>> that the TCP stack is doing that all the time, for example:
>>>>>
>>>>> - Let say that you are running out completely and constantly of tc=
ptw,
>>>>> and then all connections transitioning to TIME_WAIT state are compe=
ting
>>>>> with the TIME_WAIT timeout scan that tries to free all the expired
>>>>> tcptw. If the stack is doing that all the time, it can appear like=
>>>>> "live" locked.
>>>>>
>>>>> This is just an hypothesis and as usual might be a red herring.
>>>>> Anyway, could you run:
>>>>>
>>>>> $ vmstat -z | head -2; vmstat -z | grep -E 'tcp|sock'
>>>>
>>>> ITEM SIZE LIMIT USED FREE REQ FAIL S=
LEEP
>>>>
>>>> socket: 864, 4192664, 18604, 25348,49276158, 0=
, 0
>>>> tcp_inpcb: 464, 4192664, 34226, 18702,49250593, 0=
, 0
>>>> tcpcb: 1040, 4192665, 18424, 18953,49250593, 0=
, 0
>>>> tcptw: 88, 16425, 15802, 623,14526919, 8,=
0
>>>> tcpreass: 40, 32800, 15, 2285, 632381, 0,=
0
>>>>
>>>> In normal case tcptw is about 16425/600/900
>>>>
>>>> And after `sysctl -a | grep tcp` system stuck on serial console and =
I am reset it.
>>>>
>>>>> Ideally, once when everything is ok, and once when you have the is=
sue
>>>>> to see the differences (if any).
>>>>>
>>>>> If it appears your are quite low in tcptw, and if you have enough
>>>>> memory, could you try increase the tcptw limit using sysctl
>>>>
>>>> I think this is not eliminate stuck, just may do it less frequency
>>>
>>> You are right, it would just be a big hint that the tcp_tw_2msl_scan=
()
>>> contention hypothesis is the right one. As I see you have plenty of
>>> memory on your server, thus could you try with:
>>>
>>> net.inet.tcp.maxtcptw=3D4192665
>>>
>>> And see what happen. Just to validate this hypothesis.
>>
>> This is bad way for validate, with maxtcptw=3D16384 happened is random=
>> and can be waited for month. After maxtcptw=3D4192665 I am don't know
>> how long need to wait for verification this hypothesis.
>>
>> More frequency (may be 3-5 times per day) happening less traffic drops=
>> (not to zero for minutes). May be this caused also by contention in
>> tcp_tw_2msl_scan, but fast resolved (stochastic process). By eating
>> CPU power nginx can't service connection and clients closed
>> connections and need more TIME_WAIT and can trigered
>> tcp_tw_2msl_scan(reuse=3D1). After this we can got live lock.
>>
>> May be after I learning to catch and dignostic this validation is more=
>> accurately.
>=20
> Some more bits:
>=20
> socket: 864, 4192664, 30806, 790,28524160, 0, =
0
> ipq: 56, 32802, 0, 1278, 1022, 0, =
0
> udp_inpcb: 464, 4192664, 44, 364, 14066, 0, =
0
> udpcb: 32, 4192750, 44, 3081, 14066, 0, =
0
> tcp_inpcb: 464, 4192664, 38558, 378,28476709, 0, =
0
> tcpcb: 1040, 4192665, 30690, 738,28476709, 0, =
0
> tcptw: 88, 32805, 7868, 772, 8412249, 0, =
0
>=20
> last pid: 49575; load averages: 2.00, 2.05, 3.75 up 1+01:12:08 =
22:13:42
> 853 processes: 15 running, 769 sleeping, 35 waiting, 34 lock
> CPU 0: 0.0% user, 0.0% nice, 0.0% system, 100% interrupt, 0.0% id=
le
> CPU 1: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 2: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 3: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 4: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 5: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 6: 0.0% user, 0.0% nice, 0.4% system, 0.0% interrupt, 99.6% id=
le
> CPU 7: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 8: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 9: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> CPU 10: 0.0% user, 0.0% nice, 0.4% system, 0.0% interrupt, 99.6% id=
le
> CPU 11: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% id=
le
> Mem: 8659M Active, 8385M Inact, 107G Wired, 1325M Free
> ARC: 99G Total, 88G MFU, 10G MRU, 32K Anon, 167M Header, 529M Other
> Swap: 32G Total, 32G Free
>=20
> PID UID PRI NICE SIZE RES STATE C TIME WCPU COMMAND
> 49566 0 20 0 26264K 7068K CPU10 10 0:00 0.14% top
> 5 0 -8 - 0K 192K l2arc_ 6 31:07 0.13% zfskern{=
l2arc_fe
> 46120 0 20 0 14608K 3868K nanslp 8 0:10 0.10% tcpw
> 12 0 -76 - 0K 848K WAIT 1 0:00 0.02% intr{swi=
0: uart=20
>=20
>=20
> total =3D used + free
> Max used total used total =
used total used total
> 2016-09-23 21:46:41 tcptw 32805 389 1665 0 tcpcb 27788 28557 inp=
cb 28177 29296 socket 27875 28740
> 2016-09-23 21:46:42 tcptw 32805 409 1665 0 tcpcb 27723 28557 inp=
cb 28132 29296 socket 27812 28740
> 2016-09-23 21:46:43 tcptw 32805 405 1665 0 tcpcb 27750 28557 inp=
cb 28155 29296 socket 27838 28740
> 2016-09-23 21:46:44 tcptw 32805 409 1665 0 tcpcb 27765 28557 inp=
cb 28174 29296 socket 27852 28740
> 2016-09-23 21:46:45 tcptw 32805 422 1665 0 tcpcb 27737 28557 inp=
cb 28159 29296 socket 27824 28740
> 2016-09-23 21:46:46 tcptw 32805 444 1665 0 tcpcb 27729 28557 inp=
cb 28173 29296 socket 27817 28740
> 2016-09-23 21:46:47 tcptw 32805 444 1665 0 tcpcb 27712 28557 inp=
cb 28156 29296 socket 27800 28740
> 2016-09-23 21:46:48 tcptw 32805 428 1665 0 tcpcb 27693 28557 inp=
cb 28121 29296 socket 27783 28740
> 2016-09-23 21:46:49 tcptw 32805 431 1665 0 tcpcb 27677 28557 inp=
cb 28108 29296 socket 27766 28740
> 2016-09-23 21:46:50 tcptw 32805 455 1665 0 tcpcb 27721 28557 inp=
cb 28176 29296 socket 27809 28740
> 2016-09-23 21:46:51 tcptw 32805 432 1665 0 tcpcb 27739 28557 inp=
cb 28171 29296 socket 27828 28740
> 2016-09-23 21:46:52 tcptw 32805 434 1665 0 tcpcb 27731 28557 inp=
cb 28165 29296 socket 27819 28740
> 2016-09-23 21:46:53 tcptw 32805 431 1665 0 tcpcb 27742 28557 inp=
cb 28173 29296 socket 27831 28740
> 2016-09-23 21:46:54 tcptw 32805 424 1665 0 tcpcb 27738 28557 inp=
cb 28162 29296 socket 27826 28740
> 2016-09-23 21:46:55 tcptw 32805 397 1665 0 tcpcb 27740 28557 inp=
cb 28137 29296 socket 27827 28740
> 2016-09-23 21:46:56 tcptw 32805 412 1665 0 tcpcb 27742 28557 inp=
cb 28154 29296 socket 27830 28740
> 2016-09-23 21:46:57 tcptw 32805 418 1665 0 tcpcb 27749 28557 inp=
cb 28167 29296 socket 27838 28740
> 2016-09-23 21:46:58 tcptw 32805 426 1665 0 tcpcb 27740 28557 inp=
cb 28166 29296 socket 27827 28740
> 2016-09-23 21:46:59 tcptw 32805 423 1665 0 tcpcb 27687 28557 inp=
cb 28110 29296 socket 27773 28740
> 2016-09-23 21:47:00 tcptw 32805 426 1665 0 tcpcb 27716 28557 inp=
cb 28142 29296 socket 27804 28740
> 2016-09-23 21:47:01 tcptw 32805 437 1665 0 tcpcb 27732 28557 inp=
cb 28169 29296 socket 27821 28740
> 2016-09-23 21:47:02 tcptw 32805 471 1665 0 tcpcb 27672 28557 inp=
cb 28143 29296 socket 27760 28740
> 2016-09-23 21:47:03 tcptw 32805 426 1665 0 tcpcb 27752 28557 inp=
cb 28178 29296 socket 27838 28740
> 2016-09-23 21:47:04 tcptw 32805 402 1665 0 tcpcb 27760 28557 inp=
cb 28162 29296 socket 27847 28740
> 2016-09-23 21:47:05 tcptw 32805 406 1665 0 tcpcb 27757 28557 inp=
cb 28163 29296 socket 27845 28740
> 2016-09-23 21:47:06 tcptw 32805 443 1665 0 tcpcb 27783 28557 inp=
cb 28226 29296 socket 27871 28740
> 2016-09-23 21:47:07 tcptw 32805 484 1665 0 tcpcb 27707 28557 inp=
cb 28191 29296 socket 27794 28740
> 2016-09-23 21:47:08 tcptw 32805 473 1665 0 tcpcb 27721 28557 inp=
cb 28194 29296 socket 27807 28740
> 2016-09-23 21:47:09 tcptw 32805 432 1665 0 tcpcb 27749 28557 inp=
cb 28181 29296 socket 27837 28740
> 2016-09-23 21:47:10 tcptw 32805 421 1665 0 tcpcb 27780 28557 inp=
cb 28201 29296 socket 27868 28740
> 2016-09-23 21:47:11 tcptw 32805 530 1665 0 tcpcb 27814 28557 inp=
cb 28344 29296 socket 27902 28740
> 2016-09-23 21:47:12 tcptw 32805 680 1665 0 tcpcb 27874 28557 inp=
cb 28554 29296 socket 27964 28740
> 2016-09-23 21:47:13 tcptw 32805 832 1665 0 tcpcb 27881 28557 inp=
cb 28713 29296 socket 27971 28740
> 2016-09-23 21:47:14 tcptw 32805 997 1665 0 tcpcb 27880 28557 inp=
cb 28877 29352 socket 27972 28740
> 2016-09-23 21:47:15 tcptw 32805 1155 1890 0 tcpcb 27931 28557 inp=
cb 29086 29560 socket 28023 28740
> 2016-09-23 21:47:16 tcptw 32805 1322 2250 0 tcpcb 27981 28557 inp=
cb 29303 29800 socket 28075 28740
> 2016-09-23 21:47:17 tcptw 32805 1496 2385 0 tcpcb 28065 28557 inp=
cb 29561 30040 socket 28159 28740
> 2016-09-23 21:47:18 tcptw 32805 1648 2385 0 tcpcb 28151 28557 inp=
cb 29799 30280 socket 28245 28740
> 2016-09-23 21:47:19 tcptw 32805 1790 2655 0 tcpcb 28398 28599 inp=
cb 30188 30672 socket 28492 28796
> 2016-09-23 21:47:20 tcptw 32805 1954 2655 0 tcpcb 28712 28923 inp=
cb 30666 31120 socket 28807 29116
> 2016-09-23 21:47:21 tcptw 32805 2115 3015 0 tcpcb 29061 29244 inp=
cb 31176 31576 socket 29156 29468
> 2016-09-23 21:47:22 tcptw 32805 2265 3150 0 tcpcb 29335 29538 inp=
cb 31600 32056 socket 29430 29704
> 2016-09-23 21:47:23 tcptw 32805 2424 3150 0 tcpcb 29553 29775 inp=
cb 31977 32440 socket 29648 29956
> 2016-09-23 21:47:24 tcptw 32805 2590 3375 0 tcpcb 29711 29901 inp=
cb 32301 32744 socket 29807 30112
> 2016-09-23 21:47:25 tcptw 32805 2760 3780 0 tcpcb 29794 30015 inp=
cb 32554 33040 socket 29891 30224
> 2016-09-23 21:47:26 tcptw 32805 2935 3915 0 tcpcb 29879 30111 inp=
cb 32814 33312 socket 29976 30292
> 2016-09-23 21:47:27 tcptw 32805 3109 3915 0 tcpcb 29953 30195 inp=
cb 33062 33584 socket 30050 30392
> 2016-09-23 21:47:28 tcptw 32805 3264 4140 0 tcpcb 30060 30267 inp=
cb 33324 33824 socket 30158 30476
> 2016-09-23 21:47:29 tcptw 32805 3435 4275 0 tcpcb 30137 30363 inp=
cb 33572 34032 socket 30235 30572
> 2016-09-23 21:47:30 tcptw 32805 3600 4500 0 tcpcb 30221 30489 inp=
cb 33821 34304 socket 30320 30644
> 2016-09-23 21:47:31 tcptw 32805 3775 4635 0 tcpcb 30309 30588 inp=
cb 34084 34576 socket 30408 30740
> 2016-09-23 21:47:32 tcptw 32805 3936 4770 0 tcpcb 30534 30741 inp=
cb 34470 34960 socket 30634 30908
> 2016-09-23 21:47:33 tcptw 32805 4097 4905 0 tcpcb 30744 30951 inp=
cb 34841 35352 socket 30844 31160
> 2016-09-23 21:47:34 tcptw 32805 4233 5040 0 tcpcb 31006 31176 inp=
cb 35239 35680 socket 31106 31372
> 2016-09-23 21:47:35 tcptw 32805 4366 5265 0 tcpcb 31160 31386 inp=
cb 35526 35920 socket 31260 31568
> 2016-09-23 21:47:36 tcptw 32805 4738 5535 0 tcpcb 29529 31428 inp=
cb 34267 36016 socket 29629 31596
> 2016-09-23 21:47:37 tcptw 32805 4879 5625 0 tcpcb 29506 31428 inp=
cb 34385 36016 socket 29607 31596
> 2016-09-23 21:47:38 tcptw 32805 5011 5895 0 tcpcb 29590 31428 inp=
cb 34601 36016 socket 29691 31596
> 2016-09-23 21:47:39 tcptw 32805 5130 5895 0 tcpcb 29713 31428 inp=
cb 34843 36016 socket 29815 31596
> 2016-09-23 21:47:40 tcptw 32805 5259 6165 0 tcpcb 29783 31428 inp=
cb 35042 36016 socket 29886 31596
> 2016-09-23 21:47:41 tcptw 32805 5378 6255 0 tcpcb 29606 31428 inp=
cb 34984 36016 socket 29709 31596
> 2016-09-23 21:47:42 tcptw 32805 5489 6255 0 tcpcb 29638 31428 inp=
cb 35127 36016 socket 29741 31596
> 2016-09-23 21:47:43 tcptw 32805 5629 6390 0 tcpcb 29630 31428 inp=
cb 35259 36016 socket 29735 31596
> 2016-09-23 21:47:44 tcptw 32805 5754 6660 0 tcpcb 29593 31428 inp=
cb 35347 36016 socket 29696 31596
> 2016-09-23 21:47:45 tcptw 32805 5887 6660 0 tcpcb 29606 31428 inp=
cb 35493 36016 socket 29709 31596
> 2016-09-23 21:47:46 tcptw 32805 6011 6750 0 tcpcb 29613 31428 inp=
cb 35624 36016 socket 29716 31596
> 2016-09-23 21:47:47 tcptw 32805 6128 7020 0 tcpcb 29642 31428 inp=
cb 35770 36128 socket 29745 31596
> 2016-09-23 21:47:48 tcptw 32805 6250 7020 0 tcpcb 29742 31428 inp=
cb 35992 36416 socket 29845 31596
> 2016-09-23 21:47:49 tcptw 32805 6378 7155 0 tcpcb 29745 31428 inp=
cb 36123 36472 socket 29850 31596
> 2016-09-23 21:47:50 tcptw 32805 6486 7290 0 tcpcb 29756 31428 inp=
cb 36242 36648 socket 29861 31596
> 2016-09-23 21:47:51 tcptw 32805 6603 7515 0 tcpcb 29807 31428 inp=
cb 36410 36792 socket 29912 31596
> 2016-09-23 21:47:52 tcptw 32805 6736 7515 0 tcpcb 29830 31428 inp=
cb 36566 36912 socket 29935 31596
> 2016-09-23 21:47:53 tcptw 32805 6852 7785 0 tcpcb 29892 31428 inp=
cb 36744 37112 socket 29996 31596
> 2016-09-23 21:47:54 tcptw 32805 6991 7785 0 tcpcb 29876 31428 inp=
cb 36867 37288 socket 29981 31596
> 2016-09-23 21:47:55 tcptw 32805 7102 8010 0 tcpcb 29928 31428 inp=
cb 37030 37400 socket 30033 31596
> 2016-09-23 21:47:56 tcptw 32805 7227 8010 0 tcpcb 29960 31428 inp=
cb 37187 37544 socket 30065 31596
> 2016-09-23 21:47:57 tcptw 32805 7356 8280 0 tcpcb 30031 31428 inp=
cb 37387 37752 socket 30136 31596
> 2016-09-23 21:47:58 tcptw 32805 7505 8415 0 tcpcb 30164 31428 inp=
cb 37669 38040 socket 30270 31596
> 2016-09-23 21:47:59 tcptw 32805 7618 8415 0 tcpcb 30302 31428 inp=
cb 37920 38328 socket 30408 31596
> 2016-09-23 21:48:00 tcptw 32805 7740 8505 0 tcpcb 30478 31428 inp=
cb 38218 38560 socket 30584 31596
> 2016-09-23 21:48:01 tcptw 32805 7858 8640 0 tcpcb 30663 31428 inp=
cb 38521 38880 socket 30769 31596
So my hypothesis was wrong it is not a contention between
pfslowtimo()/tcp_tw_2msl_scan(reuse=3D0) and
tcp_input()/tcp_twstart()/tcp_tw_2msl_scan(reuse=3D1) as you still have
plenty of unused tcptw.
It is an issue between tcp_tw_2msl_scan(reuse=3D0) and something else.
--
Julien
--GOI7f8WkMNfWtsDtwWXMNSIBf9GVuUV42--
--4UdjdloAavhgGhlDNQTC5rJuu8bdjFenc
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
iQEcBAEBCgAGBQJX6MhXAAoJEKVlQ5Je6dhxduEH/j8Yk508aLefZnH9EpL1TdCw
eL1y5ctkXVJRhtAKl8hL7uuWoY0aNLCsJbEK85CcOmzuUm2QWLr1wD22D+A9EFSN
LzNt6Q/jvzT9OV1OZYmmrIvDUiaD7Y5Tkli4VlBYem590T65r3zgWx3Llazorwc2
+TMTBGbNByk82zKMZ0DRwykPa5pm3w6oMi5ZMlAUWWMNR0m5AAPfuObFdEawcVXe
3G4HLh76N4hcY1+3DkuXHU1syJFcf6Fpj7xvVltD/mLuLESUSvrPBuQPZna3zX/6
lz0XT4wv6T/kiHnkAoRleZmno70rvFxR6WInHvlUIaMsjIfyKj4O9wpT+YLBg+Y=
=WFRA
-----END PGP SIGNATURE-----
--4UdjdloAavhgGhlDNQTC5rJuu8bdjFenc--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?0a1522c0-bf23-8862-7785-94076e2e8d70>