a few hundreds of messages from PF peg the cpu to 100% - SOLVED see #14

[thelittleblackbird]

hi all,

I was having a problem with a weak cpu and the time it spends in interrupt handling during a speed test, so I opened a thread and luckily got solvedhttps://forum.opnsense.org/index.php?topic=52224.0

But now, thinking about that I find strange that a few hundreds of messages per second is really running the performance.

So my question here woudl be, what is the expected number of messages from the FW before is hitting 50% cpu on a system like mine (Atom E3940). Shouldnt a system like this one "resist" thousands of messages per second before hitting 100% cpu?

is there any logging strategy i am doing wrong?

regards and thanks

[meyergru]

I would guess this really is more of a storage limitation because of RMW-cycles induced by ZFS.

That CPU is not the fastest, either. For each RMW cycle, it must calculate ZFS checksums. A proper centralized log server could probably buffer log messages more efficiently. If you have Monit running on top, each new message is also parsed and compared against triggers. You could use top and see which processes actually peg the CPU.

[thelittleblackbird]

hi, thanks for the answer.

I would guess this really is more of a storage limitation because of RMW-cycles induced by ZFS.

That CPU is not the fastest, either. For each RMW cycle, it must calculate ZFS checksums. A proper centralized log server could probably buffer log messages more efficiently. If you have Monit running on top, each new message is also parsed and compared against triggers. You could use top and see which processes actually peg the CPU.

Please take a look into the linked thread.

it is the IRQ handler what is maxing out the cpu.

when you say it is a storage limitation, what do you mean exactly?

[meyergru]

I mean that it is probably the CPU waiting for I/O operations to finish because the storage subsystem is struggling. With NVMe storage, writing very small, frequent log lines leads to heavy 'write amplification' due to the large underlying flash block sizes, causing significant latency spikes.

The fact that reducing the logging activity resolved the issue completely confirms the storage bottleneck theory. When the logging was set to high, the frequent, small writes to the NVMe caused massive write amplification and continuous synchronous I/O blocks.

In FreeBSD/OPNsense, such a severe storage backlog causes 'Lock Contention' in the kernel and forces an influx of Software Interrupts (SWIs) to manage the blocked I/O buffers. This is why the IRQ handler threads (intr) ran hot: they weren't just processing network packets, but handling the massive overhead of a stalling filesystem trying to commit log rows to a struggling SSD. Turning down the logs broke this vicious cycle.

[thelittleblackbird]

I mean that it is probably the CPU waiting for I/O operations to finish because the storage subsystem is struggling. With NVMe storage, writing very small, frequent log lines leads to heavy 'write amplification' due to the large underlying flash block sizes, causing significant latency spikes.

The fact that reducing the logging activity resolved the issue completely confirms the storage bottleneck theory. When the logging was set to high, the frequent, small writes to the NVMe caused massive write amplification and continuous synchronous I/O blocks.

In FreeBSD/OPNsense, such a severe storage backlog causes 'Lock Contention' in the kernel and forces an influx of Software Interrupts (SWIs) to manage the blocked I/O buffers. This is why the IRQ handler threads (intr) ran hot: they weren't just processing network packets, but handling the massive overhead of a stalling filesystem trying to commit log rows to a struggling SSD. Turning down the logs broke this vicious cycle.

got it, then it means that if instead of writing to disk, I set the option to write to ram or to send the message to another equipemetn, as you suggested, i should be able to combine a "high" level of verbosity with a low cpu usage, right?

if it is so, i will tested it tomorrow and see what is happening.

[meyergru]

Correct.

[thelittleblackbird]

Correct.

As a quick test i set up the environment option to keep /var/log into ramdisk, this should eliminate the overhead of the disk logging

It didnt work.

During the week i will install and test a log collector into another machine but i certainly have some doubts that it will be faster than a ramdisk

any thoughts ?

[cookiemonster]

Could you install htop, launch with admin privs and sort by CPU ? May show a clue

[Patrick M. Hausen]

You can just invoke "top" and sort by CPU. FreeBSD top can do that. And lots of other things.

[thelittleblackbird]

Could you install htop, launch with admin privs and sort by CPU ? May show a clue

You can just invoke "top" and sort by CPU. FreeBSD top can do that. And lots of other things.

