From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [63.128.21.124]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)) (No client certificate requested) by lists.bufferbloat.net (Postfix) with ESMTPS id C872F3CB35 for ; Thu, 5 Nov 2020 08:33:29 -0500 (EST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1604583209; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=YwKrK7hcIdd+pxuwChu61ol4p0wlF7wBs2To3OX277c=; b=byh3fZDkKJ/c/qEznO46hQ3EEp8tEUHBbvi5ouwVGtx/BWsL1a5P5xYTlXr5os47DScei8 6sRl6K0Y0EhlUEimey/C6vOsLQbjM4i5c9ZkdqWmBwR2tx0RjXbDr4KlnidHZ2eCa+X0KT yv+dUXEfOCxfpMsCtQ7hu+QbV9x1PK4= Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-26-o-XEAqPUMCCbatt9WXvo4g-1; Thu, 05 Nov 2020 08:33:25 -0500 X-MC-Unique: o-XEAqPUMCCbatt9WXvo4g-1 Received: from smtp.corp.redhat.com (int-mx04.intmail.prod.int.phx2.redhat.com [10.5.11.14]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 225981882FAA; Thu, 5 Nov 2020 13:33:24 +0000 (UTC) Received: from carbon (unknown [10.36.110.25]) by smtp.corp.redhat.com (Postfix) with ESMTP id 934585DE84; Thu, 5 Nov 2020 13:33:18 +0000 (UTC) Date: Thu, 5 Nov 2020 14:33:17 +0100 From: Jesper Dangaard Brouer To: Bloat Message-ID: <20201105143317.78276bbc@carbon> In-Reply-To: References: <87imalumps.fsf@toke.dk> <871rh8vf1p.fsf@toke.dk> <81ED2A33-D366-42FC-9344-985FEE8F11BA@creamfinance.com> <87sg9ot5f1.fsf@toke.dk> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.14 Authentication-Results: relay.mimecast.com; auth=pass smtp.auth=CUSA124A263 smtp.mailfrom=brouer@redhat.com X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Subject: Re: [Bloat] Router congestion, slow ping/ack times with kernel 5.4.60 X-BeenThere: bloat@lists.bufferbloat.net X-Mailman-Version: 2.1.20 Precedence: list List-Id: General list for discussing Bufferbloat List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 05 Nov 2020 13:33:29 -0000 On Thu, 05 Nov 2020 13:22:10 +0100 Thomas Rosenstein via Bloat wrote: > On 5 Nov 2020, at 12:21, Toke H=C3=B8iland-J=C3=B8rgensen wrote: >=20 > > "Thomas Rosenstein" writes: > > =20 > >>> If so, this sounds more like a driver issue, or maybe something to=20 > >>> do with scheduling. Does it only happen with ICMP? You could try this > >>> tool for a userspace UDP measurement: =20 > >> > >> It happens with all packets, therefore the transfer to backblaze with= =20 > >> 40 threads goes down to ~8MB/s instead of >60MB/s =20 > > > > Huh, right, definitely sounds like a kernel bug; or maybe the new=20 > > kernel is getting the hardware into a state where it bugs out when > > there are lots of flows or something. > > > > You could try looking at the ethtool stats (ethtool -S) while > > running the test and see if any error counters go up. Here's a > > handy script to monitor changes in the counters: > > > > https://github.com/netoptimizer/network-testing/blob/master/bin/ethtool= _stats.pl > > =20 > >> I'll try what that reports! > >> =20 > >>> Also, what happens if you ping a host on the internet (*through* > >>> the router instead of *to* it)? =20 > >> > >> Same issue, but twice pronounced, as it seems all interfaces are > >> affected. > >> So, ping on one interface and the second has the issue. > >> Also all traffic across the host has the issue, but on both sides, > >> so ping to the internet increased by 2x =20 > > > > Right, so even an unloaded interface suffers? But this is the same=20 > > NIC, right? So it could still be a hardware issue... > > =20 > >> Yep default that CentOS ships, I just tested 4.12.5 there the > >> issue also does not happen. So I guess I can bisect it > >> then...(really don't want to =F0=9F=98=83) =20 > > > > Well that at least narrows it down :) =20 >=20 > I just tested 5.9.4 seems to also fix it partly, I have long > stretches where it looks good, and then some increases again. (3.10 > Stock has them too, but not so high, rather 1-3 ms) >=20 > for example: >=20 > 64 bytes from x.x.x.x: icmp_seq=3D10 ttl=3D64 time=3D0.169 ms > 64 bytes from x.x.x.x: icmp_seq=3D11 ttl=3D64 time=3D5.53 ms > 64 bytes from x.x.x.x: icmp_seq=3D12 ttl=3D64 time=3D9.44 ms > 64 bytes from x.x.x.x: icmp_seq=3D13 ttl=3D64 time=3D0.167 ms > 64 bytes from x.x.x.x: icmp_seq=3D14 ttl=3D64 time=3D3.88 ms >=20 > and then again: >=20 > 64 bytes from x.x.x.x: icmp_seq=3D15 ttl=3D64 time=3D0.569 ms > 64 bytes from x.x.x.x: icmp_seq=3D16 ttl=3D64 time=3D0.148 ms > 64 bytes from x.x.x.x: icmp_seq=3D17 ttl=3D64 time=3D0.286 ms > 64 bytes from x.x.x.x: icmp_seq=3D18 ttl=3D64 time=3D0.257 ms > 64 bytes from x.x.x.x: icmp_seq=3D19 ttl=3D64 time=3D0.220 ms > 64 bytes from x.x.x.x: icmp_seq=3D20 ttl=3D64 time=3D0.125 ms > 64 bytes from x.x.x.x: icmp_seq=3D21 ttl=3D64 time=3D0.188 ms > 64 bytes from x.x.x.x: icmp_seq=3D22 ttl=3D64 time=3D0.202 ms > 64 bytes from x.x.x.x: icmp_seq=3D23 ttl=3D64 time=3D0.195 ms > 64 bytes from x.x.x.x: icmp_seq=3D24 ttl=3D64 time=3D0.177 ms > 64 bytes from x.x.x.x: icmp_seq=3D25 ttl=3D64 time=3D0.242 ms > 64 bytes from x.x.x.x: icmp_seq=3D26 ttl=3D64 time=3D0.339 ms > 64 bytes from x.x.x.x: icmp_seq=3D27 ttl=3D64 time=3D0.183 ms > 64 bytes from x.x.x.x: icmp_seq=3D28 ttl=3D64 time=3D0.221 ms > 64 bytes from x.x.x.x: icmp_seq=3D29 ttl=3D64 time=3D0.317 ms > 64 bytes from x.x.x.x: icmp_seq=3D30 ttl=3D64 time=3D0.210 ms > 64 bytes from x.x.x.x: icmp_seq=3D31 ttl=3D64 time=3D0.242 ms > 64 bytes from x.x.x.x: icmp_seq=3D32 ttl=3D64 time=3D0.127 ms > 64 bytes from x.x.x.x: icmp_seq=3D33 ttl=3D64 time=3D0.217 ms > 64 bytes from x.x.x.x: icmp_seq=3D34 ttl=3D64 time=3D0.184 ms >=20 >=20 > For me it looks now that there was some fix between 5.4.60 and 5.9.4 > ... anyone can pinpoint it? I have some bpftrace tools to measure these kind of latency spikes here: [1] https://github.com/xdp-project/xdp-project/blob/master/areas/latency/ The tool you want is: softirq_net_latency.bt [2] https://github.com/xdp-project/xdp-project/blob/master/areas/latency/s= oftirq_net_latency.bt Example output see[3]: [3] https://bugzilla.redhat.com/show_bug.cgi?id=3D1795049#c8 Based on the kernel versions, I don't expect this to be same latency issue as described in the bugzilla[3] case (as IIRC it was fixed in 4.19). It can still be similar issue, where some userspace process is reading information from the kernel (/sys/fs/cgroup/memory/memory.stat in BZ case) that blocks softirq from running, and result in these latency spikes. Install guide to bpftrace[4]: [4] https://github.com/xdp-project/xdp-project/blob/master/areas/mem/bpftr= ace/INSTALL.org --=20 Best regards, Jesper Dangaard Brouer MSc.CS, Principal Kernel Engineer at Red Hat LinkedIn: http://www.linkedin.com/in/brouer