Weird/High CPU usage caused by LOG target

Weird/High CPU usage caused by LOG target

[Tom Yan]

Hi all,

So I was trying to log all traffics in the FORWARD chain with the LOG
target in iptables (while I say all, it's just some VPN server/client
that is used by only me, and the tests were just opening some
website).

I notice that the logging causes high CPU usage (so it goes up only
when there are traffics). In (h)top, the usage shows up as openvpn's
if the forwarding involves their tuns. Say I am forwarding from one
tun to another, each of the openvpn instance will max out one core on
my raspberry pi 3 b+. (And that actually slows the whole system down,
like ssh/bash responsiveness, and stalls the traffic flow.) If I do
not log, or log with the NFLOG target instead, their CPU usage will be
less than 1%.

Interestingly, the problem seems to be way less obvious if I am using
it on higher end devices (like my Haswell PC, or even a raspberry pi
4). There are still "spikes" as well, but it won't make me "notice"
the problem, at least not when I am just doing some trivial web
browsing.

Let me know how I can further help debugging, if any of you are
interested in fixing this.

Regards,
Tom

Re: Weird/High CPU usage caused by LOG target

[Thomas Korimort]

Hi tom yan!

I also noted such a type of CPU usage on my Raspberry Pi 4 4 GB. I have
also found several privacy concerns on my new powerful Raspberry pi 4
4GB. Maybe there are people highjacking CPU power from Raspberry Pis to
do cryptomining or whatever else in terms of distributed
(super)-computing. I am suspecting that the high usability of the
Raspberry Pi 4 4 GB and generally the RPi series imposes a threat to
companies and people who offer high-priced consumer electronics. That is
why we have to experience such kind of issues on our Raspberry Pi
platforms, because a lot of competitors try to push out the RPi
platforms of their business. For example: cost of a modern Smart Tv:
2000 bucks, cost of a similar sized monitor with 4K/2K capability +
self-maintained RPi 4 4GB running Raspbian Buster as a full-fledged
media center: 350 bucks.

During operation of my RPi 4 4 GB i also noticed high CPU peaks. That
was due to not supported x.264 hardware-encoding (now it is supported).
Furthermore, sometimes the RPi4 4GB gets slow. After the update of the
x.264 codec the situation is now relieved. Though sometimes while using
Kodi also strange phenomena occur in terms of slowed down interface
interaction and reaction. That might be related to high CPU load because
of ASCII logging. People underestimate the CPU usage logging features
are making.

Many greetings, Thomas Korimort.

On 26.12.19 04:05, Tom Yan wrote:
> Hi all,
>
> So I was trying to log all traffics in the FORWARD chain with the LOG
> target in iptables (while I say all, it's just some VPN server/client
> that is used by only me, and the tests were just opening some
> website).
>
> I notice that the logging causes high CPU usage (so it goes up only
> when there are traffics). In (h)top, the usage shows up as openvpn's
> if the forwarding involves their tuns. Say I am forwarding from one
> tun to another, each of the openvpn instance will max out one core on
> my raspberry pi 3 b+. (And that actually slows the whole system down,
> like ssh/bash responsiveness, and stalls the traffic flow.) If I do
> not log, or log with the NFLOG target instead, their CPU usage will be
> less than 1%.
>
> Interestingly, the problem seems to be way less obvious if I am using
> it on higher end devices (like my Haswell PC, or even a raspberry pi
> 4). There are still "spikes" as well, but it won't make me "notice"
> the problem, at least not when I am just doing some trivial web
> browsing.
>
> Let me know how I can further help debugging, if any of you are
> interested in fixing this.
>
> Regards,
> Tom

Re: Weird/High CPU usage caused by LOG target

[Duncan Roe]

On Thu, Dec 26, 2019 at 11:05:33AM +0800, Tom Yan wrote:
> Hi all,
>
> So I was trying to log all traffics in the FORWARD chain with the LOG
> target in iptables (while I say all, it's just some VPN server/client
> that is used by only me, and the tests were just opening some
> website).
>
> I notice that the logging causes high CPU usage (so it goes up only
> when there are traffics). In (h)top, the usage shows up as openvpn's
> if the forwarding involves their tuns. Say I am forwarding from one
> tun to another, each of the openvpn instance will max out one core on
> my raspberry pi 3 b+. (And that actually slows the whole system down,
> like ssh/bash responsiveness, and stalls the traffic flow.) If I do
> not log, or log with the NFLOG target instead, their CPU usage will be
> less than 1%.
>
> Interestingly, the problem seems to be way less obvious if I am using
> it on higher end devices (like my Haswell PC, or even a raspberry pi
> 4). There are still "spikes" as well, but it won't make me "notice"
> the problem, at least not when I am just doing some trivial web
> browsing.
>
> Let me know how I can further help debugging, if any of you are
> interested in fixing this.
>
> Regards,
> Tom
>
Hi Tom,

Just in case you missed it, be sure that your logger is configured not to sync
the file system after every logging. That is the default action btw.