done in the other thread i link, the top shows a 100% usage in the interrupt level specially in the netisr irq handler, see the picture:
https://forum.opnsense.org/index.php?action=dlattach;attach=56143

[cookiemonster]

You can just invoke "top" and sort by CPU. FreeBSD top can do that. And lots of other things.

True, just preferences. I find htop better shows me the process tree and colours. Just personal preferences.

Could you install htop, launch with admin privs and sort by CPU ? May show a clue

You can just invoke "top" and sort by CPU. FreeBSD top can do that. And lots of other things.

done in the other thread i link, the top shows a 100% usage in the interrupt level specially in the netisr irq handler, see the picture:
https://forum.opnsense.org/index.php?action=dlattach;attach=56143

Sure but I'm referring to htop allows to see the process tree in real time which is of more interest.

[thelittleblackbird]

Sure but I'm referring to htop allows to see the process tree in real time which is of more interest.

htop is not able to display irq handlers AFIK

in your image the interrupt context is summarized in the red bar in the processor usage, among a lot of other things

[cookiemonster]

but why limit your investigation to that metric only?
Unless I misread the whole thing you have a firewall that has an apparent overuse of cpu cycles. You are trying to investigate what _process_ might be the one(s) causing the spike in cpu cycles. Here is what my suggestion is, to use htop to see what processes are using up the cpus. From that you can hopefully identify the processes and start digging into them to figure out why.
A ps no matter what flags to use is only a point-in-time list of processes. top/htop are updating real time unless the whole machine is too overwhlemed.

[thelittleblackbird]

but why limit your investigation to that metric only?
Unless I misread the whole thing you have a firewall that has an apparent overuse of cpu cycles. You are trying to investigate what _process_ might be the one(s) causing the spike in cpu cycles. Here is what my suggestion is, to use htop to see what processes are using up the cpus. From that you can hopefully identify the processes and start digging into them to figure out why.
A ps no matter what flags to use is only a point-in-time list of processes. top/htop are updating real time unless the whole machine is too overwhlemed.

The cpu is consumed in the irq context, it is an exception handler, not a process, the IRQ is calling the netisr that is the procedure executed in the interrupt context-> this procedure is in charge of receiving and processing the packet into the PF path.

you have a detailed investigation in the thread i posted in the beginning, IRQ per second is normal, not error logged, not any HW misbehaving.

I positively know it is the logging of the FW or something related / called by pf, because logging verbosity, and fw disabled has an impact in the test.

I am currently investigating the console output (i have it enabled by default), because i also dont know what else could be once we ruled out the logging subsystem or problems wiht the ssd

[thelittleblackbird]

I found the root cause :) (or at least i believe that)

Short story:
the culprit seems to be the logging done to the serial port enabled by default in opnsense. It can be disabled in BSD with

Code Select Expand

"sysctl kern.consmute=1" which reduces the verbosity of the kernel.
Because the serial port is configured to 115Kbps the logging could make contention of the thread until the message is transmitted, keeping the processor busy just in the I/O.


Long story:
The speed test via the web interface seems to deliver duplicated, out of order and directed to other ports packets which in the end is detected by the FW and it is making it to complain, those messages are dumped into the DMESG buffer but seems also to be dumped into the active serial console.
This process is done in an IRQ context and it is managed directly by the kernel, because the console speed is 115kbps so if the number of incoming messages is bigger than the messages processed, even if the logging subsystem can be deferred, will create waiting states in the processor during the IRQ handler context.

This explains why disabling the FW, reducing the verbosity or just simply running some other tests to other interfaces were resulting in a normal behavior --> all of them reduced the level of verbosity or was making the traffic more "protocol compliant"

fortunately this logging to the serial console can be disabled via

Code Select Expand

"sysctl kern.consmute=1"It will not affect other logging mechanisms but still allows the kernel panic messages to go through. Dmesg logging seems not be affected so in the end nothing is lost. to apply the fix, needs to be done via the tunnable

This one makes me wonder why such default was selected in opnsense, because the content is created by the I/O in the serial console, how powerful the processor is not really important because the limiting factor is the transmission time.

in any case I would like to ask for 2 easy changes:

• is it possible to have a sane default that disable this kernel verbosity on an install
• is it possible to have the option in the gui to enabled it, if needed