QEMUv8 Xen FF-A CI job fails with "rcu: INFO: rcu_preempt detected stalls"

[jforissier]

From https://github.com/OP-TEE/optee_os/actions/runs/14962427164/job/42026468432?pr=7393:

2025-05-12T02:58:07.6573652Z cd /__w/optee_os/optee_repo_qemu_v8/build/../out/bin && \
2025-05-12T02:58:07.6574431Z 	export QEMU=/__w/optee_os/optee_repo_qemu_v8/build/../qemu/build/qemu-system-aarch64 && \
2025-05-12T02:58:07.6577058Z 	export QEMU_CHECK_ARGS="-nographic -smp 4 -cpu max,sme=off,pauth-impdef=on -d unimp -semihosting-config enable=on,target=native -m 3072 -bios bl1.bin -initrd rootfs.cpio.gz -kernel Image -append 'console=ttyAMA0,38400 keep_bootcon root=/dev/vda2 ' -drive if=none,file=/__w/optee_os/optee_repo_qemu_v8/build/../out/bin/xen.ext4,format=raw,id=hd1 -device virtio-blk-device,drive=hd1 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0,max-bytes=1024,period=1000 -netdev user,id=vmnic -device virtio-net-device,netdev=vmnic -machine virt,acpi=off,secure=on,mte=off,gic-version=3,virtualization=true  -serial mon:stdio -serial file:serial1.log -fsdev local,id=fsdev0,path=../..,security_model=none -device virtio-9p-device,fsdev=fsdev0,mount_tag=host" && \
2025-05-12T02:58:07.6579660Z 	export XEN_BOOT=y && \
2025-05-12T02:58:07.6579860Z 	export XEN_FFA=y && \
2025-05-12T02:58:07.6580058Z 	export RUST_ENABLE=y && \
2025-05-12T02:58:07.6580383Z 	expect /__w/optee_os/optee_repo_qemu_v8/build/../build/qemu-check.exp --  || \
2025-05-12T02:58:07.6580725Z 	(if [ "" ]; then \
2025-05-12T02:58:07.6580922Z 		echo "== $PWD/serial0.log:"; \
2025-05-12T02:58:07.6581137Z 		cat serial0.log; \
2025-05-12T02:58:07.6581333Z 		echo "== end of $PWD/serial0.log:"; \
2025-05-12T02:58:07.6581582Z 		echo "== $PWD/serial1.log:"; \
2025-05-12T02:58:07.6581794Z 		cat serial1.log; \
2025-05-12T02:58:07.6581981Z 		echo "== end of $PWD/serial1.log:"; \
2025-05-12T02:58:07.6582207Z 	fi; false)
2025-05-12T02:58:20.9711152Z Starting QEMU... done, guest is booted (Xen Dom0).
2025-05-12T02:58:20.9712356Z Running: xtest ...
2025-05-12T02:58:47.5259520Z ############ Kernel error: 'rcu: INFO: rcu_preempt detected stalls'
2025-05-12T02:58:47.5285334Z make: *** [Makefile:661: check] Error 1
2025-05-12T02:58:47.6640326Z ##[error]Process completed with exit code 2.

[jenswi-linaro]

I think the problem got worse when we upgraded the kernel, but even with an older kernel, we still have:

[   10.147114] BUG: scheduling while atomic: kworker/0:0/8/0x00000002
[   10.147681] Modules linked in:
[   10.147917] CPU: 0 UID: 0 PID: 8 Comm: kworker/0:0 Tainted: G        W          6.12.0-00017-g4da2533c1595 #1
[   10.148601] Tainted: [W]=WARN
[   10.148791] Hardware name: linux,dummy-virt (DT)
[   10.149133] Workqueue: ffa_pcpu_irq_notification notif_pcpu_irq_work_fn
[   10.149682] Call trace:

Only it seems to recover. I suspect the problem is in Xen.

[jenswi-linaro]

No, the problem is in the kernel. Adding

CONFIG_DEBUG_MUTEXES=y
CONFIG_DEBUG_ATOMIC_SLEEP=y

to the kernel configuration gives a lot of:

[    3.445939] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:258
[    3.446661] in_atomic(): 1, irqs_disabled(): 1, non_block: 0, pid: 9, name: kworker/0:0
[    3.447258] preempt_count: 1, expected: 0
[    3.447543] RCU nest depth: 0, expected: 0
[    3.448300] CPU: 0 UID: 0 PID: 9 Comm: kworker/0:0 Not tainted 6.14.0-00017-g7ff2e5089d2e-dirty #4
[    3.448454] Hardware name: linux,dummy-virt (DT)
[    3.448684] Workqueue: ffa_pcpu_irq_notification notif_pcpu_irq_work_fn
[    3.449710] Call trace:
[    3.449875]  show_stack+0x18/0x24 (C)
[    3.450089]  dump_stack_lvl+0x78/0x90
[    3.450136]  dump_stack+0x18/0x24
[    3.450148]  __might_resched+0x114/0x170
[    3.450160]  __might_sleep+0x48/0x98
[    3.450170]  mutex_lock+0x24/0x80
[    3.450183]  handle_notif_callbacks+0x54/0xe0
[    3.450193]  notif_get_and_handle+0x40/0x88
[    3.450203]  generic_exec_single+0x80/0xc0
[    3.450218]  smp_call_function_single+0xfc/0x1a0
[    3.450230]  notif_pcpu_irq_work_fn+0x2c/0x38
[    3.450241]  process_one_work+0x14c/0x2b4
[    3.450254]  worker_thread+0x2e4/0x3e0
[    3.450264]  kthread+0x13c/0x210
[    3.450275]  ret_from_fork+0x10/0x20

[github-actions]

This issue has been marked as a stale issue because it has been open (more than) 30 days with no activity. Remove the stale label or add a comment, otherwise this issue will automatically be closed in 5 days. Note, that you can always re-open a closed issue at any time.