I have used large-volume logging in the past and never encountered a CPU problem
(but had to run logrotate every minute to avoid filling the disk).

Cheers ... Duncan.

Re: Weird/High CPU usage caused by LOG target

[Reindl Harald]

Am 26.12.19 um 23:29 schrieb Duncan Roe:
> On Thu, Dec 26, 2019 at 11:05:33AM +0800, Tom Yan wrote:
>> Hi all,
>>
>> So I was trying to log all traffics in the FORWARD chain with the LOG
>> target in iptables (while I say all, it's just some VPN server/client
>> that is used by only me, and the tests were just opening some
>> website).
>>
>> I notice that the logging causes high CPU usage (so it goes up only
>> when there are traffics). In (h)top, the usage shows up as openvpn's
>> if the forwarding involves their tuns. Say I am forwarding from one
>> tun to another, each of the openvpn instance will max out one core on
>> my raspberry pi 3 b+. (And that actually slows the whole system down,
>> like ssh/bash responsiveness, and stalls the traffic flow.) If I do
>> not log, or log with the NFLOG target instead, their CPU usage will be
>> less than 1%.
>>
>> Interestingly, the problem seems to be way less obvious if I am using
>> it on higher end devices (like my Haswell PC, or even a raspberry pi
>> 4). There are still "spikes" as well, but it won't make me "notice"
>> the problem, at least not when I am just doing some trivial web
>> browsing.
>>
>> Let me know how I can further help debugging, if any of you are
>> interested in fixing this.
>>
> Just in case you missed it, be sure that your logger is configured not to sync
> the file system after every logging. That is the default action btw.
> 
> I have used large-volume logging in the past and never encountered a CPU problem
> (but had to run logrotate every minute to avoid filling the disk)

the problem is "-j LOG" at it's own and not suprisingly after having
enough of random crashes and kexec only spits the disk full of
demsg-output from iptables "-j LOG" switching awy to NFLOG and ulogd and
never ever faced antother crash

"-j LOG" spits into kernel ring buffer and by it's own produces double
load no matter what happns after the action

Re: Weird/High CPU usage caused by LOG target

[Tom Yan]

Hi Duncan,

Not sure what default action you are referring to. If you are talking
about ulogd (hence NFLOG), as I said, I don't experience similar issue
with them. For the record, I tried to set `Storage=` in journald.conf
to volatile / none when I was using LOG. It didn't help avoiding the
high usage. (The usage doesn't reflect as systemd-journald's anyway.)
And I don't have any syslog installed.

Also, the CPU problem seems to be specific to low-end devices. The
"line" even seem to just draw between a raspberry pi 3 b+ and 4. So it
wouldn't surprise me if one cannot reproduce/notice it easily on some
"server server" or even just some old Nehalem desktop. By the way, I
tested with both a mainline aarch64 kernel build (5.4.6) and a
raspberrypi armv7 kernel build (4.19.88). The issue was reproducible
with either of them. (The distro was Arch Liunx ARM, if that matters.)

For the record, I am not writing because I "need to" use LOG and/or
log everything. I am writing just because I noticed the issue and felt
like I should report it. But thank you for you attention anyway.

Regards,
Tom

On Fri, 27 Dec 2019 at 06:51, Duncan Roe <duncan_roe@optusnet.com.au> wrote:
>
> On Thu, Dec 26, 2019 at 11:05:33AM +0800, Tom Yan wrote:
> > Hi all,
> >
> > So I was trying to log all traffics in the FORWARD chain with the LOG
> > target in iptables (while I say all, it's just some VPN server/client
> > that is used by only me, and the tests were just opening some
> > website).
> >
> > I notice that the logging causes high CPU usage (so it goes up only
> > when there are traffics). In (h)top, the usage shows up as openvpn's
> > if the forwarding involves their tuns. Say I am forwarding from one
> > tun to another, each of the openvpn instance will max out one core on
> > my raspberry pi 3 b+. (And that actually slows the whole system down,
> > like ssh/bash responsiveness, and stalls the traffic flow.) If I do
> > not log, or log with the NFLOG target instead, their CPU usage will be
> > less than 1%.
> >
> > Interestingly, the problem seems to be way less obvious if I am using
> > it on higher end devices (like my Haswell PC, or even a raspberry pi
> > 4). There are still "spikes" as well, but it won't make me "notice"
> > the problem, at least not when I am just doing some trivial web
> > browsing.
> >
> > Let me know how I can further help debugging, if any of you are
> > interested in fixing this.
> >
> > Regards,
> > Tom
> >
> Hi Tom,
>
> Just in case you missed it, be sure that your logger is configured not to sync
> the file system after every logging. That is the default action btw.
>
> I have used large-volume logging in the past and never encountered a CPU problem
> (but had to run logrotate every minute to avoid filling the disk).
>
> Cheers ... Duncan.

Re: Weird/High CPU usage caused by LOG target

[Tom Yan]

Hi Reindl,

Hmm. Not sure I get what you mean. Are you saying that this could be a
"generic" kernel flaw (in handling logging / messages), instead of a
Netfilter-specific issue?

