[26.7.4_1]Intermittent connection drops, kernel thread at 100% CPU seems related

[dragao-azul]

Hi,

Long time lurker (thanks everyone, very useful posts), first time poster.

I'm having an issue since the 15th/16th of September that results in momentary connection drops.

Context:
I use opnsense as a firewall in my homelab, I was away for some time and on my return I immediately started experiencing occasional internet drops for 8-10sec.
OPNsense is virtualised in proxmox with the NICs (I226-V) passthroughed directly to the VM. CPU is in host mode (4 vCPUs, physical CPU is an N150).
On debug, I saw proxmox CPU usage history with higher spikes since the aforementioned dates - so I suspect that's when it started.

Current observations:
If I monitor the ping to 8.8.8.8 or 9.9.9.9 (in fact I used both simultaneously) - I sometimes get spikes of 5-10sec. During this time, I simultaneously looked at CPU usage and the system usage spikes. ChatGPT got involved from here to help debug and may be taking me in wrong directions - it did help spot that clock{clock (0)} consumes 100% of 1 CPU over this time, but I'm not sure if this by itself is very valuable.



I'm trying to progress from here but I feel like I'm getting into the weeds of the kernel's working. Is there a recommended debug strategy for this? Since the dates coincide with the latest updates was any known change introduced? The only thing that stood out (disclaimer disclaimer: helped by ChatGPT to spot it) was "o src: iflib: assorted upstream patches from stable/15" but since it was working before it would imply a regression.

In the meanwhile I'll keep trying to break down this clock thread that spikes.

Many thanks!

[meyergru]

Any specific reason not to leave handling of the physical NIC to PVE via virtio, as described here?

That would also take the igc/iflib driver path inside OPNsense out of the equation.

[dragao-azul]

Thanks meyergru, perhaps not a great one, but when I set things up I followed some friends setup that had used passthrough.
Perhaps silly, but I was also learning my steps and didn't want to accidentally give my proxmox an IP/access via WAN.


Regardless, just to acknowledge the answer and I just ported everything to virtio.
Let me monitor for a while. The first 15min look good, there's very minor peaks, on the healthy side (5% as opposed to 25% of my total CPUs), but sometimes I had 20-30min between peaks so let me give it a few hours.

[dragao-azul]

Not sure if it counts as "solved", but setting up as virtio doesn't cause the issue anymore! The intel drivers might have brought something finicky, but for virtualisation this works! Thanks again!

[dragao-azul]

Unfortunately I need to go back on my words: while everything was good for 1 day the problem came back again.

The only thing I did to make it better were a few restarts of the opnsense VM and removing the passthrough from the VM.


I've tried another reboot (of opnsense), but even immediately after that the issue repeated itself.


I noticed a post above about PPP(oE) and my WAN is a PPPoE connection (no VLAN) in case that makes a difference, but I get the feeling the post might be some unrelated boot issue?

I'll try to dig a bit further, but any pointer on the best way to go about identifying the problematic process/thread/interrupt sources would be helpful.

Thanks!

[meyergru]

That was only a boot issue and does not explain these short outages. I would try disabling multiqueue on the NICs of the OPNsense VM.

There have also been reports of a current issue that may be related:
https://forum.opnsense.org/index.php?topic=52420.0

Can you give the output of:

Code Select Expand

sysctl kern.timecounter.hardware
sysctl kern.timecounter.choice
sysctl kern.timecounter.fast_gettime

sysctl kern.eventtimer.timer
sysctl kern.eventtimer.choice
sysctl kern.eventtimer.periodic

sysctl kern.eventtimer.et.LAPIC.frequency
sysctl kern.eventtimer.et.LAPIC.quality

Also, do the outages coincide with VM snapshots or backups?

[dragao-azul]

Thanks, here's the result of those:

Code Select Expand

root@OPNsense:~ # sysctl kern.timecounter.hardware
kern.timecounter.hardware: kvmclock
root@OPNsense:~ # sysctl kern.timecounter.choice
kern.timecounter.choice: TSC(-100) i8254(0) ACPI-fast(900) kvmclock(975) dummy(-1000000)
root@OPNsense:~ # sysctl kern.timecounter.fast_gettime
kern.timecounter.fast_gettime: 1
root@OPNsense:~ #
root@OPNsense:~ # sysctl kern.eventtimer.timer
kern.eventtimer.timer: LAPIC
root@OPNsense:~ # sysctl kern.eventtimer.choice
kern.eventtimer.choice: LAPIC(600) i8254(100) RTC(0)
root@OPNsense:~ # sysctl kern.eventtimer.periodic
kern.eventtimer.periodic: 0
root@OPNsense:~ #
root@OPNsense:~ # sysctl kern.eventtimer.et.LAPIC.frequency
kern.eventtimer.et.LAPIC.frequency: 500003658
root@OPNsense:~ # sysctl kern.eventtimer.et.LAPIC.quality
kern.eventtimer.et.LAPIC.quality: 600


No, they don't coincide with snapshots or backups of this or other VM/LXC in the system. I can't say they never match as I do have 15min snapshots  (zfs) and not very precise detection of this, but the distribution is random, I have plenty of examples falling out of the snapshot/backup timestamps. It's like 5 events per hour, sometime less sometimes more.


Timers do seem relevant though - I'm parroting ChatGPT a bit, but it helped me build some dtrace analysis and (I'll quote a paragraph):

...
More importantly, the fourth capture did work, and it contains exactly the evidence we were looking for. There are substantial samples in:

Code Select Expand

tcp_timer_rexmt
tcp_timer_enter
softclock_call_cc
softclock_thread
and also a large amount of networking processing around tcp_input_with_port, IPv6, netgraph, VirtIO, etc.

So the earlier clock observation was real: at least during this event, softclock_thread is spending time processing TCP retransmission timers. That is a significant narrowing of the problem.
...


EDIT: taking a hint from the linked post thread:

Code Select Expand

root@OPNsense:~ # vmstat -i | grep timer
cpu0:timer                       8789276        829
cpu1:timer                        312606         29
cpu2:timer                        316936         30
cpu3:timer                        281377         27


[meyergru]

Thanks. This does not look like the LAPIC calibration problem from the thread I linked.

Your LAPIC frequency of about 500 MHz looks sane and is almost exactly what was reported for the working Proxmox case there. The broken case had a frequency off by roughly three orders of magnitude and around 65k timer interrupts/sec on every vCPU.

The `vmstat -i` numbers are interesting, but note that the displayed rate is averaged since boot, so it may hide what happens during one of the short stalls.

Since you are using `kvmclock`, I think one simple A/B test would still be worthwhile:

Code Select Expand

sysctl kern.timecounter.hardware=ACPI-fast

Leave everything else unchanged and see whether the stalls still occur. With several events per hour it should not take too long to get a useful result.

You can switch back with:

Code Select Expand

sysctl kern.timecounter.hardware=kvmclock

I would not conclude from the DTrace samples yet that the TCP retransmission timers are the cause. They may also be a consequence of the actual stall: if packet processing stops briefly, retransmission timers expire and `softclock_thread` subsequently has a lot of work to do.

The snapshot-related KVM clock problem I mentioned earlier also looks less likely in your case, since you have many events which clearly do not coincide with snapshots or backups.