random fails on latency tests

Well, I think it's surely related to a trace I'm getting on dmesg output. I'm getting it when using isolcpus=1 in the boot line and launching latency-histogram without taskset. Launching with taskset, no trace and no problem. I doesn't matter if taskset sets the affinity either to 1, 2 or even 1,2, trace just not happens.

From the trace, I'm pretty sure it's related to the integrated NIC, a Tigon tg3, since it's the only hardware reported as PCI-MSI. It seems to me that the kernel is having some problem setting the smp affinity for that interrupt. Using pci=nomsi on the boot line makes the NIC appear as IO-APIC, yes, but latency-histogram continues to behave the same way. Blacklisting tg3 module doesn't solve the problem, either. Since SYSINFO line says CLOCK NAME: 'tsc' but dmesg says "Clocksource: Switched to clocksource hpet", I also tried setting Clocksource=hpet on the boot line. Didn't worked.

When getting the trace, sometimes latency-histogram works as expected. If not, latency-histograms takes some seconds to start and min latency shows negative values of -24,7 and -999,7 on base and servo threads respectively, then it throws those variance errors, and you get an overrun in dmesg. Latency-test shows values in that ballpark, but as positive latency. Latency-plot doesn't get it anyway, it just shows low latency values. Linuxcnc itself, well, right now I started it with the axis simulator half a dozen times. Launched from xterm window. No taskset used. Seems to be working fine. No traces, no overruns reported, neither on the GUI, nor on the xterm, nor on dmesg output.

Funny enough, you don't always get that trace, even if not using taskset. Chance to not getting it seems higher after some tests. But after a restart, you can be pretty sure to get it, unless using taskset (or not using isolcpus=) However, without isolcpus on the boot line, latency is bad. Latency-test has the same kind of behaviour, you can get the trace, or not, but it seems to be managing it better since latency values reported are always positive. You can get the trace but get no problem sometimes, like it happens with latency-histogram. Latency-plot, as said, always gives positive, low latency values "only", even with trace and initial overrun on dmesg. Linuxcnc itself seems to behave better, but if memory serves me well, I have seen initial overruns reported on dmesg, but not reported on the GUI. That did not happen last time, however.

Well, I can work around this randomly happening error using taskset, even if latency is worse. But it seems worth to report it.

Have a nice day.

