kselftest ftrace timeout on 6.17-rc1

[Alexandre Ghiti]

Hi,

I'm hitting a timeout while running the kselftest ftrace. I noticed the 
following message:

[  898.107116] CPU: 3 UID: 0 PID: 0 Comm: swapper/3 Not tainted 
6.17.0-rc1-00011-gfed5c715461b #1 NONE ^M
[  898.107270] Hardware name: riscv-virtio qemu/qemu, BIOS 2024.10 
10/01/2024^M
t[  898.107422] Call Trace:^M
r[  898.107563] [<ffffffff8001c700>] dump_backtrace+0x28/0x38^M
[  898.107777] [<ffffffff800024e0>] show_stack+0x38/0x50^M
/[  898.107789] [<ffffffff80014e70>] dump_stack_lvl+0x70/0xa0^M
t[  898.107802] [<ffffffff80014eb8>] dump_stack+0x18/0x20^M
[  898.107814] [<ffffffff80003e6c>] __report_bad_irq+0x4c/0xe0^M
r[  898.107827] [<ffffffff80106490>] note_interrupt+0x2c0/0x330^M
i[  898.107841] [<ffffffff8010219a>] handle_irq_event+0xea/0x128^M
[  898.107864] [<ffffffff801085e0>] handle_fasteoi_irq+0x170/0x368^M
g[  898.107878] [<ffffffff8010143e>] handle_irq_desc+0x2e/0x50^M
g[  898.107889] [<ffffffff8010148e>] generic_handle_irq+0x2e/0x40^M
e[  898.107900] [<ffffffff808923b6>] imsic_handle_irq+0x56/0x138^M
[  898.107915] [<ffffffff8010143e>] handle_irq_desc+0x2e/0x50^M
r[  898.107926] [<ffffffff8010155e>] generic_handle_domain_irq+0x26/0x38^M
[  898.107949] [<ffffffff8088f7e6>] riscv_intc_aia_irq+0x2e/0x48^M
  [  898.107960] [<ffffffff8126008a>] handle_riscv_irq+0x6a/0x100^M
e[  898.107974] [<ffffffff812717aa>] call_on_irq_stack+0x32/0x40^M
[  898.108045] handlers:^M
vents[  898.114633] [<ffffffff80a080b0>] serial8250_interrupt^M
/n[  898.115362] Disabling IRQ #18^M

After that, the testsuite continues but when powering off the system, 
systemd processes time out and the following goes on and on up to the 
testsuite timeout:

[ 4549.527497] systemd[1]: Starting systemd-timesyncd.service - Network 
Time Synchronization...^M
+ poweroff^M
[ 4785.600294] systemd[1]: Starting systemd-udevd.service - Rule-based 
Manager for Device Events and Files...^M
[ 5072.202390] systemd[1]: systemd-journald.service: Main process 
exited, code=killed, status=6/ABRT^M
[ 5096.220366] systemd[1]: systemd-journald.service: Failed with result 
'watchdog'.^M
[ 5134.455968] systemd[1]: systemd-journald.service: Consumed 8min 
10.237s CPU time, 17.9M memory peak.^M
[ 5391.847831] systemd[1]: systemd-timesyncd.service: start operation 
timed out. Terminating.^M
[ 5406.418554] systemd[1]: systemd-udevd.service: start operation timed 
out. Terminating.^M
[ 5415.922624] systemd[1]: systemd-journald.service: Scheduled restart 
job, restart counter is at 1.^M
^[[0;1;38:5:185mFailed to set wall message, ignoring: Transport endpoint 
is not connected^[[0m^M^M
^[[0;1;31mCall to PowerOff failed: Transport endpoint is not 
connected^[[0m^M^M
^[[?2004hroot at rivos:~# [ 5694.407580] systemd[1]: Starting 
systemd-journald.service - Journal Service...^M
[ 5718.498283] systemd[1]: systemd-timesyncd.service: State 
'stop-sigterm' timed out. Killing.^M
[ 5722.711572] systemd[1]: systemd-timesyncd.service: Killing process 
5250 (9) with signal SIGKILL.^M
[ 5725.813288] systemd[1]: systemd-udevd.service: State 'stop-sigterm' 
timed out. Killing.^M
[ 5731.150475] systemd[1]: systemd-udevd.service: Killing process 5254 
(9) with signal SIGKILL.^M
[ 5753.604271] systemd[1]: systemd-journald.service: start operation 
timed out. Terminating.^M
[ 5858.815392] systemd[1]: Started systemd-initctl.service - initctl 
Compatibility Daemon.^M
[ 5902.829130] systemd[1]: systemd-timesyncd.service: Main process 
exited, code=killed, status=9/KILL^M
[ 5908.889406] systemd[1]: systemd-timesyncd.service: Failed with result 
'timeout'.^M

I haven't been able to reproduce it locally unfortunately, which is 
weird, but maybe someone has an idea what could go wrong?

Thanks,

Alex