Hi, this is your Linux kernel regression tracker. Top-posting for once,
to make this easily accessible to everyone.

Patrick, did you see the comment from Jozsef? Are you having trouble
providing additional data or what's the status here from your side? Or
is that something we can forget?

Ciao, Thorsten

#regzbot poke

On 11.04.22 13:47, Jozsef Kadlecsik wrote:

Hi,

On Mon, 11 Apr 2022, Thorsten Leemhuis wrote:

quoted

On 16.03.22 10:17, Thorsten Leemhuis wrote:

quoted

[TLDR: I'm adding the regression report below to regzbot, the Linux
kernel regression tracking bot; all text you find below is compiled from
a few templates paragraphs you might have encountered already already
from similar mails.]

On 16.03.22 00:15, McLean, Patrick wrote:

quoted

quoted

When we upgraded from the 5.10 (5.10.61) series to the 5.15 (5.15.16) 
series, we encountered an intermittent performance regression that 
appears to be related to iptables / ipset. This regression was 
noticed on Kubernetes hosts that run kube-router and experience a 
high amount of churn to both iptables and ipsets. Specifically, when 
we run the nftables (iptables-1.8.7 / nftables-1.0.0) iptables 
wrapper xtables-nft-multi on the 5.15 series kernel, we end up 
getting extremely laggy response times when iptables attempts to 
lookup information on the ipsets that are used in the iptables 
definition. This issue isn’t reproducible on all hosts. However, our 
experience has been that across a fleet of ~50 hosts we experienced 
this issue on ~40% of the hosts. When the problem evidences, the time 
that it takes to run unrestricted iptables list commands like 
iptables -L or iptables-save gradually increases over the course of 
about 1 - 2 hours. Growing from less than a second to run, to takin

 g sometimes over 2 minutes to run. After that 2 hour mark it seems to 
 plateau and not grow any longer. Flushing tables or ipsets doesn’t seem 
 to have any affect on the issue. However, rebooting the host does reset 
 the issue. Occasionally, a machine that was evidencing the problem may 
 no longer evidence it after being rebooted.

quoted

quoted

We did try to debug this to find a root cause, but ultimately ran 
short on time. We were not able to perform a set of bisects to 
hopefully narrow down the issue as the problem isn’t consistently 
reproducible. We were able to get some straces where it appears that 
most of the time is spent on getsockopt() operations. It appears that 
during iptables operations, it attempts to do some work to resolve 
the ipsets that are linked to the iptables definitions (perhaps 
getting the names of the ipsets themselves?). Slowly that getsockopt 
request takes more and more time on affected hosts. Here is an 
example strace of the operation in question:

Yes, iptables list/save have to get the names of the referenced sets and 
that is performed via getsockopt() calls.

I went through all of the ipset related patches between 5.10.6 (copy&paste 
error but just the range is larger) and 5.15.16 and as far as I see none 
of them can be responsible for the regression. More data is required to 
locate the source of the slowdown.

Best regards,
Jozsef

quoted

quoted

quoted

0.000074 newfstatat(AT_FDCWD, "/etc/nsswitch.conf", {st_mode=S_IFREG|0644, st_size=539, ...}, 0) = 0 <0.000017>
0.000064 openat(AT_FDCWD, "/var/db/protocols.db", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) <0.000017>
0.000057 openat(AT_FDCWD, "/etc/protocols", O_RDONLY|O_CLOEXEC) = 4 <0.000013>
0.000034 newfstatat(4, "", {st_mode=S_IFREG|0644, st_size=6108, ...}, AT_EMPTY_PATH) = 0 <0.000009>
0.000032 lseek(4, 0, SEEK_SET)     = 0 <0.000008>
0.000025 read(4, "# /etc/protocols\n#\n# Internet (I"..., 4096) = 4096 <0.000010>
0.000036 close(4)                  = 0 <0.000008>
0.000028 write(1, "ANGME7BF25 - [0:0]\n:KUBE-POD-FW-"..., 4096) = 4096 <0.000028>
0.000049 socket(AF_INET, SOCK_RAW, IPPROTO_RAW) = 4 <0.000015>
0.000032 fcntl(4, F_SETFD, FD_CLOEXEC) = 0 <0.000008>
0.000024 getsockopt(4, SOL_IP, 0x53 /* IP_??? */, "\0\1\0\0\7\0\0\0", [8]) = 0 <0.000024>
0.000046 getsockopt(4, SOL_IP, 0x53 /* IP_??? */, "\7\0\0\0\7\0\0\0KUBE-DST-VBH27M7NWLDOZIE"..., [40]) = 0 <0.109384>
0.109456 close(4)                  = 0 <0.000022>

