a few hundreds of messages from PF peg the cpu to 100%

[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