On 5 Nov 2020, at 14:33, Jesper Dangaard Brouer wrote:
On Thu, 05 Nov 2020 13:22:10 +0100
Thomas Rosenstein via Bloat <bloat@lists.bufferbloat.net> wrote:
On 5 Nov 2020, at 12:21, Toke Høiland-Jørgensen wrote:
"Thomas Rosenstein" <thomas.rosenst...@creamfinance.com> writes:
If so, this sounds more like a driver issue, or maybe something to
do with scheduling. Does it only happen with ICMP? You could try
this
tool for a userspace UDP measurement:
It happens with all packets, therefore the transfer to backblaze
with
40 threads goes down to ~8MB/s instead of >60MB/s
Huh, right, definitely sounds like a kernel bug; or maybe the new
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
I'll try what that reports!
Also, what happens if you ping a host on the internet (*through*
the router instead of *to* it)?
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
Right, so even an unloaded interface suffers? But this is the same
NIC, right? So it could still be a hardware issue...
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 😃)
Well that at least narrows it down :)
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)
for example:
64 bytes from x.x.x.x: icmp_seq=10 ttl=64 time=0.169 ms
64 bytes from x.x.x.x: icmp_seq=11 ttl=64 time=5.53 ms
64 bytes from x.x.x.x: icmp_seq=12 ttl=64 time=9.44 ms
64 bytes from x.x.x.x: icmp_seq=13 ttl=64 time=0.167 ms
64 bytes from x.x.x.x: icmp_seq=14 ttl=64 time=3.88 ms
and then again:
64 bytes from x.x.x.x: icmp_seq=15 ttl=64 time=0.569 ms
64 bytes from x.x.x.x: icmp_seq=16 ttl=64 time=0.148 ms
64 bytes from x.x.x.x: icmp_seq=17 ttl=64 time=0.286 ms
64 bytes from x.x.x.x: icmp_seq=18 ttl=64 time=0.257 ms
64 bytes from x.x.x.x: icmp_seq=19 ttl=64 time=0.220 ms
64 bytes from x.x.x.x: icmp_seq=20 ttl=64 time=0.125 ms
64 bytes from x.x.x.x: icmp_seq=21 ttl=64 time=0.188 ms
64 bytes from x.x.x.x: icmp_seq=22 ttl=64 time=0.202 ms
64 bytes from x.x.x.x: icmp_seq=23 ttl=64 time=0.195 ms
64 bytes from x.x.x.x: icmp_seq=24 ttl=64 time=0.177 ms
64 bytes from x.x.x.x: icmp_seq=25 ttl=64 time=0.242 ms
64 bytes from x.x.x.x: icmp_seq=26 ttl=64 time=0.339 ms
64 bytes from x.x.x.x: icmp_seq=27 ttl=64 time=0.183 ms
64 bytes from x.x.x.x: icmp_seq=28 ttl=64 time=0.221 ms
64 bytes from x.x.x.x: icmp_seq=29 ttl=64 time=0.317 ms
64 bytes from x.x.x.x: icmp_seq=30 ttl=64 time=0.210 ms
64 bytes from x.x.x.x: icmp_seq=31 ttl=64 time=0.242 ms
64 bytes from x.x.x.x: icmp_seq=32 ttl=64 time=0.127 ms
64 bytes from x.x.x.x: icmp_seq=33 ttl=64 time=0.217 ms
64 bytes from x.x.x.x: icmp_seq=34 ttl=64 time=0.184 ms
For me it looks now that there was some fix between 5.4.60 and 5.9.4
... anyone can pinpoint it?
So, new day, same issue!
I upgraded now all routers to 5.9.4, and the issue is back ...
here, when I stop it, it goes immediatly down to 0.xx ms
64 bytes from x.x.x.x: icmp_seq=48 ttl=64 time=1.67 ms
64 bytes from x.x.x.x: icmp_seq=49 ttl=64 time=12.6 ms
64 bytes from x.x.x.x: icmp_seq=50 ttl=64 time=13.8 ms
64 bytes from x.x.x.x: icmp_seq=51 ttl=64 time=5.59 ms
64 bytes from x.x.x.x: icmp_seq=52 ttl=64 time=5.86 ms
64 bytes from x.x.x.x: icmp_seq=53 ttl=64 time=9.26 ms
64 bytes from x.x.x.x: icmp_seq=54 ttl=64 time=8.28 ms
64 bytes from x.x.x.x: icmp_seq=55 ttl=64 time=12.4 ms
64 bytes from x.x.x.x: icmp_seq=56 ttl=64 time=0.551 ms
64 bytes from x.x.x.x: icmp_seq=57 ttl=64 time=4.37 ms
64 bytes from x.x.x.x: icmp_seq=58 ttl=64 time=12.1 ms
64 bytes from x.x.x.x: icmp_seq=59 ttl=64 time=5.93 ms
64 bytes from x.x.x.x: icmp_seq=60 ttl=64 time=6.58 ms
64 bytes from x.x.x.x: icmp_seq=61 ttl=64 time=9.19 ms
64 bytes from x.x.x.x: icmp_seq=62 ttl=64 time=0.124 ms
64 bytes from x.x.x.x: icmp_seq=63 ttl=64 time=7.08 ms
64 bytes from x.x.x.x: icmp_seq=64 ttl=64 time=9.69 ms
64 bytes from x.x.x.x: icmp_seq=65 ttl=64 time=7.52 ms
64 bytes from x.x.x.x: icmp_seq=66 ttl=64 time=14.9 ms
64 bytes from x.x.x.x: icmp_seq=67 ttl=64 time=12.6 ms
64 bytes from x.x.x.x: icmp_seq=68 ttl=64 time=2.34 ms
64 bytes from x.x.x.x: icmp_seq=69 ttl=64 time=8.97 ms
64 bytes from x.x.x.x: icmp_seq=70 ttl=64 time=0.203 ms
64 bytes from x.x.x.x: icmp_seq=71 ttl=64 time=9.10 ms
64 bytes from x.x.x.x: icmp_seq=72 ttl=64 time=3.16 ms
64 bytes from x.x.x.x: icmp_seq=73 ttl=64 time=1.88 ms
64 bytes from x.x.x.x: icmp_seq=74 ttl=64 time=11.5 ms
64 bytes from x.x.x.x: icmp_seq=75 ttl=64 time=11.9 ms
64 bytes from x.x.x.x: icmp_seq=76 ttl=64 time=3.64 ms
64 bytes from x.x.x.x: icmp_seq=77 ttl=64 time=5.82 ms
64 bytes from x.x.x.x: icmp_seq=78 ttl=64 time=0.121 ms
64 bytes from x.x.x.x: icmp_seq=79 ttl=64 time=0.212 ms
64 bytes from x.x.x.x: icmp_seq=80 ttl=64 time=0.158 ms
64 bytes from x.x.x.x: icmp_seq=81 ttl=64 time=0.174 ms
64 bytes from x.x.x.x: icmp_seq=82 ttl=64 time=0.160 ms
64 bytes from x.x.x.x: icmp_seq=83 ttl=64 time=0.210 ms
64 bytes from x.x.x.x: icmp_seq=84 ttl=64 time=0.211 ms
64 bytes from x.x.x.x: icmp_seq=85 ttl=64 time=0.182 ms
64 bytes from x.x.x.x: icmp_seq=86 ttl=64 time=0.161 ms
64 bytes from x.x.x.x: icmp_seq=87 ttl=64 time=0.167 ms
64 bytes from x.x.x.x: icmp_seq=88 ttl=64 time=0.143 ms
64 bytes from x.x.x.x: icmp_seq=89 ttl=64 time=0.186 ms
64 bytes from x.x.x.x: icmp_seq=90 ttl=64 time=0.148 ms
64 bytes from x.x.x.x: icmp_seq=91 ttl=64 time=0.187 ms
64 bytes from x.x.x.x: icmp_seq=92 ttl=64 time=0.174 ms
64 bytes from x.x.x.x: icmp_seq=93 ttl=64 time=0.167 ms
I have also tried the bpftrace, there were no high IRQ reported during
the test, here's the latency output:
@latency_usecs[21]:
[0] 17 |
|
[1] 463 |@@@
|
[2, 4) 6814
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 5401 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 136 |@
|
[16, 32) 42 |
|
[32, 64) 2 |
|
[64, 128) 1 |
|
@latency_usecs[13]:
[0] 108 |
|
[1] 2089 |@@@
|
[2, 4) 32112
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 7642 |@@@@@@@@@@@@
|
[8, 16) 462 |
|
[16, 32) 159 |
|
[32, 64) 32 |
|
[64, 128) 34 |
|
[128, 256) 10 |
|
[256, 512) 1 |
|
@latency_usecs[22]:
[0] 244 |
|
[1] 3481 |@@@@@
|
[2, 4) 33795
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 13848 |@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 607 |
|
[16, 32) 214 |
|
[32, 64) 58 |
|
[64, 128) 42 |
|
[128, 256) 12 |
|
@latency_usecs[16]:
[0] 539 |
|
[1] 7601 |@@@@@@
|
[2, 4) 62482
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 22456 |@@@@@@@@@@@@@@@@@@
|
[8, 16) 1252 |@
|
[16, 32) 480 |
|
[32, 64) 211 |
|
[64, 128) 134 |
|
[128, 256) 17 |
|
@latency_usecs[2]:
[0] 352 |
|
[1] 18810 |@@@@@@@@@@@@@
|
[2, 4) 74915
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 11504 |@@@@@@@
|
[8, 16) 1077 |
|
[16, 32) 479 |
|
[32, 64) 329 |
|
[64, 128) 359 |
|
[128, 256) 79 |
|
[256, 512) 2 |
|
@latency_usecs[23]:
[0] 1214 |
|
[1] 9483 |@@@@@@@
|
[2, 4) 64949
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 34220 |@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 1940 |@
|
[16, 32) 775 |
|
[32, 64) 224 |
|
[64, 128) 220 |
|
[128, 256) 51 |
|
@latency_usecs[9]:
[0] 407 |
|
[1] 8040 |@@@@@
|
[2, 4) 80780
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 46867 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 3232 |@@
|
[16, 32) 614 |
|
[32, 64) 337 |
|
[64, 128) 231 |
|
[128, 256) 33 |
|
[256, 512) 0 |
|
[512, 1K) 0 |
|
[1K, 2K) 0 |
|
[2K, 4K) 0 |
|
[4K, 8K) 0 |
|
[8K, 16K) 1 |
|
@latency_usecs[4]:
[0] 513 |
|
[1] 10016 |@@@@@
|
[2, 4) 100149
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 32956 |@@@@@@@@@@@@@@@@@
|
[8, 16) 1436 |
|
[16, 32) 731 |
|
[32, 64) 285 |
|
[64, 128) 302 |
|
[128, 256) 64 |
|
[256, 512) 1 |
|
@latency_usecs[18]:
[0] 679 |
|
[1] 10962 |@@@@@@
|
[2, 4) 93837
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 36900 |@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 2050 |@
|
[16, 32) 1283 |
|
[32, 64) 390 |
|
[64, 128) 419 |
|
[128, 256) 91 |
|
[256, 512) 1 |
|
@latency_usecs[3]:
[0] 792 |
|
[1] 12109 |@@@@@@@
|
[2, 4) 83144
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 43316 |@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 4688 |@@
|
[16, 32) 2087 |@
|
[32, 64) 786 |
|
[64, 128) 791 |
|
[128, 256) 316 |
|
[256, 512) 43 |
|
[512, 1K) 5 |
|
[1K, 2K) 1 |
|
@latency_usecs[5]:
[0] 1990 |@
|
[1] 14018 |@@@@@@@@
|
[2, 4) 85797
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 56720 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 2993 |@
|
[16, 32) 1239 |
|
[32, 64) 536 |
|
[64, 128) 567 |
|
[128, 256) 106 |
|
[256, 512) 5 |
|
[512, 1K) 11 |
|
[1K, 2K) 4 |
|
@latency_usecs[15]:
[0] 719 |
|
[1] 12086 |@@@@@@
|
[2, 4) 95664
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 57490 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 3632 |@
|
[16, 32) 1417 |
|
[32, 64) 695 |
|
[64, 128) 696 |
|
[128, 256) 182 |
|
[256, 512) 2 |
|
[512, 1K) 7 |
|
[1K, 2K) 6 |
|
@latency_usecs[6]:
[0] 585 |
|
[1] 11880 |@@@@@@@
|
[2, 4) 87736
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 72264 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 2554 |@
|
[16, 32) 1403 |
|
[32, 64) 813 |
|
[64, 128) 624 |
|
[128, 256) 168 |
|
[256, 512) 23 |
|
[512, 1K) 3 |
|
@latency_usecs[11]:
[0] 768 |
|
[1] 19378 |@@@@@@@@@
|
[2, 4) 104935
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 81555 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 3645 |@
|
[16, 32) 1535 |
|
[32, 64) 837 |
|
[64, 128) 913 |
|
[128, 256) 207 |
|
[256, 512) 2 |
|
@latency_usecs[1]:
[0] 1511 |
|
[1] 23327 |@@@@@@@@@@
|
[2, 4) 107938
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[4, 8) 118722
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16) 5364 |@@
|
[16, 32) 2551 |@
|
[32, 64) 874 |
|
[64, 128) 809 |
|
[128, 256) 192 |
|
[256, 512) 3 |
|
[512, 1K) 0 |
|
[1K, 2K) 1 |
|
@latency_usecs[17]:
[0] 1268 |
|
[1] 16486 |@@@@@
|
[2, 4) 146148
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 92483 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 12484 |@@@@
|
[16, 32) 2330 |
|
[32, 64) 1040 |
|
[64, 128) 1054 |
|
[128, 256) 234 |
|
[256, 512) 6 |
|
[512, 1K) 2 |
|
[1K, 2K) 1 |
|
[2K, 4K) 0 |
|
[4K, 8K) 1 |
|
@latency_usecs[14]:
[0] 2685 |@
|
[1] 119278
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2, 4) 113518
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[4, 8) 33067 |@@@@@@@@@@@@@@
|
[8, 16) 9740 |@@@@
|
[16, 32) 3348 |@
|
[32, 64) 2245 |
|
[64, 128) 1515 |
|
[128, 256) 466 |
|
[256, 512) 8 |
|
@latency_usecs[10]:
[0] 2013 |
|
[1] 28900 |@@@@@@@@
|
[2, 4) 175104
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 71562 |@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 6094 |@
|
[16, 32) 2884 |
|
[32, 64) 1481 |
|
[64, 128) 1450 |
|
[128, 256) 311 |
|
[256, 512) 6 |
|
[512, 1K) 1 |
|
@latency_usecs[7]:
[0] 4790 |@
|
[1] 94276 |@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[2, 4) 186012
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 44289 |@@@@@@@@@@@@
|
[8, 16) 6822 |@
|
[16, 32) 2842 |
|
[32, 64) 2361 |
|
[64, 128) 3178 |
|
[128, 256) 910 |
|
[256, 512) 19 |
|
[512, 1K) 1 |
|
@latency_usecs[12]:
[0] 2360 |
|
[1] 33684 |@@@@@@
|
[2, 4) 280464
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 51498 |@@@@@@@@@
|
[8, 16) 10636 |@
|
[16, 32) 4374 |
|
[32, 64) 2077 |
|
[64, 128) 2414 |
|
[128, 256) 596 |
|
[256, 512) 8 |
|
[512, 1K) 0 |
|
[1K, 2K) 0 |
|
[2K, 4K) 0 |
|
[4K, 8K) 1 |
|
@latency_usecs[0]:
[0] 3559 |
|
[1] 41168 |@@@@@@@@
|
[2, 4) 251224
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 126271 |@@@@@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 15213 |@@@
|
[16, 32) 6788 |@
|
[32, 64) 4227 |
|
[64, 128) 4231 |
|
[128, 256) 1669 |
|
[256, 512) 395 |
|
[512, 1K) 54 |
|
[1K, 2K) 1 |
|
@latency_usecs[8]:
[0] 5280 |
|
[1] 43115 |@@@@@@@
|
[2, 4) 319098
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 98723 |@@@@@@@@@@@@@@@@
|
[8, 16) 16048 |@@
|
[16, 32) 9455 |@
|
[32, 64) 3755 |
|
[64, 128) 4650 |
|
[128, 256) 1284 |
|
[256, 512) 61 |
|
[512, 1K) 2 |
|
[1K, 2K) 1 |
|
[2K, 4K) 1 |
|
[4K, 8K) 2 |
|
@latency_usecs[19]:
[0] 49889 |@@@@@@@@@@@@
|
[1] 199560
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2, 4) 185771
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[4, 8) 59143 |@@@@@@@@@@@@@@@
|
[8, 16) 24402 |@@@@@@
|
[16, 32) 13158 |@@@
|
[32, 64) 12889 |@@@
|
[64, 128) 12269 |@@@
|
[128, 256) 6322 |@
|
[256, 512) 299 |
|
[512, 1K) 8 |
|
[1K, 2K) 1 |
|
@latency_usecs[20]:
[0] 6314 |
|
[1] 51792 |@@@@@@@
|
[2, 4) 353847
|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8) 154730 |@@@@@@@@@@@@@@@@@@@@@@
|
[8, 16) 23434 |@@@
|
[16, 32) 8441 |@
|
[32, 64) 3300 |
|
[64, 128) 3058 |
|
[128, 256) 1017 |
|
[256, 512) 124 |
|
[512, 1K) 12 |
|
[1K, 2K) 1 |
|
@Jesper: how should that be interpreted?
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/softirq_net_latency.bt
Example output see[3]:
[3] https://bugzilla.redhat.com/show_bug.cgi?id=1795049#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/bpftrace/INSTALL.org
--
Best regards,
Jesper Dangaard Brouer
MSc.CS, Principal Kernel Engineer at Red Hat
LinkedIn: http://www.linkedin.com/in/brouer
_______________________________________________
Bloat mailing list
Bloat@lists.bufferbloat.net
https://lists.bufferbloat.net/listinfo/bloat