On a host that is not evidencing the performance regression we 
normally see that operation take ~ 0.00001 as opposed to 
0.109384.Additionally, hosts that were evidencing the problem we also 
saw high lock times with `klockstat` (unfortunately at the time we 
did not know about or run echo "0" > /proc/sys/kernel/kptr_restrict 
to get the callers of the below commands).

klockstat -i 5 -n 10 (on a host experiencing the problem)
Caller   Avg Hold  Count   Max hold Total hold
b'[unknown]'  118490772     83  179899470 9834734132
b'[unknown]'  118416941     83  179850047 9828606138
# or somewhere later while iptables -vnL was running:
Caller   Avg Hold  Count   Max hold Total hold
b'[unknown]'  496466236     46 17919955720 22837446860
b'[unknown]'  496391064     46 17919893843 22833988950

klockstat -i 5 -n 10 (on a host not experiencing the problem)
Caller   Avg Hold  Count   Max hold Total hold
b'[unknown]'     120316   1510   85537797  181677885
b'[unknown]'    7119070     24   85527251  170857690

Hi, this is your Linux kernel regression tracker.

Thanks for the report.

CCing the regression mailing list, as it should be in the loop for all
regressions, as explained here:
https://www.kernel.org/doc/html/latest/admin-guide/reporting-issues.html

To be sure below issue doesn't fall through the cracks unnoticed, I'm
adding it to regzbot, my Linux kernel regression tracking bot:

#regzbot ^introduced v5.10..v5.15
#regzbot title net: netfilter: Intermittent performance regression
related to ipset
#regzbot ignore-activity

If it turns out this isn't a regression, free free to remove it from the
tracking by sending a reply to this thread containing a paragraph like
"#regzbot invalid: reason why this is invalid" (without the quotes).

Reminder for developers: when fixing the issue, please add a 'Link:'
tags pointing to the report (the mail quoted above) using
lore.kernel.org/r/, as explained in
'Documentation/process/submitting-patches.rst' and
'Documentation/process/5.Posting.rst'. Regzbot needs them to
automatically connect reports with fixes, but they are useful in
general, too.

I'm sending this to everyone that got the initial report, to make
everyone aware of the tracking. I also hope that messages like this
motivate people to directly get at least the regression mailing list and
ideally even regzbot involved when dealing with regressions, as messages
like this wouldn't be needed then. And don't worry, if I need to send
other mails regarding this regression only relevant for regzbot I'll
send them to the regressions lists only (with a tag in the subject so
people can filter them away). With a bit of luck no such messages will
be needed anyway.

Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)

P.S.: As the Linux kernel's regression tracker I'm getting a lot of
reports on my table. I can only look briefly into most of them and lack
knowledge about most of the areas they concern. I thus unfortunately
will sometimes get things wrong or miss something important. I hope
that's not the case here; if you think it is, don't hesitate to tell me
in a public reply, it's in everyone's interest to set the public record
straight.

-
E-mail  : kadlec@blackhole.kfki.hu, kadlecsik.jozsef@wigner.hu
PGP key : https://wigner.hu/~kadlec/pgp_public_key.txt
Address : Wigner Research Centre for Physics
          H-1525 Budapest 114, POB. 49, Hungary