Regards,
Tom

On Fri, 27 Dec 2019 at 08:23, Reindl Harald <h.reindl@thelounge.net> wrote:
>
>
>
> Am 26.12.19 um 23:29 schrieb Duncan Roe:
> > On Thu, Dec 26, 2019 at 11:05:33AM +0800, Tom Yan wrote:
> >> Hi all,
> >>
> >> So I was trying to log all traffics in the FORWARD chain with the LOG
> >> target in iptables (while I say all, it's just some VPN server/client
> >> that is used by only me, and the tests were just opening some
> >> website).
> >>
> >> I notice that the logging causes high CPU usage (so it goes up only
> >> when there are traffics). In (h)top, the usage shows up as openvpn's
> >> if the forwarding involves their tuns. Say I am forwarding from one
> >> tun to another, each of the openvpn instance will max out one core on
> >> my raspberry pi 3 b+. (And that actually slows the whole system down,
> >> like ssh/bash responsiveness, and stalls the traffic flow.) If I do
> >> not log, or log with the NFLOG target instead, their CPU usage will be
> >> less than 1%.
> >>
> >> Interestingly, the problem seems to be way less obvious if I am using
> >> it on higher end devices (like my Haswell PC, or even a raspberry pi
> >> 4). There are still "spikes" as well, but it won't make me "notice"
> >> the problem, at least not when I am just doing some trivial web
> >> browsing.
> >>
> >> Let me know how I can further help debugging, if any of you are
> >> interested in fixing this.
> >>
> > Just in case you missed it, be sure that your logger is configured not to sync
> > the file system after every logging. That is the default action btw.
> >
> > I have used large-volume logging in the past and never encountered a CPU problem
> > (but had to run logrotate every minute to avoid filling the disk)
>
> the problem is "-j LOG" at it's own and not suprisingly after having
> enough of random crashes and kexec only spits the disk full of
> demsg-output from iptables "-j LOG" switching awy to NFLOG and ulogd and
> never ever faced antother crash
>
> "-j LOG" spits into kernel ring buffer and by it's own produces double
> load no matter what happns after the action

Re: Weird/High CPU usage caused by LOG target

[Reindl Harald]

Am 27.12.19 um 02:29 schrieb Tom Yan:
> Hi Reindl,
> 
> Hmm. Not sure I get what you mean. Are you saying that this could be a
> "generic" kernel flaw (in handling logging / messages), instead of a
> Netfilter-specific issue?

dunno, but since no longer using "-j LOG" the f**g randomly crashes of
our production firewall system over months hwich nearly made me insane
are gone and that it spits to "dmesg" is ugly anyways

when i try to debug crashes, enable kexec/kdump and the only thing it
has to do is write my whole filesystem full with 100 lines iptables
related messages from dmesg repeatet until the is no space available i
am done

> On Fri, 27 Dec 2019 at 08:23, Reindl Harald <h.reindl@thelounge.net> wrote:
>>
>>
>>
>> Am 26.12.19 um 23:29 schrieb Duncan Roe:
>>> On Thu, Dec 26, 2019 at 11:05:33AM +0800, Tom Yan wrote:
>>>> Hi all,
>>>>
>>>> So I was trying to log all traffics in the FORWARD chain with the LOG
>>>> target in iptables (while I say all, it's just some VPN server/client
>>>> that is used by only me, and the tests were just opening some
>>>> website).
>>>>
>>>> I notice that the logging causes high CPU usage (so it goes up only
>>>> when there are traffics). In (h)top, the usage shows up as openvpn's
>>>> if the forwarding involves their tuns. Say I am forwarding from one
>>>> tun to another, each of the openvpn instance will max out one core on
>>>> my raspberry pi 3 b+. (And that actually slows the whole system down,
>>>> like ssh/bash responsiveness, and stalls the traffic flow.) If I do
>>>> not log, or log with the NFLOG target instead, their CPU usage will be
>>>> less than 1%.
>>>>
>>>> Interestingly, the problem seems to be way less obvious if I am using
>>>> it on higher end devices (like my Haswell PC, or even a raspberry pi
>>>> 4). There are still "spikes" as well, but it won't make me "notice"
>>>> the problem, at least not when I am just doing some trivial web
>>>> browsing.
>>>>
>>>> Let me know how I can further help debugging, if any of you are
>>>> interested in fixing this.
>>>>
>>> Just in case you missed it, be sure that your logger is configured not to sync
>>> the file system after every logging. That is the default action btw.
>>>
>>> I have used large-volume logging in the past and never encountered a CPU problem
>>> (but had to run logrotate every minute to avoid filling the disk)
>>
>> the problem is "-j LOG" at it's own and not suprisingly after having
>> enough of random crashes and kexec only spits the disk full of
>> demsg-output from iptables "-j LOG" switching awy to NFLOG and ulogd and
>> never ever faced antother crash
>>
>> "-j LOG" spits into kernel ring buffer and by it's own produces double
>> load no matter what happns after the action