PS: Here's the trace excerpt from dmesg:[ 83.573702] elogind-daemon[1378]: New session c1 of user tatel.
[ 99.888347] I-pipe: head domain RTAI registered.
[ 99.888460] WARNING: CPU: 0 PID: 1611 at arch/x86/kernel/apic/msi.c:106 msi_set_affinity+0x120/0x150
[ 99.888461] Modules linked in: rtai_hal(+) snd_hda_codec_hdmi snd_hda_intel snd_hda_codec radeon ttm drm_kms_helper drm snd_hda_core hp_wmi snd_hwdep sparse_keymap rfkill snd_pcm wmi_bmof snd_timer snd drm_panel_orientation_quirks i2c_algo_bit evdev fb_sys_fops syscopyarea sysfillrect sysimgblt pcspkr serio_raw edac_mce_amd soundcore k8temp wmi button ext4 crc32c_generic crc16 mbcache jbd2 fscrypto sg sd_mod psmouse i2c_piix4 ohci_pci floppy ahci libahci libata scsi_mod tg3 libphy ehci_pci ohci_hcd ehci_hcd usbcore
[ 99.888474] CPU: 0 PID: 1611 Comm: insmod Tainted: G W 4.19.195-rtai-amd64 #5
[ 99.888475] Hardware name: Hewlett-Packard HP Compaq dc5850 Microtower/3029h, BIOS 786F6 v01.09 04/09/2008
[ 99.888476] I-pipe domain: Linux
[ 99.888476] RIP: 0010:msi_set_affinity+0x120/0x150
[ 99.888477] Code: 83 c7 20 c1 e7 04 ff 50 18 0f a3 e8 73 0a 48 8b 43 18 48 89 df ff 50 60 48 83 c4 08 44 89 e0 5b 5d 41 5c 41 5d 41 5e 41 5f c3 <0f> 0b 48 89 ee 48 89 df e8 e3 fd ff ff eb df 65 48 c7 04 d5 20 41
[ 99.888478] RSP: 0018:ffffc90000177bb8 EFLAGS: 00010297
[ 99.888479] RAX: 0000000000000000 RBX: ffff88807c84c828 RCX: 0000000000000000
[ 99.888480] RDX: ffff88807c84c800 RSI: 0000000000000037 RDI: 0000000000000000
[ 99.888481] RBP: ffff888079e08440 R08: 0000000000000000 R09: 0000000000000000
[ 99.888482] R10: 0000000000000040 R11: 0000000000000000 R12: 0000000000000000
[ 99.888482] R13: ffffc90000177bf8 R14: 0000000000000001 R15: ffff888079e089c0
[ 99.888483] FS: 00007ff87fc1c4c0(0000) GS:ffff88807da00000(0000) knlGS:0000000000000000
[ 99.888484] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 99.888485] CR2: 00007fd540ded0b0 CR3: 000000007aea1000 CR4: 00000000000006f0
[ 99.888485] Call Trace:
[ 99.888486] ? irq_msi_compose_msg+0x50/0x50
[ 99.888486] ? ipipe_set_irq_affinity+0x78/0xa0
[ 99.888487] ? rt_assign_irq_to_cpu+0x6e/0xa0 [rtai_hal]
[ 99.888488] ? __rtai_hal_init+0x1ec/0x220 [rtai_hal]
[ 99.888489] ? rt_free_timers+0x40/0x40 [rtai_hal]
[ 99.888489] ? do_one_initcall+0x3f/0x170
[ 99.888490] ? free_unref_page_commit+0x8a/0x100
[ 99.888490] ? kmem_cache_alloc+0x80/0xf0
[ 99.888491] ? do_init_module+0x50/0x1f0
[ 99.888492] ? load_module+0x1b07/0x1cf0
[ 99.888492] ? __do_sys_finit_module+0x96/0xb0
[ 99.888493] ? __do_sys_finit_module+0x96/0xb0
[ 99.888494] ? do_syscall_64+0x59/0x1e0
[ 99.888494] ? __ipipe_trap_prologue+0xef/0x210
[ 99.888495] ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 99.888496] ---[ end trace 3f6c88e031e59fea ]---
[ 99.888568] RTAI[hal]: mounted. ISOL_CPUS_MASK: 2.
[ 99.888571] SYSINFO - # CPUs: 2, TIMER NAME: 'lapic', TIMER IRQ: 4355, TIMER FREQ: 12466489, CLOCK NAME: 'tsc', CLOCK FREQ: 2293835000, CPU FREQ: 2293835000, LINUX TIMER IRQ: 4355.
[ 99.947127] RTAI[malloc]: global heap size = 2097152 bytes, <BSD>.
[ 99.947164] kstacks pool size = 524288 bytes
[ 99.947165] RTAI[sched]: hard timer type/freq = lapic/12466489(Hz)
[ 99.947166] linear timed lists.
[ 99.947167] RTAI[sched]: Linux timer freq = 250 (Hz), TimeBase freq = 2293835000 hz.
[ 99.947168] RTAI[sched]: timer setup = 80 ns, resched latency = 0 ns.
[ 100.007461] USERMODE CHECK: OK.
[ 100.007465] USERMODE CHECK PROVIDED (ns): KernelLatency 741, UserLatency 968.
[ 100.007467] FINAL CALIBRATION SUMMARY (ns): KernelLatency 741, UserLatency 968.
[ 100.036909] RTAI[math]: loaded, using musl libm.
 

Is this problem on launching LinuxCNC? (I know that there is an occasional problem _quitting_ LinuxCNC)

And, what is the actual error? It seems like things are carrying on through?

What you show there is very much RTAI based, and that is a separate project to LinuxCNC. It is possible that you might get more help from them?

Yep. Launching it.

After trace call, it looks to me there's a problem setting a MSI message to set smp_affinity. Trace call always happens if using isolcpus=. Sometimes latency-histogram gets through it unscathed. Other times it gets stuck at start, then shows very high negative jitter values, then it spits truckloads of messages about variance errors. Then I can see an overrun reported on dmesg output. Same with latency-test, but when it gets stuck at the start, it displays jitter values as positive. Latency-plot and, IIRC, linuxcnc, remain always unaware.

I'm working around it by launching with "taskset 2" so I need no help. Just reporting it. I agree it's RTAI-related. Yet I think all latency-histogram, latency-plot and linuxcnc should be aware of the overrun if/when it happens. I will think about reporting it to RTAI developers. Not really willing to go into yet another mailing list. But i'll probably do it after all.

With taskset 2 jitter goes from about 3 to about 12. Still good enough.

Kernel 3.4.9-rtai behaves correctly. It shows no MSI devices, so it could be a bug in 4.19.195 or a buggy BIOS, I don't know. MSI device is an integrated Tigon tg3 NIC.

Is this the RTAI kernel Andy provided for LinuxCNC ?
In that case, there are some tests i did with a bunch of older PC's, it does not work with some of those at all while 3.4.9 works perfectly well.
Latency test would run with results at 0, leme find the link:
forum.linuxcnc.org/18-computer/38838-har...ts-used-pc-s?start=0

Very nice work in that thread you provided!

I copied URLs for that thread and the lcnc-hw related one into my notes. I see the point for resizing windows, but I wonder, isn't that like testing latency while using a sledgehammer against the PC? I mean, I usually try to avoid anything unusual while testing. But, good to know, I will put an eye on that

About that RTAI kernel: yep, I think it is