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 833443B29D for ; Thu, 12 Nov 2020 05:05:27 -0500 (EST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1605175527; 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=IjEquf/a4QfYbyr/O3eAjhWf/lgCfTUR5U2uA5tUDdE=; b=Qc8qtjBQ7uncZiFPali5lgoWyo8X85FtcD360kLhJJ2R4wkLab0MDESRjSkvaJDSo8wgOP cZYHTh+Br3YK/0+HYSQFkK+lbaTW4//066DUlCydrO9RGMDiqM2z6Y3UpBKsrbxH/Qrkz7 fgF4spYFwjVaKubu0ysN9bSW77eytKo= 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-590-hHo0d2_PNPKL41pwRGiHtw-1; Thu, 12 Nov 2020 05:05:15 -0500 X-MC-Unique: hHo0d2_PNPKL41pwRGiHtw-1 Received: from smtp.corp.redhat.com (int-mx05.intmail.prod.int.phx2.redhat.com [10.5.11.15]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 7E617801F9A; Thu, 12 Nov 2020 10:05:14 +0000 (UTC) Received: from carbon (unknown [10.36.110.8]) by smtp.corp.redhat.com (Postfix) with ESMTP id 3A70C75136; Thu, 12 Nov 2020 10:05:09 +0000 (UTC) Date: Thu, 12 Nov 2020 11:05:08 +0100 From: Jesper Dangaard Brouer To: "Thomas Rosenstein" Cc: "Bufferbloat" , brouer@redhat.com, Saeed Mahameed , Tariq Toukan Message-ID: <20201112110508.59f402e7@carbon> In-Reply-To: <27110D8E-77DF-4D10-A5EA-6430DBD55BC7@creamfinance.com> References: <871rh8vf1p.fsf@toke.dk> <81ED2A33-D366-42FC-9344-985FEE8F11BA@creamfinance.com> <87sg9ot5f1.fsf@toke.dk> <20201105143317.78276bbc@carbon> <11812D44-BD46-4CA4-BA39-6080BD88F163@creamfinance.com> <20201106121840.7959ae4b@carbon> <87blgaso84.fsf@toke.dk> <20201106135358.09f6c281@carbon> <20201106151324.5f506574@carbon> <1E70B6D2-1212-43FA-989A-03B657EEE2F2@creamfinance.com> <20201106211940.4c30ccc9@carbon> <6963be0e-3eb5-5875-b53c-66033f50dc2d@gmail.com> <12D28386-7C00-4A31-91E4-37083C1674F9@creamfinance.com> <20201109092428.293104ea@carbon> <7723D882-4DAB-4A70-9D00-DF1976872AC2@creamfinance.com> <20201109124030.71216677@carbon> <27110D8E-77DF-4D10-A5EA-6430DBD55BC7@creamfinance.com> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.15 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=US-ASCII Content-Transfer-Encoding: 7bit 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, 12 Nov 2020 10:05:27 -0000 On Mon, 09 Nov 2020 15:33:46 +0100 "Thomas Rosenstein" wrote: > On 9 Nov 2020, at 12:40, Jesper Dangaard Brouer wrote: > > > On Mon, 09 Nov 2020 11:09:33 +0100 > > "Thomas Rosenstein" wrote: > > > >> On 9 Nov 2020, at 9:24, Jesper Dangaard Brouer wrote: > >> > >>> On Sat, 07 Nov 2020 14:00:04 +0100 > >>> Thomas Rosenstein via Bloat wrote: > >>> > >>>> Here's an extract from the ethtool https://pastebin.com/cabpWGFz > >>>> just > >>>> in > >>>> case there's something hidden. > >>> > >>> Yes, there is something hiding in the data from ethtool_stats.pl[1]: > >>> (10G Mellanox Connect-X cards via 10G SPF+ DAC) > >>> > >>> stat: 1 ( 1) <= outbound_pci_stalled_wr_events /sec > >>> stat: 339731557 (339,731,557) <= rx_buffer_passed_thres_phy /sec > >>> > >>> I've not seen this counter 'rx_buffer_passed_thres_phy' before, > >>> looking > >>> in the kernel driver code it is related to "rx_buffer_almost_full". > >>> The numbers per second is excessive (but it be related to a driver > >>> bug > >>> as it ends up reading "high" -> rx_buffer_almost_full_high in the > >>> extended counters). > > I have now tested with a new kernel 5.9.4 build made from 3.10 with make > oldconfig and I noticed an interesting effect. > > The first ca. 2 minutes the router behaves completely normal as with > 3.10, after that the ping times go crazy. > > I have recorded this with ethtool, and also the ping times. > > Ethtool: (13 MB) > https://drive.google.com/file/d/1Ojp64UUw0zKwrgF_CisZb3BCdidAJYZo/view?usp=sharing > > The transfer first was doing around 50 - 70 MB/s then once the ping > times go worse it dropped to ~12 MB/s. > ca. Line 74324 the transfer speed drops to 12 MB/s Lets add them here so we can see and talk about them: 74324 Ethtool(eth4 ) stat: 144584002 ( 144,584,002) <= rx_buffer_passed_thres_phy /sec 74325 Ethtool(eth4 ) stat: 17243186 ( 17,243,186) <= rx_bytes /sec 74326 Ethtool(eth4 ) stat: 19032079 ( 19,032,079) <= rx_bytes_phy /sec Significant difference between RX-bytes Phy-level and OS-level. 17243186*8/10^6 = 138 Mbit/s 74327 Ethtool(eth4 ) stat: 321 ( 321) <= rx_cache_busy /sec 74328 Ethtool(eth4 ) stat: 321 ( 321) <= rx_cache_full /sec 74329 Ethtool(eth4 ) stat: 7323 ( 7,323) <= rx_cache_reuse /sec 74330 Ethtool(eth4 ) stat: 15188 ( 15,188) <= rx_csum_complete /sec 74331 Ethtool(eth4 ) stat: 1 ( 1) <= rx_csum_none /sec 74332 Ethtool(eth4 ) stat: 96 ( 96) <= rx_csum_unnecessary /sec 74333 Ethtool(eth4 ) stat: 1242 ( 1,242) <= rx_discards_phy /sec Packets are getting rx_discards 74334 Ethtool(eth4 ) stat: 15285 ( 15,285) <= rx_packets /sec 74335 Ethtool(eth4 ) stat: 16655 ( 16,655) <= rx_packets_phy /sec (16655-15285 = 1370) Again difference between RX-packets Phy-level and OS-level 74336 Ethtool(eth4 ) stat: 19132497 ( 19,132,497) <= rx_prio0_bytes /sec 74337 Ethtool(eth4 ) stat: 1264 ( 1,264) <= rx_prio0_discards /sec 74338 Ethtool(eth4 ) stat: 15474 ( 15,474) <= rx_prio0_packets /sec > Seems you are right about the rx_buffer_passed_thres_phy if you check > just those lines they appear more often once the speed dropped. > Not sure if that's the cause or an effect of the underlying problem! Thanks for the link to Mellanox doc: https://community.mellanox.com/s/article/understanding-mlx5-ethtool-counters The counter: 'rx_buffer_passed_thres_phy' Description: 'The number of events where the port receive buffer was over 85% full. Supported from kernel 4.14' The counter: 'tx_pause_ctrl_phy' Description: 'The number of link layer pause packets transmitted on a physical port. If this counter is increasing, it implies that the NIC is congested and cannot absorb the traffic coming from the network.' So, the NIC is clearly telling us that something is wrong. You are not near link speed (12MB/s => 96Mbit/s). And still port receive buffer is over 85% full most of the time. There are indications that, the NIC is congested and cannot absorb the traffic coming from the network. Long-shot theory(1): Could this be caused by CPUs going into too deep sleep states? And NIC not sending wake-up signal early enough, e.g. because it holds on to packets for generating a bulk at IRQ raise. Long-shot theory(2): The NIC driver IRQ interrupt coalesce adaptive-IRQ (adj via ethtool -C) is wrong. The reason it is wrong is because of TSO frames, due packet-to-byte ratio isn't taken into account. You can test theory(2) in two ways, via disabling TSO and via adjusting ethtool --show-coalesce|--coalesce (-c|-C). The --coalesce change can change part of theory(1), the NIC wake-up/IRQ interval. For CPU sleep modes see software package 'tuned'. > Pings: > https://drive.google.com/file/d/16phOxM5IFU6RAl4Ua4pRqMNuLYBc4RK7/view?usp=sharing > > Pause frames were activated again after the restart. > > (Here a link for rerefence for the ethtool variables: > https://community.mellanox.com/s/article/understanding-mlx5-ethtool-counters) To easier digest, here are some of the interesting counters. 74171 Ethtool(eth4 ) stat: 24 ( 24) <= outbound_pci_stalled_wr /sec 74172 Ethtool(eth4 ) stat: 1 ( 1) <= outbound_pci_stalled_wr_events /sec [...] 74628 Ethtool(eth5 ) stat: 40 ( 40) <= outbound_pci_stalled_wr /sec 74629 Ethtool(eth5 ) stat: 1 ( 1) <= outbound_pci_stalled_wr_events /sec 74539 Ethtool(eth4 ) stat: 432 ( 432) <= tx_global_pause /sec 74540 Ethtool(eth4 ) stat: 551264 ( 551,264) <= tx_global_pause_duration /sec 74541 Ethtool(eth4 ) stat: 434 ( 434) <= tx_mac_control_phy /sec 74542 Ethtool(eth4 ) stat: 31 ( 31) <= tx_nop /sec 74543 Ethtool(eth4 ) stat: 24888 ( 24,888) <= tx_packets /sec 74544 Ethtool(eth4 ) stat: 25187 ( 25,187) <= tx_packets_phy /sec 74545 Ethtool(eth4 ) stat: 434 ( 434) <= tx_pause_ctrl_phy /sec 74546 Ethtool(eth4 ) stat: 15190865 ( 15,190,865) <= tx_prio0_bytes /sec 74547 Ethtool(eth4 ) stat: 24907 ( 24,907) <= tx_prio0_packets /sec 74548 Ethtool(eth4 ) stat: 647795 ( 647,795) <= tx_tso_bytes /sec 74549 Ethtool(eth4 ) stat: 196 ( 196) <= tx_tso_packets /sec 74550 Ethtool(eth4 ) stat: 15005949 ( 15,005,949) <= tx_vport_unicast_bytes /sec 74551 Ethtool(eth4 ) stat: 24780 ( 24,780) <= tx_vport_unicast_packets /sec 74552 Ethtool(eth4 ) stat: 57 ( 57) <= tx_xmit_more /sec [...] 75030 Ethtool(eth5 ) stat: 39 ( 39) <= tx_global_pause /sec 75031 Ethtool(eth5 ) stat: 242374 ( 242,374) <= tx_global_pause_duration /sec 75032 Ethtool(eth5 ) stat: 39 ( 39) <= tx_mac_control_phy /sec 75033 Ethtool(eth5 ) stat: 166 ( 166) <= tx_nop /sec 75034 Ethtool(eth5 ) stat: 14837 ( 14,837) <= tx_packets /sec 75035 Ethtool(eth5 ) stat: 14816 ( 14,816) <= tx_packets_phy /sec 75036 Ethtool(eth5 ) stat: 39 ( 39) <= tx_pause_ctrl_phy /sec 75037 Ethtool(eth5 ) stat: 16748584 ( 16,748,584) <= tx_prio0_bytes /sec 75038 Ethtool(eth5 ) stat: 14708 ( 14,708) <= tx_prio0_packets /sec 75039 Ethtool(eth5 ) stat: 2477442 ( 2,477,442) <= tx_tso_bytes /sec 75040 Ethtool(eth5 ) stat: 733 ( 733) <= tx_tso_packets /sec 75041 Ethtool(eth5 ) stat: 16765330 ( 16,765,330) <= tx_vport_unicast_bytes /sec 75042 Ethtool(eth5 ) stat: 14780 ( 14,780) <= tx_vport_unicast_packets /sec 75043 Ethtool(eth5 ) stat: 2 ( 2) <= tx_xmit_more /sec -- Best regards, Jesper Dangaard Brouer MSc.CS, Principal Kernel Engineer at Red Hat LinkedIn: http://www.linkedin.com/in/brouer