Messages

@Patrick M. Hausen
My hw platform is an old sg 115 hw Rev 3,so I guess it is an uart. I will confirm the moment I come back home.

This interface is disconnected and almost dint use it in years, but I prefer to have it enabled just in case of a catastrophic event (thanks for the support, by the way)

@franco
?????

I know the problem is small and probably only happening to me, in fact I fixed it in my installation via a tunnable. I reported it back just in case is useful for somebody else, and that's all.

If you consider it is stupid is fine, we can close the thread (I already marked as solved...)

Coming back to the discussion, for me to understand it, why are you s aying all the messages are muted? They are still accesible via dmseg buffer...

All "misc" -> "urgent" does is mute the "misc" messages you said will kill your console.


Cheers,
Franco

nobody is denying that, the messages will disappear from the console because they will not be outputted by PF....

> Just to focus the discussion

No, you focus here please: if you don't want "misc" don't set "misc".

If you change the scope to the console, which happens to be a serial console, for output that is not needed for operation just turn it off. At least use the default, which is "urgent", which works for hundreds of thousands of users.


Cheers,
Franco

I think i didnt explain myself. -> setting this variable also mute the FW to the dmesg buffer afaik, this could be undesired because the logging capabilities could be affected.

I dont want to touch the logging capabilities/verbosity, i only want not to log to the serial console.

So first of all this isn't normal. Looks like corruption on the wire. Bad cables?

If its a corruption on the wire, then the CRC counter possibly should increase. So try to check your Error Interface counters.

errors logged by the HW or PF due to CRC are always 0 or 1 to maximum, the uptime is counted in tens of weeks.

you can check the previous investigations of this thread here:
https://forum.opnsense.org/index.php?topic=52224.0

Otherwise it can be caused by asymmetry.

Similar to
https://github.com/opnsense/core/issues/10346

yes, I can recognize the error and i am pretty sure it is happening to me too. I didnt give it importance because i thought it was a problem with a saturation test and those errors / RST packets could be due to duplicates or out-or-order.

But honestly, even if the errors are real and real problems are happening, i expect the FW to be able to cope with those situations, please remember that we are speaking about a 350mbps line. I expect the HW to cope with the "regular problems" with several 1gpbs interfaces maxing the transmission out.

Secondly, these are all logged under PF_DEBUG_MISC, which means that's set under Firewall: Settings: Advanced: Debug. If you select "urgent" or "none" these should go away easily. The default these days is supposed to be "urgent", but in some cases it default to "none". I can fix that.

Looking at the code at some point the default was "misc" indeed: https://github.com/opnsense/core/commit/269b8b789

This setting is only for changing the verbosity of the FW, but this is in my opinion not the root cause here.

Just to focus the discussion --> the problem is that when the FW log is sent to the serial console it can set the CPU to 100% because the PacketFilter tries to send a log message through a 115kbps interface, a few hundreds of messages per second is enough to trigger this effect in my installation. And more important, this is independent of the power of the processor.

Changing the verbosity of the kernel (because PF is executed in an irq context) will certainly mitigate the problem, but this is not addressing the issue. On top of that, i think reducing the verbosity is not a good solution because logs analysis is often a first line of defence to see if something unusual is happening

I though i explained that in my post :(

Maybe I missed this several times but what messages are we talking about exactly? Is this normalized to the point where we just assume "these messages" are a given and we need to fix the console accordingly? Why not chase these messages and mute them, or find the root cause?


Cheers,
Franco

the messages are regular pf messages about the status of the incoming packet, or when a new entry is inserted in the connections table, you can see some excerpts of the messages here:

https://forum.opnsense.org/index.php?action=dlattach;attach=56244

The root cause is just some packets with some problems in the wire, as u can see in the link, they are the typical status messages, nothing out of the ordinary, just a FW doing its job. The problem is when those messages are beyond some threshold and then start consuming cpu cycles because the default config push them into the serial console.

And this is when i would like to know if this serial output could be disabled because is taking a lot of cycles for almost nothing, because the dmesg buffer is still getting the status output.

[Short story:]

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

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

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

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

I suppose this is now answered with more detail here https://forum.opnsense.org/index.php?topic=52307.msg269775;boardseen#new so no need to repeat.

Yep, I consider this thread closed

thanks anyway

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 ?

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.

CPU bottlenecked by storage subsystem perhaps, trying to log.

AFAIK (that i could be wrong) the storage subsystem should not be in the IRQ handler, doesnt it?

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?