* [BUG] RCU CPU stall warnings on TREE01 on arm64
@ 2025-05-05 19:03 Paul E. McKenney
2025-05-05 22:44 ` Paul E. McKenney
2025-05-06 14:09 ` Joel Fernandes
0 siblings, 2 replies; 7+ messages in thread
From: Paul E. McKenney @ 2025-05-05 19:03 UTC (permalink / raw)
To: rcu
Hello!
Following up on off-list discussions and requests for more information.
These reproduce reasonably easily, and here is an example:
------------------------------------------------------------------------
[ 426.022056] rcu: NOCB: Cannot CB-offload online CPU 25
[ 460.867350] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 460.867980] rcu: 0-...!: (1 GPs behind) idle=8fe4/1/0x4000000000000000 softirq=2124/2125 fqs=0
[ 460.868726] rcu: 1-...!: (1 GPs behind) idle=e0ac/1/0x4000000000000000 softirq=3547/3547 fqs=0
[ 460.869468] rcu: 5-...!: (1 GPs behind) idle=5c34/1/0x4000000000000000 softirq=2084/2084 fqs=0
[ 460.870233] rcu: 8-...!: (1 GPs behind) idle=9fdc/1/0x4000000000000000 softirq=4301/4301 fqs=0
[ 460.871007] rcu: 9-...!: (0 ticks this GP) idle=4a2c/1/0x4000000000000000 softirq=3873/3873 fqs=0
[ 460.871772] rcu: 10-...!: (1 GPs behind) idle=4994/1/0x4000000000000000 softirq=4760/4760 fqs=0
[ 460.872511] rcu: 12-...!: (1 GPs behind) idle=0bbc/1/0x4000000000000000 softirq=3545/3545 fqs=0
[ 460.873300] rcu: 13-...!: (1 GPs behind) idle=a59c/1/0x4000000000000000 softirq=2097/2098 fqs=0
[ 460.874084] rcu: 14-...!: (1 GPs behind) idle=22cc/1/0x4000000000000000 softirq=4424/4424 fqs=0
[ 460.874864] rcu: 15-...!: (1 GPs behind) idle=0e5c/1/0x4000000000000000 softirq=5984/5984 fqs=0
[ 460.875625] rcu: 16-...!: (1 GPs behind) idle=d5bc/1/0x4000000000000000 softirq=6313/6313 fqs=0
[ 460.876374] rcu: 17-...!: (1 GPs behind) idle=848c/1/0x4000000000000000 softirq=4160/4160 fqs=0
[ 460.877182] rcu: 18-...!: (1 GPs behind) idle=a1c4/1/0x4000000000000000 softirq=3217/3217 fqs=0
[ 460.877930] rcu: 19-...!: (0 ticks this GP) idle=cbe4/1/0x4000000000000000 softirq=7886/7886 fqs=0
[ 460.878772] rcu: 20-...!: (1 GPs behind) idle=3acc/1/0x4000000000000000 softirq=4315/4317 fqs=0
[ 460.879514] rcu: 21-...!: (1 GPs behind) idle=eb7c/1/0x4000000000000000 softirq=4221/4221 fqs=0
[ 460.880225] rcu: 22-...!: (1 GPs behind) idle=477c/1/0x4000000000000000 softirq=5049/5049 fqs=0
[ 460.880990] rcu: 23-...!: (1 GPs behind) idle=8404/1/0x4000000000000000 softirq=5635/5636 fqs=0
[ 460.881739] rcu: 24-...!: (0 ticks this GP) idle=11e4/1/0x4000000000000000 softirq=2031/2031 fqs=0
[ 460.882497] rcu: 25-...!: (0 ticks this GP) idle=3434/1/0x4000000000000000 softirq=3495/3495 fqs=0
[ 460.883296] rcu: 26-...!: (1 GPs behind) idle=f864/1/0x4000000000000000 softirq=3645/3645 fqs=0
[ 460.884054] rcu: 27-...!: (0 ticks this GP) idle=3e74/1/0x4000000000000000 softirq=4168/4168 fqs=0
[ 460.884805] rcu: 28-...!: (1 GPs behind) idle=71a4/1/0x4000000000000000 softirq=3596/3596 fqs=0
[ 460.885570] rcu: 29-...!: (1 GPs behind) idle=9aa4/1/0x4000000000000000 softirq=3111/3112 fqs=0
[ 460.886276] rcu: 30-...!: (1 GPs behind) idle=10dc/1/0x4000000000000000 softirq=3030/3030 fqs=0
[ 460.887030] rcu: 31-...!: (0 ticks this GP) idle=0fb4/1/0x4000000000000000 softirq=3540/3540 fqs=0
[ 460.887777] rcu: 32-...!: (1 GPs behind) idle=fad4/1/0x4000000000000000 softirq=2645/2645 fqs=0
[ 460.888548] rcu: 33-...!: (0 ticks this GP) idle=37ac/1/0x4000000000000000 softirq=2201/2201 fqs=0
[ 460.889336] rcu: 34-...!: (1 GPs behind) idle=85ac/1/0x4000000000000000 softirq=2336/2336 fqs=0
[ 460.890081] rcu: 35-...!: (1 GPs behind) idle=756c/1/0x4000000000000000 softirq=1534/1536 fqs=0
[ 460.890820] rcu: 36-...!: (0 ticks this GP) idle=b2ec/1/0x4000000000000000 softirq=4286/4286 fqs=0
[ 460.891572] rcu: 37-...!: (1 GPs behind) idle=de1c/1/0x4000000000000000 softirq=2725/2725 fqs=0
[ 460.892323] rcu: 38-...!: (1 GPs behind) idle=c62c/1/0x4000000000000000 softirq=2341/2342 fqs=0
[ 460.893096] rcu: 39-...!: (1 GPs behind) idle=be2c/1/0x4000000000000000 softirq=2650/2651 fqs=0
[ 460.893830] rcu: 40-...!: (1 GPs behind) idle=7ecc/1/0x4000000000000000 softirq=2119/2121 fqs=0
[ 460.894621] rcu: 41-...!: (0 ticks this GP) idle=19dc/1/0x4000000000000000 softirq=3539/3539 fqs=0
[ 460.895384] rcu: 42-...!: (0 ticks this GP) idle=a74c/1/0x4000000000000000 softirq=2259/2259 fqs=0
[ 460.896148] rcu: Tasks blocked on level-1 rcu_node (CPUs 30-42): P91/1:b..l
[ 460.896778] rcu: (detected by 11, t=7962 jiffies, g=15565, q=48 ncpus=39)
[ 460.897395] Sending NMI from CPU 11 to CPUs 0:
[ 461.047304] rcu-torture: rtc: 00000000fb6bc815 ver: 2137 tfle: 0 rta: 2137 rtaf: 0 rtf: 2128 rtmbe: 0 rtmbkf: 0/2042 rtbe: 0 rtbke: 0 rtbf: 0 rtb: 0 nt: 148999 onoff: 32/32:36/37 7,348:36,3639 4096:26899 (HZ=250) barrier: 979/980:0 read-exits: 416 nocb-toggles: 1013:969 gpwraps: 0
[ 461.047343] rcu-torture: Reader Pipe: 1919541609 11501 0 0 0 0 0 0 0 0 0
[ 461.047383] rcu-torture: Reader Batch: 1919533823 19422 0 0 0 0 0 0 0 0 0
[ 461.047401] rcu-torture: Free-Block Circulation: 2136 2136 2135 2134 2133 2132 2131 2130 2129 2128 0
[ 462.777371] NMI backtrace for cpu 0
[ 462.777547] CPU: 0 UID: 0 PID: 20 Comm: migration/0 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
[ 462.777551] Hardware name: linux,dummy-virt (DT)
[ 462.777552] Stopper: multi_cpu_stop+0x0/0x15c <- __stop_cpus.constprop.0+0x78/0xc4
[ 462.777564] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
[ 462.777566] pc : handle_softirqs+0xa0/0x248
[ 462.777836] lr : handle_softirqs+0x7c/0x248
[ 462.777838] sp : ffff800080003f50
[ 462.777839] x29: ffff800080003f50 x28: ffff000003d9d780 x27: 0000000000000000
[ 462.777842] x26: 0000000000000282 x25: 0000000000000000 x24: ffffafb5af9f4000
[ 462.777843] x23: 0000000063400005 x22: ffffafb5adb9b8f0 x21: ffffafb5af9e93c8
[ 462.778009] x20: ffffafb5b02970c0 x19: ffff000003d9d780 x18: 0000000000000001
[ 462.778012] x17: ffff504a6d7bc000 x16: ffff800080000000 x15: ffff00001d5f4d00
[ 462.778013] x14: 0000000000000156 x13: 0000000000000000 x12: 0000000000000000
[ 462.778015] x11: ffff00001d1b0d80 x10: 00000000002ab980 x9 : 0000000000000000
[ 462.778017] x8 : 000001d6146032ba x7 : ffff00000500b800 x6 : 0000000000000000
[ 462.778019] x5 : 00000000002ab980 x4 : 0000000100009e3e x3 : ffff504a6d7bc000
[ 462.778020] x2 : 0000006bbfae36c0 x1 : ffff504a6d7bc000 x0 : ffffafb5af9f4000
[ 462.778232] Call trace:
[ 462.778233] handle_softirqs+0xa0/0x248 (P)
[ 462.778296] __do_softirq+0x14/0x20
[ 462.778299] ____do_softirq+0x10/0x1c
[ 462.778389] call_on_irq_stack+0x24/0x4c
[ 462.778391] do_softirq_own_stack+0x1c/0x2c
[ 462.778393] __irq_exit_rcu+0xd8/0x110
[ 462.778395] irq_exit_rcu+0x10/0x1c
[ 462.778456] el1_interrupt+0x38/0x68
[ 462.778531] el1h_64_irq_handler+0x18/0x24
[ 462.778533] el1h_64_irq+0x6c/0x70
[ 462.778534] multi_cpu_stop+0xf0/0x15c (P)
[ 462.778536] cpu_stopper_thread+0x8c/0x11c
[ 462.778642] smpboot_thread_fn+0x220/0x24c
[ 462.778647] kthread+0x134/0x208
[ 462.778649] ret_from_fork+0x10/0x20
[ 463.888107] NMI backtrace for cpu 1
[ 463.888117] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
[ 463.888120] Hardware name: linux,dummy-virt (DT)
[ 463.888121] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
[ 463.888123] pc : handle_softirqs+0xa0/0x248
[ 463.888135] lr : handle_softirqs+0x7c/0x248
[ 463.888140] sp : ffff80008000bf50
[ 463.888140] x29: ffff80008000bf50 x28: ffff000003d9e900 x27: 0000000000000000
[ 463.888143] x26: 0000000000000282 x25: ffff000003d9e900 x24: ffffafb5af9f4000
[ 463.888146] x23: 0000000063400005 x22: ffffafb5adad9114 x21: ffffafb5af9e93c8
[ 463.888148] x20: ffffafb5b02970c0 x19: ffff000003d9e900 x18: 0000000000000000
[ 463.888150] x17: ffff504a6d7d6000 x16: ffff800080008000 x15: ffff00001d1cad00
[ 463.888152] x14: 0000000000000112 x13: 0000000000000000 x12: 0000000000000000
[ 463.888158] x11: 0000000000000a95 x10: 0000000000000163 x9 : 0000000000000000
[ 463.888160] x8 : 0000006bfc655500 x7 : 7fffffffffffffff x6 : 0000006bfc655500
[ 463.888165] x5 : 0000006bfca25e00 x4 : 0000000100009ff5 x3 : ffff504a6d7d6000
[ 463.888168] x2 : 0000006c01e2bea0 x1 : ffff504a6d7d6000 x0 : ffffafb5af9f4000
[ 463.888171] Call trace:
[ 463.888172] handle_softirqs+0xa0/0x248 (P)
[ 463.888175] __do_softirq+0x14/0x20
[ 463.888178] ____do_softirq+0x10/0x1c
[ 463.888183] call_on_irq_stack+0x24/0x4c
[ 463.888185] do_softirq_own_stack+0x1c/0x2c
[ 463.888187] __irq_exit_rcu+0xd8/0x110
[ 463.888192] irq_exit_rcu+0x10/0x1c
[ 463.888194] el1_interrupt+0x38/0x68
[ 463.888198] el1h_64_irq_handler+0x18/0x24
[ 463.888200] el1h_64_irq+0x6c/0x70
[ 463.888202] finish_task_switch.isra.0+0x74/0x220 (P)
[ 463.888207] __schedule+0x2fc/0x998
[ 463.888210] schedule_idle+0x28/0x48
[ 463.888212] do_idle+0x170/0x268
[ 463.888215] cpu_startup_entry+0x34/0x3c
[ 463.888217] secondary_start_kernel+0x138/0x158
[ 463.888224] __secondary_switched+0xc0/0xc4
[ 463.941174] NMI backtrace for cpu 8
[ 463.941179] CPU: 8 UID: 0 PID: 19 Comm: rcu_exp_gp_kthr Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
[ 463.941220] Hardware name: linux,dummy-virt (DT)
[ 463.941222] pstate: 23400005 (nzCv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
[ 463.941223] pc : smp_call_function_single+0xe4/0x1b0
[ 463.941292] lr : __sync_rcu_exp_select_node_cpus+0x224/0x3c8
[ 463.941366] sp : ffff800080233cd0
[ 463.941367] x29: ffff800080233d20 x28: 0000000000000002 x27: ffff000003d9c600
[ 463.941370] x26: ffffafb5b032a880 x25: ffff00001d4d7ac0 x24: ffffafb5adb49e24
[ 463.941372] x23: 0000000000001fff x22: ffffafb5af9f5ac0 x21: ffffafb5b029ea08
[ 463.941374] x20: 0000000000000000 x19: ffff800080233ce0 x18: 0000000000000001
[ 463.941376] x17: ffff504a6d88c000 x16: ffff800080040000 x15: 0000000000000000
[ 463.941378] x14: 0000000000000115 x13: 0000000000000115 x12: 0000000000000000
[ 463.941380] x11: ffffafb5af9f0408 x10: 0000000000000001 x9 : ffff000003d9c600
[ 463.941462] x8 : 0000000000000040 x7 : ffffafb5b0322ab0 x6 : ffffafb5adb49e24
[ 463.941464] x5 : 0000000000000000 x4 : ffff00001d281f08 x3 : 0000000000000001
[ 463.941535] x2 : 0000000000000000 x1 : ffff00001d281f00 x0 : 000000000000001f
[ 463.941537] Call trace:
[ 463.941538] smp_call_function_single+0xe4/0x1b0 (P)
[ 463.941541] __sync_rcu_exp_select_node_cpus+0x224/0x3c8
[ 463.941619] sync_rcu_exp_select_cpus+0x138/0x2a4
[ 463.941622] wait_rcu_exp_gp+0x18/0x30
[ 463.941644] kthread_worker_fn+0xcc/0x184
[ 463.941708] kthread+0x134/0x208
[ 463.941709] ret_from_fork+0x10/0x20
------------------------------------------------------------------------
At first glance, this looks like a stop_machine() request gone bad.
Please note that I am seeing this on most TREE01 runs and nowhere else.
So this might be a strange side effect of dynamic callback offloading,
but perhaps more likely due to TREE01 using more CPUs than it is allowing
for, that is, telling qemu "-smp 43", the kernel "maxcpus=8 nr_cpus=43",
but forcing the guest OS to run on only eight CPUs. (Why??? Well,
back in the day, there was an RCU bug exposed by this.)
All that aside, this is one of the more spectacular RCU CPU stall warnings
I have ever seen, and that is with me leaving off the NMI stack traces
for most of the CPUs. ;-)
If there is interest, I could post a tarball of a few of the full
console logs.
Come to think of it, even if there isn't interest, here you go! ;-)
https://drive.google.com/file/d/1JKmCYqK6kAwhlJZUJQeTle-o62aJXkUQ/view?usp=sharing
Thanx, Paul
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [BUG] RCU CPU stall warnings on TREE01 on arm64
2025-05-05 19:03 [BUG] RCU CPU stall warnings on TREE01 on arm64 Paul E. McKenney
@ 2025-05-05 22:44 ` Paul E. McKenney
2025-05-06 0:09 ` Paul E. McKenney
2025-05-06 14:09 ` Joel Fernandes
1 sibling, 1 reply; 7+ messages in thread
From: Paul E. McKenney @ 2025-05-05 22:44 UTC (permalink / raw)
To: rcu
On Mon, May 05, 2025 at 12:03:10PM -0700, Paul E. McKenney wrote:
> Hello!
>
> Following up on off-list discussions and requests for more information.
>
> These reproduce reasonably easily, and here is an example:
>
> ------------------------------------------------------------------------
> [ 426.022056] rcu: NOCB: Cannot CB-offload online CPU 25
> [ 460.867350] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> [ 460.867980] rcu: 0-...!: (1 GPs behind) idle=8fe4/1/0x4000000000000000 softirq=2124/2125 fqs=0
> [ 460.868726] rcu: 1-...!: (1 GPs behind) idle=e0ac/1/0x4000000000000000 softirq=3547/3547 fqs=0
Early returns suggest that the following patch suppresses this issue.
My guess is that the changes to TREE01 suffice, but I will try later
excluding the TREE01.boot changes. Architecture-dependent rcutorture
scenario files, anyone? :-/
Thanx, Paul
------------------------------------------------------------------------
diff --git a/tools/testing/selftests/rcutorture/configs/rcu/TREE01 b/tools/testing/selftests/rcutorture/configs/rcu/TREE01
index 8ae41d5f81a3..6281dbdc189f 100644
--- a/tools/testing/selftests/rcutorture/configs/rcu/TREE01
+++ b/tools/testing/selftests/rcutorture/configs/rcu/TREE01
@@ -8,8 +8,9 @@ CONFIG_NO_HZ_IDLE=y
CONFIG_NO_HZ_FULL=n
CONFIG_RCU_TRACE=y
CONFIG_HOTPLUG_CPU=y
-CONFIG_MAXSMP=y
-CONFIG_CPUMASK_OFFSTACK=y
+#CONFIG_MAXSMP=y
+CONFIG_NR_CPUS=8
+#CONFIG_CPUMASK_OFFSTACK=y
CONFIG_RCU_NOCB_CPU=y
CONFIG_DEBUG_LOCK_ALLOC=n
CONFIG_RCU_BOOST=n
diff --git a/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot b/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot
index 40af3df0f397..45e3b33f12a3 100644
--- a/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot
+++ b/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot
@@ -1,4 +1,4 @@
-maxcpus=8 nr_cpus=43
+maxcpus=8 nr_cpus=8
rcutree.gp_preinit_delay=3
rcutree.gp_init_delay=3
rcutree.gp_cleanup_delay=3
^ permalink raw reply related [flat|nested] 7+ messages in thread
* Re: [BUG] RCU CPU stall warnings on TREE01 on arm64
2025-05-05 22:44 ` Paul E. McKenney
@ 2025-05-06 0:09 ` Paul E. McKenney
0 siblings, 0 replies; 7+ messages in thread
From: Paul E. McKenney @ 2025-05-06 0:09 UTC (permalink / raw)
To: rcu
On Mon, May 05, 2025 at 03:44:43PM -0700, Paul E. McKenney wrote:
> On Mon, May 05, 2025 at 12:03:10PM -0700, Paul E. McKenney wrote:
> > Hello!
> >
> > Following up on off-list discussions and requests for more information.
> >
> > These reproduce reasonably easily, and here is an example:
> >
> > ------------------------------------------------------------------------
> > [ 426.022056] rcu: NOCB: Cannot CB-offload online CPU 25
> > [ 460.867350] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > [ 460.867980] rcu: 0-...!: (1 GPs behind) idle=8fe4/1/0x4000000000000000 softirq=2124/2125 fqs=0
> > [ 460.868726] rcu: 1-...!: (1 GPs behind) idle=e0ac/1/0x4000000000000000 softirq=3547/3547 fqs=0
>
> Early returns suggest that the following patch suppresses this issue.
> My guess is that the changes to TREE01 suffice, but I will try later
> excluding the TREE01.boot changes. Architecture-dependent rcutorture
> scenario files, anyone? :-/
Seven of nine runs failed without the patch below, and all of 63 passed
with the patch. With only the Kconfig-option portion of the patch,
all of nine passed.
One option is the architecture-dependent rcutorture scenario files
mentioned above. Another is to remove the CONFIG_MAXSMP=y and
CONFIG_CPUMASK_OFFSTACK=y from TREE01, but then add them to a new
architecture-dependent option in torture.sh.
Other options?
Thanx, Paul
> ------------------------------------------------------------------------
>
> diff --git a/tools/testing/selftests/rcutorture/configs/rcu/TREE01 b/tools/testing/selftests/rcutorture/configs/rcu/TREE01
> index 8ae41d5f81a3..6281dbdc189f 100644
> --- a/tools/testing/selftests/rcutorture/configs/rcu/TREE01
> +++ b/tools/testing/selftests/rcutorture/configs/rcu/TREE01
> @@ -8,8 +8,9 @@ CONFIG_NO_HZ_IDLE=y
> CONFIG_NO_HZ_FULL=n
> CONFIG_RCU_TRACE=y
> CONFIG_HOTPLUG_CPU=y
> -CONFIG_MAXSMP=y
> -CONFIG_CPUMASK_OFFSTACK=y
> +#CONFIG_MAXSMP=y
> +CONFIG_NR_CPUS=8
> +#CONFIG_CPUMASK_OFFSTACK=y
> CONFIG_RCU_NOCB_CPU=y
> CONFIG_DEBUG_LOCK_ALLOC=n
> CONFIG_RCU_BOOST=n
> diff --git a/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot b/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot
> index 40af3df0f397..45e3b33f12a3 100644
> --- a/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot
> +++ b/tools/testing/selftests/rcutorture/configs/rcu/TREE01.boot
> @@ -1,4 +1,4 @@
> -maxcpus=8 nr_cpus=43
> +maxcpus=8 nr_cpus=8
> rcutree.gp_preinit_delay=3
> rcutree.gp_init_delay=3
> rcutree.gp_cleanup_delay=3
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [BUG] RCU CPU stall warnings on TREE01 on arm64
2025-05-05 19:03 [BUG] RCU CPU stall warnings on TREE01 on arm64 Paul E. McKenney
2025-05-05 22:44 ` Paul E. McKenney
@ 2025-05-06 14:09 ` Joel Fernandes
2025-05-06 18:03 ` Paul E. McKenney
1 sibling, 1 reply; 7+ messages in thread
From: Joel Fernandes @ 2025-05-06 14:09 UTC (permalink / raw)
To: paulmck, rcu
On 5/5/2025 3:03 PM, Paul E. McKenney wrote:
> Hello!
>
> Following up on off-list discussions and requests for more information.
>
> These reproduce reasonably easily, and here is an example:
>
> ------------------------------------------------------------------------
> [ 426.022056] rcu: NOCB: Cannot CB-offload online CPU 25
> [ 460.867350] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> [ 460.867980] rcu: 0-...!: (1 GPs behind) idle=8fe4/1/0x4000000000000000 softirq=2124/2125 fqs=0
> [ 460.868726] rcu: 1-...!: (1 GPs behind) idle=e0ac/1/0x4000000000000000 softirq=3547/3547 fqs=0
> [ 460.869468] rcu: 5-...!: (1 GPs behind) idle=5c34/1/0x4000000000000000 softirq=2084/2084 fqs=0
> [ 460.870233] rcu: 8-...!: (1 GPs behind) idle=9fdc/1/0x4000000000000000 softirq=4301/4301 fqs=0
> [ 460.871007] rcu: 9-...!: (0 ticks this GP) idle=4a2c/1/0x4000000000000000 softirq=3873/3873 fqs=0
> [ 460.871772] rcu: 10-...!: (1 GPs behind) idle=4994/1/0x4000000000000000 softirq=4760/4760 fqs=0
> [ 460.872511] rcu: 12-...!: (1 GPs behind) idle=0bbc/1/0x4000000000000000 softirq=3545/3545 fqs=0
> [ 460.873300] rcu: 13-...!: (1 GPs behind) idle=a59c/1/0x4000000000000000 softirq=2097/2098 fqs=0
> [ 460.874084] rcu: 14-...!: (1 GPs behind) idle=22cc/1/0x4000000000000000 softirq=4424/4424 fqs=0
> [ 460.874864] rcu: 15-...!: (1 GPs behind) idle=0e5c/1/0x4000000000000000 softirq=5984/5984 fqs=0
> [ 460.875625] rcu: 16-...!: (1 GPs behind) idle=d5bc/1/0x4000000000000000 softirq=6313/6313 fqs=0
> [ 460.876374] rcu: 17-...!: (1 GPs behind) idle=848c/1/0x4000000000000000 softirq=4160/4160 fqs=0
> [ 460.877182] rcu: 18-...!: (1 GPs behind) idle=a1c4/1/0x4000000000000000 softirq=3217/3217 fqs=0
> [ 460.877930] rcu: 19-...!: (0 ticks this GP) idle=cbe4/1/0x4000000000000000 softirq=7886/7886 fqs=0
> [ 460.878772] rcu: 20-...!: (1 GPs behind) idle=3acc/1/0x4000000000000000 softirq=4315/4317 fqs=0
> [ 460.879514] rcu: 21-...!: (1 GPs behind) idle=eb7c/1/0x4000000000000000 softirq=4221/4221 fqs=0
> [ 460.880225] rcu: 22-...!: (1 GPs behind) idle=477c/1/0x4000000000000000 softirq=5049/5049 fqs=0
> [ 460.880990] rcu: 23-...!: (1 GPs behind) idle=8404/1/0x4000000000000000 softirq=5635/5636 fqs=0
> [ 460.881739] rcu: 24-...!: (0 ticks this GP) idle=11e4/1/0x4000000000000000 softirq=2031/2031 fqs=0
> [ 460.882497] rcu: 25-...!: (0 ticks this GP) idle=3434/1/0x4000000000000000 softirq=3495/3495 fqs=0
> [ 460.883296] rcu: 26-...!: (1 GPs behind) idle=f864/1/0x4000000000000000 softirq=3645/3645 fqs=0
> [ 460.884054] rcu: 27-...!: (0 ticks this GP) idle=3e74/1/0x4000000000000000 softirq=4168/4168 fqs=0
> [ 460.884805] rcu: 28-...!: (1 GPs behind) idle=71a4/1/0x4000000000000000 softirq=3596/3596 fqs=0
> [ 460.885570] rcu: 29-...!: (1 GPs behind) idle=9aa4/1/0x4000000000000000 softirq=3111/3112 fqs=0
> [ 460.886276] rcu: 30-...!: (1 GPs behind) idle=10dc/1/0x4000000000000000 softirq=3030/3030 fqs=0
> [ 460.887030] rcu: 31-...!: (0 ticks this GP) idle=0fb4/1/0x4000000000000000 softirq=3540/3540 fqs=0
> [ 460.887777] rcu: 32-...!: (1 GPs behind) idle=fad4/1/0x4000000000000000 softirq=2645/2645 fqs=0
> [ 460.888548] rcu: 33-...!: (0 ticks this GP) idle=37ac/1/0x4000000000000000 softirq=2201/2201 fqs=0
> [ 460.889336] rcu: 34-...!: (1 GPs behind) idle=85ac/1/0x4000000000000000 softirq=2336/2336 fqs=0
> [ 460.890081] rcu: 35-...!: (1 GPs behind) idle=756c/1/0x4000000000000000 softirq=1534/1536 fqs=0
> [ 460.890820] rcu: 36-...!: (0 ticks this GP) idle=b2ec/1/0x4000000000000000 softirq=4286/4286 fqs=0
> [ 460.891572] rcu: 37-...!: (1 GPs behind) idle=de1c/1/0x4000000000000000 softirq=2725/2725 fqs=0
> [ 460.892323] rcu: 38-...!: (1 GPs behind) idle=c62c/1/0x4000000000000000 softirq=2341/2342 fqs=0
> [ 460.893096] rcu: 39-...!: (1 GPs behind) idle=be2c/1/0x4000000000000000 softirq=2650/2651 fqs=0
> [ 460.893830] rcu: 40-...!: (1 GPs behind) idle=7ecc/1/0x4000000000000000 softirq=2119/2121 fqs=0
> [ 460.894621] rcu: 41-...!: (0 ticks this GP) idle=19dc/1/0x4000000000000000 softirq=3539/3539 fqs=0
> [ 460.895384] rcu: 42-...!: (0 ticks this GP) idle=a74c/1/0x4000000000000000 softirq=2259/2259 fqs=0
> [ 460.896148] rcu: Tasks blocked on level-1 rcu_node (CPUs 30-42): P91/1:b..l
> [ 460.896778] rcu: (detected by 11, t=7962 jiffies, g=15565, q=48 ncpus=39)
> [ 460.897395] Sending NMI from CPU 11 to CPUs 0:
> [ 461.047304] rcu-torture: rtc: 00000000fb6bc815 ver: 2137 tfle: 0 rta: 2137 rtaf: 0 rtf: 2128 rtmbe: 0 rtmbkf: 0/2042 rtbe: 0 rtbke: 0 rtbf: 0 rtb: 0 nt: 148999 onoff: 32/32:36/37 7,348:36,3639 4096:26899 (HZ=250) barrier: 979/980:0 read-exits: 416 nocb-toggles: 1013:969 gpwraps: 0
> [ 461.047343] rcu-torture: Reader Pipe: 1919541609 11501 0 0 0 0 0 0 0 0 0
> [ 461.047383] rcu-torture: Reader Batch: 1919533823 19422 0 0 0 0 0 0 0 0 0
> [ 461.047401] rcu-torture: Free-Block Circulation: 2136 2136 2135 2134 2133 2132 2131 2130 2129 2128 0
> [ 462.777371] NMI backtrace for cpu 0
> [ 462.777547] CPU: 0 UID: 0 PID: 20 Comm: migration/0 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> [ 462.777551] Hardware name: linux,dummy-virt (DT)
> [ 462.777552] Stopper: multi_cpu_stop+0x0/0x15c <- __stop_cpus.constprop.0+0x78/0xc4
> [ 462.777564] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> [ 462.777566] pc : handle_softirqs+0xa0/0x248
> [ 462.777836] lr : handle_softirqs+0x7c/0x248
> [ 462.777838] sp : ffff800080003f50
> [ 462.777839] x29: ffff800080003f50 x28: ffff000003d9d780 x27: 0000000000000000
> [ 462.777842] x26: 0000000000000282 x25: 0000000000000000 x24: ffffafb5af9f4000
> [ 462.777843] x23: 0000000063400005 x22: ffffafb5adb9b8f0 x21: ffffafb5af9e93c8
> [ 462.778009] x20: ffffafb5b02970c0 x19: ffff000003d9d780 x18: 0000000000000001
> [ 462.778012] x17: ffff504a6d7bc000 x16: ffff800080000000 x15: ffff00001d5f4d00
> [ 462.778013] x14: 0000000000000156 x13: 0000000000000000 x12: 0000000000000000
> [ 462.778015] x11: ffff00001d1b0d80 x10: 00000000002ab980 x9 : 0000000000000000
> [ 462.778017] x8 : 000001d6146032ba x7 : ffff00000500b800 x6 : 0000000000000000
> [ 462.778019] x5 : 00000000002ab980 x4 : 0000000100009e3e x3 : ffff504a6d7bc000
> [ 462.778020] x2 : 0000006bbfae36c0 x1 : ffff504a6d7bc000 x0 : ffffafb5af9f4000
> [ 462.778232] Call trace:
> [ 462.778233] handle_softirqs+0xa0/0x248 (P)
> [ 462.778296] __do_softirq+0x14/0x20
> [ 462.778299] ____do_softirq+0x10/0x1c
> [ 462.778389] call_on_irq_stack+0x24/0x4c
> [ 462.778391] do_softirq_own_stack+0x1c/0x2c
> [ 462.778393] __irq_exit_rcu+0xd8/0x110
> [ 462.778395] irq_exit_rcu+0x10/0x1c
> [ 462.778456] el1_interrupt+0x38/0x68
> [ 462.778531] el1h_64_irq_handler+0x18/0x24
> [ 462.778533] el1h_64_irq+0x6c/0x70
> [ 462.778534] multi_cpu_stop+0xf0/0x15c (P)
> [ 462.778536] cpu_stopper_thread+0x8c/0x11c
> [ 462.778642] smpboot_thread_fn+0x220/0x24c
> [ 462.778647] kthread+0x134/0x208
> [ 462.778649] ret_from_fork+0x10/0x20
> [ 463.888107] NMI backtrace for cpu 1
> [ 463.888117] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> [ 463.888120] Hardware name: linux,dummy-virt (DT)
> [ 463.888121] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> [ 463.888123] pc : handle_softirqs+0xa0/0x248
> [ 463.888135] lr : handle_softirqs+0x7c/0x248
> [ 463.888140] sp : ffff80008000bf50
> [ 463.888140] x29: ffff80008000bf50 x28: ffff000003d9e900 x27: 0000000000000000
> [ 463.888143] x26: 0000000000000282 x25: ffff000003d9e900 x24: ffffafb5af9f4000
> [ 463.888146] x23: 0000000063400005 x22: ffffafb5adad9114 x21: ffffafb5af9e93c8
> [ 463.888148] x20: ffffafb5b02970c0 x19: ffff000003d9e900 x18: 0000000000000000
> [ 463.888150] x17: ffff504a6d7d6000 x16: ffff800080008000 x15: ffff00001d1cad00
> [ 463.888152] x14: 0000000000000112 x13: 0000000000000000 x12: 0000000000000000
> [ 463.888158] x11: 0000000000000a95 x10: 0000000000000163 x9 : 0000000000000000
> [ 463.888160] x8 : 0000006bfc655500 x7 : 7fffffffffffffff x6 : 0000006bfc655500
> [ 463.888165] x5 : 0000006bfca25e00 x4 : 0000000100009ff5 x3 : ffff504a6d7d6000
> [ 463.888168] x2 : 0000006c01e2bea0 x1 : ffff504a6d7d6000 x0 : ffffafb5af9f4000
> [ 463.888171] Call trace:
> [ 463.888172] handle_softirqs+0xa0/0x248 (P)
> [ 463.888175] __do_softirq+0x14/0x20
> [ 463.888178] ____do_softirq+0x10/0x1c
> [ 463.888183] call_on_irq_stack+0x24/0x4c
> [ 463.888185] do_softirq_own_stack+0x1c/0x2c
> [ 463.888187] __irq_exit_rcu+0xd8/0x110
> [ 463.888192] irq_exit_rcu+0x10/0x1c
> [ 463.888194] el1_interrupt+0x38/0x68
> [ 463.888198] el1h_64_irq_handler+0x18/0x24
> [ 463.888200] el1h_64_irq+0x6c/0x70
> [ 463.888202] finish_task_switch.isra.0+0x74/0x220 (P)
> [ 463.888207] __schedule+0x2fc/0x998
> [ 463.888210] schedule_idle+0x28/0x48
> [ 463.888212] do_idle+0x170/0x268
> [ 463.888215] cpu_startup_entry+0x34/0x3c
> [ 463.888217] secondary_start_kernel+0x138/0x158
> [ 463.888224] __secondary_switched+0xc0/0xc4
> [ 463.941174] NMI backtrace for cpu 8
> [ 463.941179] CPU: 8 UID: 0 PID: 19 Comm: rcu_exp_gp_kthr Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> [ 463.941220] Hardware name: linux,dummy-virt (DT)
> [ 463.941222] pstate: 23400005 (nzCv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> [ 463.941223] pc : smp_call_function_single+0xe4/0x1b0
> [ 463.941292] lr : __sync_rcu_exp_select_node_cpus+0x224/0x3c8
> [ 463.941366] sp : ffff800080233cd0
> [ 463.941367] x29: ffff800080233d20 x28: 0000000000000002 x27: ffff000003d9c600
> [ 463.941370] x26: ffffafb5b032a880 x25: ffff00001d4d7ac0 x24: ffffafb5adb49e24
> [ 463.941372] x23: 0000000000001fff x22: ffffafb5af9f5ac0 x21: ffffafb5b029ea08
> [ 463.941374] x20: 0000000000000000 x19: ffff800080233ce0 x18: 0000000000000001
> [ 463.941376] x17: ffff504a6d88c000 x16: ffff800080040000 x15: 0000000000000000
> [ 463.941378] x14: 0000000000000115 x13: 0000000000000115 x12: 0000000000000000
> [ 463.941380] x11: ffffafb5af9f0408 x10: 0000000000000001 x9 : ffff000003d9c600
> [ 463.941462] x8 : 0000000000000040 x7 : ffffafb5b0322ab0 x6 : ffffafb5adb49e24
> [ 463.941464] x5 : 0000000000000000 x4 : ffff00001d281f08 x3 : 0000000000000001
> [ 463.941535] x2 : 0000000000000000 x1 : ffff00001d281f00 x0 : 000000000000001f
> [ 463.941537] Call trace:
> [ 463.941538] smp_call_function_single+0xe4/0x1b0 (P)
> [ 463.941541] __sync_rcu_exp_select_node_cpus+0x224/0x3c8
> [ 463.941619] sync_rcu_exp_select_cpus+0x138/0x2a4
> [ 463.941622] wait_rcu_exp_gp+0x18/0x30
> [ 463.941644] kthread_worker_fn+0xcc/0x184
> [ 463.941708] kthread+0x134/0x208
> [ 463.941709] ret_from_fork+0x10/0x20
I wish the back trace also included which CPU the smp_call_function_single is
waiting on. This is similar to what Boqun sees as well, where we are spinning on
csd lock for a CPU that is wedged. In this case, the 'wedged' appears to be on
level-1 rcu_node (CPUs 30-42) ? But we don't have those backtraces in the above
to confirm which specific one.
Al though, cpu 8 looks like it could itself be the one blocking the GP as a
secondary effect of the smp_call IPI not coming through?
Speaking of smp_call, may be it does make sense for EXP to not wait too long for
csd lock thus to not make dire matters worse? After all, the GP may well
complete eventually even without the IPI executing? Perhaps even sooner if the
CPU doing the smp_call wait does some other useful work as well.
> At first glance, this looks like a stop_machine() request gone bad.
> Please note that I am seeing this on most TREE01 runs and nowhere else.
> So this might be a strange side effect of dynamic callback offloading,
> but perhaps more likely due to TREE01 using more CPUs than it is allowing
> for, that is, telling qemu "-smp 43", the kernel "maxcpus=8 nr_cpus=43",
> but forcing the guest OS to run on only eight CPUs. (Why??? Well,
> back in the day, there was an RCU bug exposed by this.)
>
> All that aside, this is one of the more spectacular RCU CPU stall warnings
> I have ever seen, and that is with me leaving off the NMI stack traces
> for most of the CPUs. ;-)
IIRC, NMI stack tracing on ARM is unreliable due to raisins.
>
> If there is interest, I could post a tarball of a few of the full
> console logs.
>
> Come to think of it, even if there isn't interest, here you go! ;-)
>
> https://drive.google.com/file/d/1JKmCYqK6kAwhlJZUJQeTle-o62aJXkUQ/view?usp=sharing
TREE01 in this trace seems to be a different splat I think:
[ 71.612482] rcu: Offline CPU 1 blocking current GP.
Causing the stall I think. Something to do with hotplug? I wonder if without
hotplug testing, it will trigger or not with the same CPU count settings. It may
be worth adding the ARM folks as well.
- Joel
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [BUG] RCU CPU stall warnings on TREE01 on arm64
2025-05-06 14:09 ` Joel Fernandes
@ 2025-05-06 18:03 ` Paul E. McKenney
2025-05-06 18:21 ` Paul E. McKenney
0 siblings, 1 reply; 7+ messages in thread
From: Paul E. McKenney @ 2025-05-06 18:03 UTC (permalink / raw)
To: Joel Fernandes; +Cc: rcu
On Tue, May 06, 2025 at 10:09:54AM -0400, Joel Fernandes wrote:
>
>
> On 5/5/2025 3:03 PM, Paul E. McKenney wrote:
> > Hello!
> >
> > Following up on off-list discussions and requests for more information.
> >
> > These reproduce reasonably easily, and here is an example:
> >
> > ------------------------------------------------------------------------
> > [ 426.022056] rcu: NOCB: Cannot CB-offload online CPU 25
> > [ 460.867350] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > [ 460.867980] rcu: 0-...!: (1 GPs behind) idle=8fe4/1/0x4000000000000000 softirq=2124/2125 fqs=0
> > [ 460.868726] rcu: 1-...!: (1 GPs behind) idle=e0ac/1/0x4000000000000000 softirq=3547/3547 fqs=0
> > [ 460.869468] rcu: 5-...!: (1 GPs behind) idle=5c34/1/0x4000000000000000 softirq=2084/2084 fqs=0
> > [ 460.870233] rcu: 8-...!: (1 GPs behind) idle=9fdc/1/0x4000000000000000 softirq=4301/4301 fqs=0
> > [ 460.871007] rcu: 9-...!: (0 ticks this GP) idle=4a2c/1/0x4000000000000000 softirq=3873/3873 fqs=0
> > [ 460.871772] rcu: 10-...!: (1 GPs behind) idle=4994/1/0x4000000000000000 softirq=4760/4760 fqs=0
> > [ 460.872511] rcu: 12-...!: (1 GPs behind) idle=0bbc/1/0x4000000000000000 softirq=3545/3545 fqs=0
> > [ 460.873300] rcu: 13-...!: (1 GPs behind) idle=a59c/1/0x4000000000000000 softirq=2097/2098 fqs=0
> > [ 460.874084] rcu: 14-...!: (1 GPs behind) idle=22cc/1/0x4000000000000000 softirq=4424/4424 fqs=0
> > [ 460.874864] rcu: 15-...!: (1 GPs behind) idle=0e5c/1/0x4000000000000000 softirq=5984/5984 fqs=0
> > [ 460.875625] rcu: 16-...!: (1 GPs behind) idle=d5bc/1/0x4000000000000000 softirq=6313/6313 fqs=0
> > [ 460.876374] rcu: 17-...!: (1 GPs behind) idle=848c/1/0x4000000000000000 softirq=4160/4160 fqs=0
> > [ 460.877182] rcu: 18-...!: (1 GPs behind) idle=a1c4/1/0x4000000000000000 softirq=3217/3217 fqs=0
> > [ 460.877930] rcu: 19-...!: (0 ticks this GP) idle=cbe4/1/0x4000000000000000 softirq=7886/7886 fqs=0
> > [ 460.878772] rcu: 20-...!: (1 GPs behind) idle=3acc/1/0x4000000000000000 softirq=4315/4317 fqs=0
> > [ 460.879514] rcu: 21-...!: (1 GPs behind) idle=eb7c/1/0x4000000000000000 softirq=4221/4221 fqs=0
> > [ 460.880225] rcu: 22-...!: (1 GPs behind) idle=477c/1/0x4000000000000000 softirq=5049/5049 fqs=0
> > [ 460.880990] rcu: 23-...!: (1 GPs behind) idle=8404/1/0x4000000000000000 softirq=5635/5636 fqs=0
> > [ 460.881739] rcu: 24-...!: (0 ticks this GP) idle=11e4/1/0x4000000000000000 softirq=2031/2031 fqs=0
> > [ 460.882497] rcu: 25-...!: (0 ticks this GP) idle=3434/1/0x4000000000000000 softirq=3495/3495 fqs=0
> > [ 460.883296] rcu: 26-...!: (1 GPs behind) idle=f864/1/0x4000000000000000 softirq=3645/3645 fqs=0
> > [ 460.884054] rcu: 27-...!: (0 ticks this GP) idle=3e74/1/0x4000000000000000 softirq=4168/4168 fqs=0
> > [ 460.884805] rcu: 28-...!: (1 GPs behind) idle=71a4/1/0x4000000000000000 softirq=3596/3596 fqs=0
> > [ 460.885570] rcu: 29-...!: (1 GPs behind) idle=9aa4/1/0x4000000000000000 softirq=3111/3112 fqs=0
> > [ 460.886276] rcu: 30-...!: (1 GPs behind) idle=10dc/1/0x4000000000000000 softirq=3030/3030 fqs=0
> > [ 460.887030] rcu: 31-...!: (0 ticks this GP) idle=0fb4/1/0x4000000000000000 softirq=3540/3540 fqs=0
> > [ 460.887777] rcu: 32-...!: (1 GPs behind) idle=fad4/1/0x4000000000000000 softirq=2645/2645 fqs=0
> > [ 460.888548] rcu: 33-...!: (0 ticks this GP) idle=37ac/1/0x4000000000000000 softirq=2201/2201 fqs=0
> > [ 460.889336] rcu: 34-...!: (1 GPs behind) idle=85ac/1/0x4000000000000000 softirq=2336/2336 fqs=0
> > [ 460.890081] rcu: 35-...!: (1 GPs behind) idle=756c/1/0x4000000000000000 softirq=1534/1536 fqs=0
> > [ 460.890820] rcu: 36-...!: (0 ticks this GP) idle=b2ec/1/0x4000000000000000 softirq=4286/4286 fqs=0
> > [ 460.891572] rcu: 37-...!: (1 GPs behind) idle=de1c/1/0x4000000000000000 softirq=2725/2725 fqs=0
> > [ 460.892323] rcu: 38-...!: (1 GPs behind) idle=c62c/1/0x4000000000000000 softirq=2341/2342 fqs=0
> > [ 460.893096] rcu: 39-...!: (1 GPs behind) idle=be2c/1/0x4000000000000000 softirq=2650/2651 fqs=0
> > [ 460.893830] rcu: 40-...!: (1 GPs behind) idle=7ecc/1/0x4000000000000000 softirq=2119/2121 fqs=0
> > [ 460.894621] rcu: 41-...!: (0 ticks this GP) idle=19dc/1/0x4000000000000000 softirq=3539/3539 fqs=0
> > [ 460.895384] rcu: 42-...!: (0 ticks this GP) idle=a74c/1/0x4000000000000000 softirq=2259/2259 fqs=0
> > [ 460.896148] rcu: Tasks blocked on level-1 rcu_node (CPUs 30-42): P91/1:b..l
> > [ 460.896778] rcu: (detected by 11, t=7962 jiffies, g=15565, q=48 ncpus=39)
> > [ 460.897395] Sending NMI from CPU 11 to CPUs 0:
> > [ 461.047304] rcu-torture: rtc: 00000000fb6bc815 ver: 2137 tfle: 0 rta: 2137 rtaf: 0 rtf: 2128 rtmbe: 0 rtmbkf: 0/2042 rtbe: 0 rtbke: 0 rtbf: 0 rtb: 0 nt: 148999 onoff: 32/32:36/37 7,348:36,3639 4096:26899 (HZ=250) barrier: 979/980:0 read-exits: 416 nocb-toggles: 1013:969 gpwraps: 0
> > [ 461.047343] rcu-torture: Reader Pipe: 1919541609 11501 0 0 0 0 0 0 0 0 0
> > [ 461.047383] rcu-torture: Reader Batch: 1919533823 19422 0 0 0 0 0 0 0 0 0
> > [ 461.047401] rcu-torture: Free-Block Circulation: 2136 2136 2135 2134 2133 2132 2131 2130 2129 2128 0
> > [ 462.777371] NMI backtrace for cpu 0
> > [ 462.777547] CPU: 0 UID: 0 PID: 20 Comm: migration/0 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> > [ 462.777551] Hardware name: linux,dummy-virt (DT)
> > [ 462.777552] Stopper: multi_cpu_stop+0x0/0x15c <- __stop_cpus.constprop.0+0x78/0xc4
> > [ 462.777564] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> > [ 462.777566] pc : handle_softirqs+0xa0/0x248
> > [ 462.777836] lr : handle_softirqs+0x7c/0x248
> > [ 462.777838] sp : ffff800080003f50
> > [ 462.777839] x29: ffff800080003f50 x28: ffff000003d9d780 x27: 0000000000000000
> > [ 462.777842] x26: 0000000000000282 x25: 0000000000000000 x24: ffffafb5af9f4000
> > [ 462.777843] x23: 0000000063400005 x22: ffffafb5adb9b8f0 x21: ffffafb5af9e93c8
> > [ 462.778009] x20: ffffafb5b02970c0 x19: ffff000003d9d780 x18: 0000000000000001
> > [ 462.778012] x17: ffff504a6d7bc000 x16: ffff800080000000 x15: ffff00001d5f4d00
> > [ 462.778013] x14: 0000000000000156 x13: 0000000000000000 x12: 0000000000000000
> > [ 462.778015] x11: ffff00001d1b0d80 x10: 00000000002ab980 x9 : 0000000000000000
> > [ 462.778017] x8 : 000001d6146032ba x7 : ffff00000500b800 x6 : 0000000000000000
> > [ 462.778019] x5 : 00000000002ab980 x4 : 0000000100009e3e x3 : ffff504a6d7bc000
> > [ 462.778020] x2 : 0000006bbfae36c0 x1 : ffff504a6d7bc000 x0 : ffffafb5af9f4000
> > [ 462.778232] Call trace:
> > [ 462.778233] handle_softirqs+0xa0/0x248 (P)
> > [ 462.778296] __do_softirq+0x14/0x20
> > [ 462.778299] ____do_softirq+0x10/0x1c
> > [ 462.778389] call_on_irq_stack+0x24/0x4c
> > [ 462.778391] do_softirq_own_stack+0x1c/0x2c
> > [ 462.778393] __irq_exit_rcu+0xd8/0x110
> > [ 462.778395] irq_exit_rcu+0x10/0x1c
> > [ 462.778456] el1_interrupt+0x38/0x68
> > [ 462.778531] el1h_64_irq_handler+0x18/0x24
> > [ 462.778533] el1h_64_irq+0x6c/0x70
> > [ 462.778534] multi_cpu_stop+0xf0/0x15c (P)
> > [ 462.778536] cpu_stopper_thread+0x8c/0x11c
> > [ 462.778642] smpboot_thread_fn+0x220/0x24c
> > [ 462.778647] kthread+0x134/0x208
> > [ 462.778649] ret_from_fork+0x10/0x20
> > [ 463.888107] NMI backtrace for cpu 1
> > [ 463.888117] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> > [ 463.888120] Hardware name: linux,dummy-virt (DT)
> > [ 463.888121] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> > [ 463.888123] pc : handle_softirqs+0xa0/0x248
> > [ 463.888135] lr : handle_softirqs+0x7c/0x248
> > [ 463.888140] sp : ffff80008000bf50
> > [ 463.888140] x29: ffff80008000bf50 x28: ffff000003d9e900 x27: 0000000000000000
> > [ 463.888143] x26: 0000000000000282 x25: ffff000003d9e900 x24: ffffafb5af9f4000
> > [ 463.888146] x23: 0000000063400005 x22: ffffafb5adad9114 x21: ffffafb5af9e93c8
> > [ 463.888148] x20: ffffafb5b02970c0 x19: ffff000003d9e900 x18: 0000000000000000
> > [ 463.888150] x17: ffff504a6d7d6000 x16: ffff800080008000 x15: ffff00001d1cad00
> > [ 463.888152] x14: 0000000000000112 x13: 0000000000000000 x12: 0000000000000000
> > [ 463.888158] x11: 0000000000000a95 x10: 0000000000000163 x9 : 0000000000000000
> > [ 463.888160] x8 : 0000006bfc655500 x7 : 7fffffffffffffff x6 : 0000006bfc655500
> > [ 463.888165] x5 : 0000006bfca25e00 x4 : 0000000100009ff5 x3 : ffff504a6d7d6000
> > [ 463.888168] x2 : 0000006c01e2bea0 x1 : ffff504a6d7d6000 x0 : ffffafb5af9f4000
> > [ 463.888171] Call trace:
> > [ 463.888172] handle_softirqs+0xa0/0x248 (P)
> > [ 463.888175] __do_softirq+0x14/0x20
> > [ 463.888178] ____do_softirq+0x10/0x1c
> > [ 463.888183] call_on_irq_stack+0x24/0x4c
> > [ 463.888185] do_softirq_own_stack+0x1c/0x2c
> > [ 463.888187] __irq_exit_rcu+0xd8/0x110
> > [ 463.888192] irq_exit_rcu+0x10/0x1c
> > [ 463.888194] el1_interrupt+0x38/0x68
> > [ 463.888198] el1h_64_irq_handler+0x18/0x24
> > [ 463.888200] el1h_64_irq+0x6c/0x70
> > [ 463.888202] finish_task_switch.isra.0+0x74/0x220 (P)
> > [ 463.888207] __schedule+0x2fc/0x998
> > [ 463.888210] schedule_idle+0x28/0x48
> > [ 463.888212] do_idle+0x170/0x268
> > [ 463.888215] cpu_startup_entry+0x34/0x3c
> > [ 463.888217] secondary_start_kernel+0x138/0x158
> > [ 463.888224] __secondary_switched+0xc0/0xc4
> > [ 463.941174] NMI backtrace for cpu 8
> > [ 463.941179] CPU: 8 UID: 0 PID: 19 Comm: rcu_exp_gp_kthr Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> > [ 463.941220] Hardware name: linux,dummy-virt (DT)
> > [ 463.941222] pstate: 23400005 (nzCv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> > [ 463.941223] pc : smp_call_function_single+0xe4/0x1b0
> > [ 463.941292] lr : __sync_rcu_exp_select_node_cpus+0x224/0x3c8
> > [ 463.941366] sp : ffff800080233cd0
> > [ 463.941367] x29: ffff800080233d20 x28: 0000000000000002 x27: ffff000003d9c600
> > [ 463.941370] x26: ffffafb5b032a880 x25: ffff00001d4d7ac0 x24: ffffafb5adb49e24
> > [ 463.941372] x23: 0000000000001fff x22: ffffafb5af9f5ac0 x21: ffffafb5b029ea08
> > [ 463.941374] x20: 0000000000000000 x19: ffff800080233ce0 x18: 0000000000000001
> > [ 463.941376] x17: ffff504a6d88c000 x16: ffff800080040000 x15: 0000000000000000
> > [ 463.941378] x14: 0000000000000115 x13: 0000000000000115 x12: 0000000000000000
> > [ 463.941380] x11: ffffafb5af9f0408 x10: 0000000000000001 x9 : ffff000003d9c600
> > [ 463.941462] x8 : 0000000000000040 x7 : ffffafb5b0322ab0 x6 : ffffafb5adb49e24
> > [ 463.941464] x5 : 0000000000000000 x4 : ffff00001d281f08 x3 : 0000000000000001
> > [ 463.941535] x2 : 0000000000000000 x1 : ffff00001d281f00 x0 : 000000000000001f
> > [ 463.941537] Call trace:
> > [ 463.941538] smp_call_function_single+0xe4/0x1b0 (P)
> > [ 463.941541] __sync_rcu_exp_select_node_cpus+0x224/0x3c8
> > [ 463.941619] sync_rcu_exp_select_cpus+0x138/0x2a4
> > [ 463.941622] wait_rcu_exp_gp+0x18/0x30
> > [ 463.941644] kthread_worker_fn+0xcc/0x184
> > [ 463.941708] kthread+0x134/0x208
> > [ 463.941709] ret_from_fork+0x10/0x20
>
> I wish the back trace also included which CPU the smp_call_function_single is
> waiting on. This is similar to what Boqun sees as well, where we are spinning on
> csd lock for a CPU that is wedged. In this case, the 'wedged' appears to be on
> level-1 rcu_node (CPUs 30-42) ? But we don't have those backtraces in the above
> to confirm which specific one.
The way to make that happen is via the CSD_LOCK_WAIT_DEBUG and the
CSD_LOCK_WAIT_DEBUG_DEFAULT Kconfig options.
> Al though, cpu 8 looks like it could itself be the one blocking the GP as a
> secondary effect of the smp_call IPI not coming through?
What caught my eye was this: "Stopper: multi_cpu_stop+0x0/0x15c".
This puppy makes all the CPUs spin with interrupts disabled. It looks
like it was running while something was blocking context switches on
at least some of the CPUs. It is a most wonderful way to amplify any
delay on any CPUs to affect all CPUs. ;-)
> Speaking of smp_call, may be it does make sense for EXP to not wait too long for
> csd lock thus to not make dire matters worse? After all, the GP may well
> complete eventually even without the IPI executing? Perhaps even sooner if the
> CPU doing the smp_call wait does some other useful work as well.
What does the RCU expedited grace period do instead of waiting?
I could imagine an smp_call_function_single() API that did exponential
backoff, spinning for a bit, sleeping, spinning for a bit, sleeping
for longer and so on. Or did you have something else in mind?
> > At first glance, this looks like a stop_machine() request gone bad.
> > Please note that I am seeing this on most TREE01 runs and nowhere else.
> > So this might be a strange side effect of dynamic callback offloading,
> > but perhaps more likely due to TREE01 using more CPUs than it is allowing
> > for, that is, telling qemu "-smp 43", the kernel "maxcpus=8 nr_cpus=43",
> > but forcing the guest OS to run on only eight CPUs. (Why??? Well,
> > back in the day, there was an RCU bug exposed by this.)
> >
> > All that aside, this is one of the more spectacular RCU CPU stall warnings
> > I have ever seen, and that is with me leaving off the NMI stack traces
> > for most of the CPUs. ;-)
>
> IIRC, NMI stack tracing on ARM is unreliable due to raisins.
Ah, true, older ARM hardware lacks NMIs.
> > If there is interest, I could post a tarball of a few of the full
> > console logs.
> >
> > Come to think of it, even if there isn't interest, here you go! ;-)
> >
> > https://drive.google.com/file/d/1JKmCYqK6kAwhlJZUJQeTle-o62aJXkUQ/view?usp=sharing
>
> TREE01 in this trace seems to be a different splat I think:
>
> [ 71.612482] rcu: Offline CPU 1 blocking current GP.
>
> Causing the stall I think. Something to do with hotplug? I wonder if without
> hotplug testing, it will trigger or not with the same CPU count settings. It may
> be worth adding the ARM folks as well.
I could try going back to the overload case and disabling CPU hotplug.
But the problem seems to be that ARM is taking the extra 35 CPUs much
more seriously than does x86, which could cause trouble given that the
rcutorture scripting is jamming all 43 of them onto eight real CPUs.
The strange thing if that they are online as far as the (de)offloading
tests are concerned, but they show no sign of ever having been brought
online.
No, I take it back, they were brought online, it is just that ARM's CPU
ID space is way different than I would expect: 0x1, 0x2, 0x3, ..., 0xe,
0xf, 0x100, 0x101, ...
With then change to TREE01, there are only ever eight of them.
Either way, the next step seems to be to remove the "CONFIG_NR_CPUS=8"
to see what happens.
Plus for TREE07, arm64 does not enable CONFIG_PREEMPT_LAZY, resulting
in rcutorture complaining about a .config error. Not sure whether it
would be easier to enable CONFIG_PREEMPT_LAZY or to make rcutorture be
able to go either way. ;-)
Thanx, Paul
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [BUG] RCU CPU stall warnings on TREE01 on arm64
2025-05-06 18:03 ` Paul E. McKenney
@ 2025-05-06 18:21 ` Paul E. McKenney
2025-05-06 19:10 ` Joel Fernandes
0 siblings, 1 reply; 7+ messages in thread
From: Paul E. McKenney @ 2025-05-06 18:21 UTC (permalink / raw)
To: Joel Fernandes; +Cc: rcu
On Tue, May 06, 2025 at 11:03:40AM -0700, Paul E. McKenney wrote:
> On Tue, May 06, 2025 at 10:09:54AM -0400, Joel Fernandes wrote:
> >
> >
> > On 5/5/2025 3:03 PM, Paul E. McKenney wrote:
> > > Hello!
> > >
> > > Following up on off-list discussions and requests for more information.
> > >
> > > These reproduce reasonably easily, and here is an example:
> > >
> > > ------------------------------------------------------------------------
> > > [ 426.022056] rcu: NOCB: Cannot CB-offload online CPU 25
> > > [ 460.867350] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > > [ 460.867980] rcu: 0-...!: (1 GPs behind) idle=8fe4/1/0x4000000000000000 softirq=2124/2125 fqs=0
> > > [ 460.868726] rcu: 1-...!: (1 GPs behind) idle=e0ac/1/0x4000000000000000 softirq=3547/3547 fqs=0
> > > [ 460.869468] rcu: 5-...!: (1 GPs behind) idle=5c34/1/0x4000000000000000 softirq=2084/2084 fqs=0
> > > [ 460.870233] rcu: 8-...!: (1 GPs behind) idle=9fdc/1/0x4000000000000000 softirq=4301/4301 fqs=0
> > > [ 460.871007] rcu: 9-...!: (0 ticks this GP) idle=4a2c/1/0x4000000000000000 softirq=3873/3873 fqs=0
> > > [ 460.871772] rcu: 10-...!: (1 GPs behind) idle=4994/1/0x4000000000000000 softirq=4760/4760 fqs=0
> > > [ 460.872511] rcu: 12-...!: (1 GPs behind) idle=0bbc/1/0x4000000000000000 softirq=3545/3545 fqs=0
> > > [ 460.873300] rcu: 13-...!: (1 GPs behind) idle=a59c/1/0x4000000000000000 softirq=2097/2098 fqs=0
> > > [ 460.874084] rcu: 14-...!: (1 GPs behind) idle=22cc/1/0x4000000000000000 softirq=4424/4424 fqs=0
> > > [ 460.874864] rcu: 15-...!: (1 GPs behind) idle=0e5c/1/0x4000000000000000 softirq=5984/5984 fqs=0
> > > [ 460.875625] rcu: 16-...!: (1 GPs behind) idle=d5bc/1/0x4000000000000000 softirq=6313/6313 fqs=0
> > > [ 460.876374] rcu: 17-...!: (1 GPs behind) idle=848c/1/0x4000000000000000 softirq=4160/4160 fqs=0
> > > [ 460.877182] rcu: 18-...!: (1 GPs behind) idle=a1c4/1/0x4000000000000000 softirq=3217/3217 fqs=0
> > > [ 460.877930] rcu: 19-...!: (0 ticks this GP) idle=cbe4/1/0x4000000000000000 softirq=7886/7886 fqs=0
> > > [ 460.878772] rcu: 20-...!: (1 GPs behind) idle=3acc/1/0x4000000000000000 softirq=4315/4317 fqs=0
> > > [ 460.879514] rcu: 21-...!: (1 GPs behind) idle=eb7c/1/0x4000000000000000 softirq=4221/4221 fqs=0
> > > [ 460.880225] rcu: 22-...!: (1 GPs behind) idle=477c/1/0x4000000000000000 softirq=5049/5049 fqs=0
> > > [ 460.880990] rcu: 23-...!: (1 GPs behind) idle=8404/1/0x4000000000000000 softirq=5635/5636 fqs=0
> > > [ 460.881739] rcu: 24-...!: (0 ticks this GP) idle=11e4/1/0x4000000000000000 softirq=2031/2031 fqs=0
> > > [ 460.882497] rcu: 25-...!: (0 ticks this GP) idle=3434/1/0x4000000000000000 softirq=3495/3495 fqs=0
> > > [ 460.883296] rcu: 26-...!: (1 GPs behind) idle=f864/1/0x4000000000000000 softirq=3645/3645 fqs=0
> > > [ 460.884054] rcu: 27-...!: (0 ticks this GP) idle=3e74/1/0x4000000000000000 softirq=4168/4168 fqs=0
> > > [ 460.884805] rcu: 28-...!: (1 GPs behind) idle=71a4/1/0x4000000000000000 softirq=3596/3596 fqs=0
> > > [ 460.885570] rcu: 29-...!: (1 GPs behind) idle=9aa4/1/0x4000000000000000 softirq=3111/3112 fqs=0
> > > [ 460.886276] rcu: 30-...!: (1 GPs behind) idle=10dc/1/0x4000000000000000 softirq=3030/3030 fqs=0
> > > [ 460.887030] rcu: 31-...!: (0 ticks this GP) idle=0fb4/1/0x4000000000000000 softirq=3540/3540 fqs=0
> > > [ 460.887777] rcu: 32-...!: (1 GPs behind) idle=fad4/1/0x4000000000000000 softirq=2645/2645 fqs=0
> > > [ 460.888548] rcu: 33-...!: (0 ticks this GP) idle=37ac/1/0x4000000000000000 softirq=2201/2201 fqs=0
> > > [ 460.889336] rcu: 34-...!: (1 GPs behind) idle=85ac/1/0x4000000000000000 softirq=2336/2336 fqs=0
> > > [ 460.890081] rcu: 35-...!: (1 GPs behind) idle=756c/1/0x4000000000000000 softirq=1534/1536 fqs=0
> > > [ 460.890820] rcu: 36-...!: (0 ticks this GP) idle=b2ec/1/0x4000000000000000 softirq=4286/4286 fqs=0
> > > [ 460.891572] rcu: 37-...!: (1 GPs behind) idle=de1c/1/0x4000000000000000 softirq=2725/2725 fqs=0
> > > [ 460.892323] rcu: 38-...!: (1 GPs behind) idle=c62c/1/0x4000000000000000 softirq=2341/2342 fqs=0
> > > [ 460.893096] rcu: 39-...!: (1 GPs behind) idle=be2c/1/0x4000000000000000 softirq=2650/2651 fqs=0
> > > [ 460.893830] rcu: 40-...!: (1 GPs behind) idle=7ecc/1/0x4000000000000000 softirq=2119/2121 fqs=0
> > > [ 460.894621] rcu: 41-...!: (0 ticks this GP) idle=19dc/1/0x4000000000000000 softirq=3539/3539 fqs=0
> > > [ 460.895384] rcu: 42-...!: (0 ticks this GP) idle=a74c/1/0x4000000000000000 softirq=2259/2259 fqs=0
> > > [ 460.896148] rcu: Tasks blocked on level-1 rcu_node (CPUs 30-42): P91/1:b..l
> > > [ 460.896778] rcu: (detected by 11, t=7962 jiffies, g=15565, q=48 ncpus=39)
> > > [ 460.897395] Sending NMI from CPU 11 to CPUs 0:
> > > [ 461.047304] rcu-torture: rtc: 00000000fb6bc815 ver: 2137 tfle: 0 rta: 2137 rtaf: 0 rtf: 2128 rtmbe: 0 rtmbkf: 0/2042 rtbe: 0 rtbke: 0 rtbf: 0 rtb: 0 nt: 148999 onoff: 32/32:36/37 7,348:36,3639 4096:26899 (HZ=250) barrier: 979/980:0 read-exits: 416 nocb-toggles: 1013:969 gpwraps: 0
> > > [ 461.047343] rcu-torture: Reader Pipe: 1919541609 11501 0 0 0 0 0 0 0 0 0
> > > [ 461.047383] rcu-torture: Reader Batch: 1919533823 19422 0 0 0 0 0 0 0 0 0
> > > [ 461.047401] rcu-torture: Free-Block Circulation: 2136 2136 2135 2134 2133 2132 2131 2130 2129 2128 0
> > > [ 462.777371] NMI backtrace for cpu 0
> > > [ 462.777547] CPU: 0 UID: 0 PID: 20 Comm: migration/0 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> > > [ 462.777551] Hardware name: linux,dummy-virt (DT)
> > > [ 462.777552] Stopper: multi_cpu_stop+0x0/0x15c <- __stop_cpus.constprop.0+0x78/0xc4
> > > [ 462.777564] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> > > [ 462.777566] pc : handle_softirqs+0xa0/0x248
> > > [ 462.777836] lr : handle_softirqs+0x7c/0x248
> > > [ 462.777838] sp : ffff800080003f50
> > > [ 462.777839] x29: ffff800080003f50 x28: ffff000003d9d780 x27: 0000000000000000
> > > [ 462.777842] x26: 0000000000000282 x25: 0000000000000000 x24: ffffafb5af9f4000
> > > [ 462.777843] x23: 0000000063400005 x22: ffffafb5adb9b8f0 x21: ffffafb5af9e93c8
> > > [ 462.778009] x20: ffffafb5b02970c0 x19: ffff000003d9d780 x18: 0000000000000001
> > > [ 462.778012] x17: ffff504a6d7bc000 x16: ffff800080000000 x15: ffff00001d5f4d00
> > > [ 462.778013] x14: 0000000000000156 x13: 0000000000000000 x12: 0000000000000000
> > > [ 462.778015] x11: ffff00001d1b0d80 x10: 00000000002ab980 x9 : 0000000000000000
> > > [ 462.778017] x8 : 000001d6146032ba x7 : ffff00000500b800 x6 : 0000000000000000
> > > [ 462.778019] x5 : 00000000002ab980 x4 : 0000000100009e3e x3 : ffff504a6d7bc000
> > > [ 462.778020] x2 : 0000006bbfae36c0 x1 : ffff504a6d7bc000 x0 : ffffafb5af9f4000
> > > [ 462.778232] Call trace:
> > > [ 462.778233] handle_softirqs+0xa0/0x248 (P)
> > > [ 462.778296] __do_softirq+0x14/0x20
> > > [ 462.778299] ____do_softirq+0x10/0x1c
> > > [ 462.778389] call_on_irq_stack+0x24/0x4c
> > > [ 462.778391] do_softirq_own_stack+0x1c/0x2c
> > > [ 462.778393] __irq_exit_rcu+0xd8/0x110
> > > [ 462.778395] irq_exit_rcu+0x10/0x1c
> > > [ 462.778456] el1_interrupt+0x38/0x68
> > > [ 462.778531] el1h_64_irq_handler+0x18/0x24
> > > [ 462.778533] el1h_64_irq+0x6c/0x70
> > > [ 462.778534] multi_cpu_stop+0xf0/0x15c (P)
> > > [ 462.778536] cpu_stopper_thread+0x8c/0x11c
> > > [ 462.778642] smpboot_thread_fn+0x220/0x24c
> > > [ 462.778647] kthread+0x134/0x208
> > > [ 462.778649] ret_from_fork+0x10/0x20
> > > [ 463.888107] NMI backtrace for cpu 1
> > > [ 463.888117] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> > > [ 463.888120] Hardware name: linux,dummy-virt (DT)
> > > [ 463.888121] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> > > [ 463.888123] pc : handle_softirqs+0xa0/0x248
> > > [ 463.888135] lr : handle_softirqs+0x7c/0x248
> > > [ 463.888140] sp : ffff80008000bf50
> > > [ 463.888140] x29: ffff80008000bf50 x28: ffff000003d9e900 x27: 0000000000000000
> > > [ 463.888143] x26: 0000000000000282 x25: ffff000003d9e900 x24: ffffafb5af9f4000
> > > [ 463.888146] x23: 0000000063400005 x22: ffffafb5adad9114 x21: ffffafb5af9e93c8
> > > [ 463.888148] x20: ffffafb5b02970c0 x19: ffff000003d9e900 x18: 0000000000000000
> > > [ 463.888150] x17: ffff504a6d7d6000 x16: ffff800080008000 x15: ffff00001d1cad00
> > > [ 463.888152] x14: 0000000000000112 x13: 0000000000000000 x12: 0000000000000000
> > > [ 463.888158] x11: 0000000000000a95 x10: 0000000000000163 x9 : 0000000000000000
> > > [ 463.888160] x8 : 0000006bfc655500 x7 : 7fffffffffffffff x6 : 0000006bfc655500
> > > [ 463.888165] x5 : 0000006bfca25e00 x4 : 0000000100009ff5 x3 : ffff504a6d7d6000
> > > [ 463.888168] x2 : 0000006c01e2bea0 x1 : ffff504a6d7d6000 x0 : ffffafb5af9f4000
> > > [ 463.888171] Call trace:
> > > [ 463.888172] handle_softirqs+0xa0/0x248 (P)
> > > [ 463.888175] __do_softirq+0x14/0x20
> > > [ 463.888178] ____do_softirq+0x10/0x1c
> > > [ 463.888183] call_on_irq_stack+0x24/0x4c
> > > [ 463.888185] do_softirq_own_stack+0x1c/0x2c
> > > [ 463.888187] __irq_exit_rcu+0xd8/0x110
> > > [ 463.888192] irq_exit_rcu+0x10/0x1c
> > > [ 463.888194] el1_interrupt+0x38/0x68
> > > [ 463.888198] el1h_64_irq_handler+0x18/0x24
> > > [ 463.888200] el1h_64_irq+0x6c/0x70
> > > [ 463.888202] finish_task_switch.isra.0+0x74/0x220 (P)
> > > [ 463.888207] __schedule+0x2fc/0x998
> > > [ 463.888210] schedule_idle+0x28/0x48
> > > [ 463.888212] do_idle+0x170/0x268
> > > [ 463.888215] cpu_startup_entry+0x34/0x3c
> > > [ 463.888217] secondary_start_kernel+0x138/0x158
> > > [ 463.888224] __secondary_switched+0xc0/0xc4
> > > [ 463.941174] NMI backtrace for cpu 8
> > > [ 463.941179] CPU: 8 UID: 0 PID: 19 Comm: rcu_exp_gp_kthr Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
> > > [ 463.941220] Hardware name: linux,dummy-virt (DT)
> > > [ 463.941222] pstate: 23400005 (nzCv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
> > > [ 463.941223] pc : smp_call_function_single+0xe4/0x1b0
> > > [ 463.941292] lr : __sync_rcu_exp_select_node_cpus+0x224/0x3c8
> > > [ 463.941366] sp : ffff800080233cd0
> > > [ 463.941367] x29: ffff800080233d20 x28: 0000000000000002 x27: ffff000003d9c600
> > > [ 463.941370] x26: ffffafb5b032a880 x25: ffff00001d4d7ac0 x24: ffffafb5adb49e24
> > > [ 463.941372] x23: 0000000000001fff x22: ffffafb5af9f5ac0 x21: ffffafb5b029ea08
> > > [ 463.941374] x20: 0000000000000000 x19: ffff800080233ce0 x18: 0000000000000001
> > > [ 463.941376] x17: ffff504a6d88c000 x16: ffff800080040000 x15: 0000000000000000
> > > [ 463.941378] x14: 0000000000000115 x13: 0000000000000115 x12: 0000000000000000
> > > [ 463.941380] x11: ffffafb5af9f0408 x10: 0000000000000001 x9 : ffff000003d9c600
> > > [ 463.941462] x8 : 0000000000000040 x7 : ffffafb5b0322ab0 x6 : ffffafb5adb49e24
> > > [ 463.941464] x5 : 0000000000000000 x4 : ffff00001d281f08 x3 : 0000000000000001
> > > [ 463.941535] x2 : 0000000000000000 x1 : ffff00001d281f00 x0 : 000000000000001f
> > > [ 463.941537] Call trace:
> > > [ 463.941538] smp_call_function_single+0xe4/0x1b0 (P)
> > > [ 463.941541] __sync_rcu_exp_select_node_cpus+0x224/0x3c8
> > > [ 463.941619] sync_rcu_exp_select_cpus+0x138/0x2a4
> > > [ 463.941622] wait_rcu_exp_gp+0x18/0x30
> > > [ 463.941644] kthread_worker_fn+0xcc/0x184
> > > [ 463.941708] kthread+0x134/0x208
> > > [ 463.941709] ret_from_fork+0x10/0x20
> >
> > I wish the back trace also included which CPU the smp_call_function_single is
> > waiting on. This is similar to what Boqun sees as well, where we are spinning on
> > csd lock for a CPU that is wedged. In this case, the 'wedged' appears to be on
> > level-1 rcu_node (CPUs 30-42) ? But we don't have those backtraces in the above
> > to confirm which specific one.
>
> The way to make that happen is via the CSD_LOCK_WAIT_DEBUG and the
> CSD_LOCK_WAIT_DEBUG_DEFAULT Kconfig options.
>
> > Al though, cpu 8 looks like it could itself be the one blocking the GP as a
> > secondary effect of the smp_call IPI not coming through?
>
> What caught my eye was this: "Stopper: multi_cpu_stop+0x0/0x15c".
>
> This puppy makes all the CPUs spin with interrupts disabled. It looks
> like it was running while something was blocking context switches on
> at least some of the CPUs. It is a most wonderful way to amplify any
> delay on any CPUs to affect all CPUs. ;-)
>
> > Speaking of smp_call, may be it does make sense for EXP to not wait too long for
> > csd lock thus to not make dire matters worse? After all, the GP may well
> > complete eventually even without the IPI executing? Perhaps even sooner if the
> > CPU doing the smp_call wait does some other useful work as well.
>
> What does the RCU expedited grace period do instead of waiting?
>
> I could imagine an smp_call_function_single() API that did exponential
> backoff, spinning for a bit, sleeping, spinning for a bit, sleeping
> for longer and so on. Or did you have something else in mind?
>
> > > At first glance, this looks like a stop_machine() request gone bad.
> > > Please note that I am seeing this on most TREE01 runs and nowhere else.
> > > So this might be a strange side effect of dynamic callback offloading,
> > > but perhaps more likely due to TREE01 using more CPUs than it is allowing
> > > for, that is, telling qemu "-smp 43", the kernel "maxcpus=8 nr_cpus=43",
> > > but forcing the guest OS to run on only eight CPUs. (Why??? Well,
> > > back in the day, there was an RCU bug exposed by this.)
> > >
> > > All that aside, this is one of the more spectacular RCU CPU stall warnings
> > > I have ever seen, and that is with me leaving off the NMI stack traces
> > > for most of the CPUs. ;-)
> >
> > IIRC, NMI stack tracing on ARM is unreliable due to raisins.
>
> Ah, true, older ARM hardware lacks NMIs.
>
> > > If there is interest, I could post a tarball of a few of the full
> > > console logs.
> > >
> > > Come to think of it, even if there isn't interest, here you go! ;-)
> > >
> > > https://drive.google.com/file/d/1JKmCYqK6kAwhlJZUJQeTle-o62aJXkUQ/view?usp=sharing
> >
> > TREE01 in this trace seems to be a different splat I think:
> >
> > [ 71.612482] rcu: Offline CPU 1 blocking current GP.
> >
> > Causing the stall I think. Something to do with hotplug? I wonder if without
> > hotplug testing, it will trigger or not with the same CPU count settings. It may
> > be worth adding the ARM folks as well.
>
> I could try going back to the overload case and disabling CPU hotplug.
> But the problem seems to be that ARM is taking the extra 35 CPUs much
> more seriously than does x86, which could cause trouble given that the
> rcutorture scripting is jamming all 43 of them onto eight real CPUs.
> The strange thing if that they are online as far as the (de)offloading
> tests are concerned, but they show no sign of ever having been brought
> online.
>
> No, I take it back, they were brought online, it is just that ARM's CPU
> ID space is way different than I would expect: 0x1, 0x2, 0x3, ..., 0xe,
> 0xf, 0x100, 0x101, ...
>
> With then change to TREE01, there are only ever eight of them.
>
> Either way, the next step seems to be to remove the "CONFIG_NR_CPUS=8"
> to see what happens.
Which causes all 43 CPUs and the stall warnings to reappear, and with
the stop-machine code again at the scene of the crime. Which is not
at all surprising: 43 vCPUs are trying to spin with interrupts disabled
on only 8 real CPUs, which just is never going to end well.
So this might just be ARM making heavier use of stop-machine than does
x86. Or maybe x86 bringing the systems only sort of online (which was
what I was seeing last I looked).
At this point I am tempted to remove the CPU-oversubscription aspect
of TREE01. What are your thoughts?
Thanx, Paul
> Plus for TREE07, arm64 does not enable CONFIG_PREEMPT_LAZY, resulting
> in rcutorture complaining about a .config error. Not sure whether it
> would be easier to enable CONFIG_PREEMPT_LAZY or to make rcutorture be
> able to go either way. ;-)
>
> Thanx, Paul
>
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [BUG] RCU CPU stall warnings on TREE01 on arm64
2025-05-06 18:21 ` Paul E. McKenney
@ 2025-05-06 19:10 ` Joel Fernandes
0 siblings, 0 replies; 7+ messages in thread
From: Joel Fernandes @ 2025-05-06 19:10 UTC (permalink / raw)
To: paulmck; +Cc: rcu
On 5/6/2025 2:21 PM, Paul E. McKenney wrote:
> On Tue, May 06, 2025 at 11:03:40AM -0700, Paul E. McKenney wrote:
>> On Tue, May 06, 2025 at 10:09:54AM -0400, Joel Fernandes wrote:
>>>
>>>
>>> On 5/5/2025 3:03 PM, Paul E. McKenney wrote:
>>>> Hello!
>>>>
>>>> Following up on off-list discussions and requests for more information.
>>>>
>>>> These reproduce reasonably easily, and here is an example:
>>>>
>>>> ------------------------------------------------------------------------
>>>> [ 426.022056] rcu: NOCB: Cannot CB-offload online CPU 25
>>>> [ 460.867350] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
>>>> [ 460.867980] rcu: 0-...!: (1 GPs behind) idle=8fe4/1/0x4000000000000000 softirq=2124/2125 fqs=0
>>>> [ 460.868726] rcu: 1-...!: (1 GPs behind) idle=e0ac/1/0x4000000000000000 softirq=3547/3547 fqs=0
>>>> [ 460.869468] rcu: 5-...!: (1 GPs behind) idle=5c34/1/0x4000000000000000 softirq=2084/2084 fqs=0
>>>> [ 460.870233] rcu: 8-...!: (1 GPs behind) idle=9fdc/1/0x4000000000000000 softirq=4301/4301 fqs=0
>>>> [ 460.871007] rcu: 9-...!: (0 ticks this GP) idle=4a2c/1/0x4000000000000000 softirq=3873/3873 fqs=0
>>>> [ 460.871772] rcu: 10-...!: (1 GPs behind) idle=4994/1/0x4000000000000000 softirq=4760/4760 fqs=0
>>>> [ 460.872511] rcu: 12-...!: (1 GPs behind) idle=0bbc/1/0x4000000000000000 softirq=3545/3545 fqs=0
>>>> [ 460.873300] rcu: 13-...!: (1 GPs behind) idle=a59c/1/0x4000000000000000 softirq=2097/2098 fqs=0
>>>> [ 460.874084] rcu: 14-...!: (1 GPs behind) idle=22cc/1/0x4000000000000000 softirq=4424/4424 fqs=0
>>>> [ 460.874864] rcu: 15-...!: (1 GPs behind) idle=0e5c/1/0x4000000000000000 softirq=5984/5984 fqs=0
>>>> [ 460.875625] rcu: 16-...!: (1 GPs behind) idle=d5bc/1/0x4000000000000000 softirq=6313/6313 fqs=0
>>>> [ 460.876374] rcu: 17-...!: (1 GPs behind) idle=848c/1/0x4000000000000000 softirq=4160/4160 fqs=0
>>>> [ 460.877182] rcu: 18-...!: (1 GPs behind) idle=a1c4/1/0x4000000000000000 softirq=3217/3217 fqs=0
>>>> [ 460.877930] rcu: 19-...!: (0 ticks this GP) idle=cbe4/1/0x4000000000000000 softirq=7886/7886 fqs=0
>>>> [ 460.878772] rcu: 20-...!: (1 GPs behind) idle=3acc/1/0x4000000000000000 softirq=4315/4317 fqs=0
>>>> [ 460.879514] rcu: 21-...!: (1 GPs behind) idle=eb7c/1/0x4000000000000000 softirq=4221/4221 fqs=0
>>>> [ 460.880225] rcu: 22-...!: (1 GPs behind) idle=477c/1/0x4000000000000000 softirq=5049/5049 fqs=0
>>>> [ 460.880990] rcu: 23-...!: (1 GPs behind) idle=8404/1/0x4000000000000000 softirq=5635/5636 fqs=0
>>>> [ 460.881739] rcu: 24-...!: (0 ticks this GP) idle=11e4/1/0x4000000000000000 softirq=2031/2031 fqs=0
>>>> [ 460.882497] rcu: 25-...!: (0 ticks this GP) idle=3434/1/0x4000000000000000 softirq=3495/3495 fqs=0
>>>> [ 460.883296] rcu: 26-...!: (1 GPs behind) idle=f864/1/0x4000000000000000 softirq=3645/3645 fqs=0
>>>> [ 460.884054] rcu: 27-...!: (0 ticks this GP) idle=3e74/1/0x4000000000000000 softirq=4168/4168 fqs=0
>>>> [ 460.884805] rcu: 28-...!: (1 GPs behind) idle=71a4/1/0x4000000000000000 softirq=3596/3596 fqs=0
>>>> [ 460.885570] rcu: 29-...!: (1 GPs behind) idle=9aa4/1/0x4000000000000000 softirq=3111/3112 fqs=0
>>>> [ 460.886276] rcu: 30-...!: (1 GPs behind) idle=10dc/1/0x4000000000000000 softirq=3030/3030 fqs=0
>>>> [ 460.887030] rcu: 31-...!: (0 ticks this GP) idle=0fb4/1/0x4000000000000000 softirq=3540/3540 fqs=0
>>>> [ 460.887777] rcu: 32-...!: (1 GPs behind) idle=fad4/1/0x4000000000000000 softirq=2645/2645 fqs=0
>>>> [ 460.888548] rcu: 33-...!: (0 ticks this GP) idle=37ac/1/0x4000000000000000 softirq=2201/2201 fqs=0
>>>> [ 460.889336] rcu: 34-...!: (1 GPs behind) idle=85ac/1/0x4000000000000000 softirq=2336/2336 fqs=0
>>>> [ 460.890081] rcu: 35-...!: (1 GPs behind) idle=756c/1/0x4000000000000000 softirq=1534/1536 fqs=0
>>>> [ 460.890820] rcu: 36-...!: (0 ticks this GP) idle=b2ec/1/0x4000000000000000 softirq=4286/4286 fqs=0
>>>> [ 460.891572] rcu: 37-...!: (1 GPs behind) idle=de1c/1/0x4000000000000000 softirq=2725/2725 fqs=0
>>>> [ 460.892323] rcu: 38-...!: (1 GPs behind) idle=c62c/1/0x4000000000000000 softirq=2341/2342 fqs=0
>>>> [ 460.893096] rcu: 39-...!: (1 GPs behind) idle=be2c/1/0x4000000000000000 softirq=2650/2651 fqs=0
>>>> [ 460.893830] rcu: 40-...!: (1 GPs behind) idle=7ecc/1/0x4000000000000000 softirq=2119/2121 fqs=0
>>>> [ 460.894621] rcu: 41-...!: (0 ticks this GP) idle=19dc/1/0x4000000000000000 softirq=3539/3539 fqs=0
>>>> [ 460.895384] rcu: 42-...!: (0 ticks this GP) idle=a74c/1/0x4000000000000000 softirq=2259/2259 fqs=0
>>>> [ 460.896148] rcu: Tasks blocked on level-1 rcu_node (CPUs 30-42): P91/1:b..l
>>>> [ 460.896778] rcu: (detected by 11, t=7962 jiffies, g=15565, q=48 ncpus=39)
>>>> [ 460.897395] Sending NMI from CPU 11 to CPUs 0:
>>>> [ 461.047304] rcu-torture: rtc: 00000000fb6bc815 ver: 2137 tfle: 0 rta: 2137 rtaf: 0 rtf: 2128 rtmbe: 0 rtmbkf: 0/2042 rtbe: 0 rtbke: 0 rtbf: 0 rtb: 0 nt: 148999 onoff: 32/32:36/37 7,348:36,3639 4096:26899 (HZ=250) barrier: 979/980:0 read-exits: 416 nocb-toggles: 1013:969 gpwraps: 0
>>>> [ 461.047343] rcu-torture: Reader Pipe: 1919541609 11501 0 0 0 0 0 0 0 0 0
>>>> [ 461.047383] rcu-torture: Reader Batch: 1919533823 19422 0 0 0 0 0 0 0 0 0
>>>> [ 461.047401] rcu-torture: Free-Block Circulation: 2136 2136 2135 2134 2133 2132 2131 2130 2129 2128 0
>>>> [ 462.777371] NMI backtrace for cpu 0
>>>> [ 462.777547] CPU: 0 UID: 0 PID: 20 Comm: migration/0 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
>>>> [ 462.777551] Hardware name: linux,dummy-virt (DT)
>>>> [ 462.777552] Stopper: multi_cpu_stop+0x0/0x15c <- __stop_cpus.constprop.0+0x78/0xc4
>>>> [ 462.777564] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
>>>> [ 462.777566] pc : handle_softirqs+0xa0/0x248
>>>> [ 462.777836] lr : handle_softirqs+0x7c/0x248
>>>> [ 462.777838] sp : ffff800080003f50
>>>> [ 462.777839] x29: ffff800080003f50 x28: ffff000003d9d780 x27: 0000000000000000
>>>> [ 462.777842] x26: 0000000000000282 x25: 0000000000000000 x24: ffffafb5af9f4000
>>>> [ 462.777843] x23: 0000000063400005 x22: ffffafb5adb9b8f0 x21: ffffafb5af9e93c8
>>>> [ 462.778009] x20: ffffafb5b02970c0 x19: ffff000003d9d780 x18: 0000000000000001
>>>> [ 462.778012] x17: ffff504a6d7bc000 x16: ffff800080000000 x15: ffff00001d5f4d00
>>>> [ 462.778013] x14: 0000000000000156 x13: 0000000000000000 x12: 0000000000000000
>>>> [ 462.778015] x11: ffff00001d1b0d80 x10: 00000000002ab980 x9 : 0000000000000000
>>>> [ 462.778017] x8 : 000001d6146032ba x7 : ffff00000500b800 x6 : 0000000000000000
>>>> [ 462.778019] x5 : 00000000002ab980 x4 : 0000000100009e3e x3 : ffff504a6d7bc000
>>>> [ 462.778020] x2 : 0000006bbfae36c0 x1 : ffff504a6d7bc000 x0 : ffffafb5af9f4000
>>>> [ 462.778232] Call trace:
>>>> [ 462.778233] handle_softirqs+0xa0/0x248 (P)
>>>> [ 462.778296] __do_softirq+0x14/0x20
>>>> [ 462.778299] ____do_softirq+0x10/0x1c
>>>> [ 462.778389] call_on_irq_stack+0x24/0x4c
>>>> [ 462.778391] do_softirq_own_stack+0x1c/0x2c
>>>> [ 462.778393] __irq_exit_rcu+0xd8/0x110
>>>> [ 462.778395] irq_exit_rcu+0x10/0x1c
>>>> [ 462.778456] el1_interrupt+0x38/0x68
>>>> [ 462.778531] el1h_64_irq_handler+0x18/0x24
>>>> [ 462.778533] el1h_64_irq+0x6c/0x70
>>>> [ 462.778534] multi_cpu_stop+0xf0/0x15c (P)
>>>> [ 462.778536] cpu_stopper_thread+0x8c/0x11c
>>>> [ 462.778642] smpboot_thread_fn+0x220/0x24c
>>>> [ 462.778647] kthread+0x134/0x208
>>>> [ 462.778649] ret_from_fork+0x10/0x20
>>>> [ 463.888107] NMI backtrace for cpu 1
>>>> [ 463.888117] CPU: 1 UID: 0 PID: 0 Comm: swapper/1 Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
>>>> [ 463.888120] Hardware name: linux,dummy-virt (DT)
>>>> [ 463.888121] pstate: 43400005 (nZcv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
>>>> [ 463.888123] pc : handle_softirqs+0xa0/0x248
>>>> [ 463.888135] lr : handle_softirqs+0x7c/0x248
>>>> [ 463.888140] sp : ffff80008000bf50
>>>> [ 463.888140] x29: ffff80008000bf50 x28: ffff000003d9e900 x27: 0000000000000000
>>>> [ 463.888143] x26: 0000000000000282 x25: ffff000003d9e900 x24: ffffafb5af9f4000
>>>> [ 463.888146] x23: 0000000063400005 x22: ffffafb5adad9114 x21: ffffafb5af9e93c8
>>>> [ 463.888148] x20: ffffafb5b02970c0 x19: ffff000003d9e900 x18: 0000000000000000
>>>> [ 463.888150] x17: ffff504a6d7d6000 x16: ffff800080008000 x15: ffff00001d1cad00
>>>> [ 463.888152] x14: 0000000000000112 x13: 0000000000000000 x12: 0000000000000000
>>>> [ 463.888158] x11: 0000000000000a95 x10: 0000000000000163 x9 : 0000000000000000
>>>> [ 463.888160] x8 : 0000006bfc655500 x7 : 7fffffffffffffff x6 : 0000006bfc655500
>>>> [ 463.888165] x5 : 0000006bfca25e00 x4 : 0000000100009ff5 x3 : ffff504a6d7d6000
>>>> [ 463.888168] x2 : 0000006c01e2bea0 x1 : ffff504a6d7d6000 x0 : ffffafb5af9f4000
>>>> [ 463.888171] Call trace:
>>>> [ 463.888172] handle_softirqs+0xa0/0x248 (P)
>>>> [ 463.888175] __do_softirq+0x14/0x20
>>>> [ 463.888178] ____do_softirq+0x10/0x1c
>>>> [ 463.888183] call_on_irq_stack+0x24/0x4c
>>>> [ 463.888185] do_softirq_own_stack+0x1c/0x2c
>>>> [ 463.888187] __irq_exit_rcu+0xd8/0x110
>>>> [ 463.888192] irq_exit_rcu+0x10/0x1c
>>>> [ 463.888194] el1_interrupt+0x38/0x68
>>>> [ 463.888198] el1h_64_irq_handler+0x18/0x24
>>>> [ 463.888200] el1h_64_irq+0x6c/0x70
>>>> [ 463.888202] finish_task_switch.isra.0+0x74/0x220 (P)
>>>> [ 463.888207] __schedule+0x2fc/0x998
>>>> [ 463.888210] schedule_idle+0x28/0x48
>>>> [ 463.888212] do_idle+0x170/0x268
>>>> [ 463.888215] cpu_startup_entry+0x34/0x3c
>>>> [ 463.888217] secondary_start_kernel+0x138/0x158
>>>> [ 463.888224] __secondary_switched+0xc0/0xc4
>>>> [ 463.941174] NMI backtrace for cpu 8
>>>> [ 463.941179] CPU: 8 UID: 0 PID: 19 Comm: rcu_exp_gp_kthr Not tainted 6.15.0-rc1-00066-g612f2bb48fa2 #22 PREEMPT
>>>> [ 463.941220] Hardware name: linux,dummy-virt (DT)
>>>> [ 463.941222] pstate: 23400005 (nzCv daif +PAN -UAO +TCO +DIT -SSBS BTYPE=--)
>>>> [ 463.941223] pc : smp_call_function_single+0xe4/0x1b0
>>>> [ 463.941292] lr : __sync_rcu_exp_select_node_cpus+0x224/0x3c8
>>>> [ 463.941366] sp : ffff800080233cd0
>>>> [ 463.941367] x29: ffff800080233d20 x28: 0000000000000002 x27: ffff000003d9c600
>>>> [ 463.941370] x26: ffffafb5b032a880 x25: ffff00001d4d7ac0 x24: ffffafb5adb49e24
>>>> [ 463.941372] x23: 0000000000001fff x22: ffffafb5af9f5ac0 x21: ffffafb5b029ea08
>>>> [ 463.941374] x20: 0000000000000000 x19: ffff800080233ce0 x18: 0000000000000001
>>>> [ 463.941376] x17: ffff504a6d88c000 x16: ffff800080040000 x15: 0000000000000000
>>>> [ 463.941378] x14: 0000000000000115 x13: 0000000000000115 x12: 0000000000000000
>>>> [ 463.941380] x11: ffffafb5af9f0408 x10: 0000000000000001 x9 : ffff000003d9c600
>>>> [ 463.941462] x8 : 0000000000000040 x7 : ffffafb5b0322ab0 x6 : ffffafb5adb49e24
>>>> [ 463.941464] x5 : 0000000000000000 x4 : ffff00001d281f08 x3 : 0000000000000001
>>>> [ 463.941535] x2 : 0000000000000000 x1 : ffff00001d281f00 x0 : 000000000000001f
>>>> [ 463.941537] Call trace:
>>>> [ 463.941538] smp_call_function_single+0xe4/0x1b0 (P)
>>>> [ 463.941541] __sync_rcu_exp_select_node_cpus+0x224/0x3c8
>>>> [ 463.941619] sync_rcu_exp_select_cpus+0x138/0x2a4
>>>> [ 463.941622] wait_rcu_exp_gp+0x18/0x30
>>>> [ 463.941644] kthread_worker_fn+0xcc/0x184
>>>> [ 463.941708] kthread+0x134/0x208
>>>> [ 463.941709] ret_from_fork+0x10/0x20
>>>
>>> I wish the back trace also included which CPU the smp_call_function_single is
>>> waiting on. This is similar to what Boqun sees as well, where we are spinning on
>>> csd lock for a CPU that is wedged. In this case, the 'wedged' appears to be on
>>> level-1 rcu_node (CPUs 30-42) ? But we don't have those backtraces in the above
>>> to confirm which specific one.
>>
>> The way to make that happen is via the CSD_LOCK_WAIT_DEBUG and the
>> CSD_LOCK_WAIT_DEBUG_DEFAULT Kconfig options.
>>
>>> Al though, cpu 8 looks like it could itself be the one blocking the GP as a
>>> secondary effect of the smp_call IPI not coming through?
>>
>> What caught my eye was this: "Stopper: multi_cpu_stop+0x0/0x15c".
>>
>> This puppy makes all the CPUs spin with interrupts disabled. It looks
>> like it was running while something was blocking context switches on
>> at least some of the CPUs. It is a most wonderful way to amplify any
>> delay on any CPUs to affect all CPUs. ;-)
>>
>>> Speaking of smp_call, may be it does make sense for EXP to not wait too long for
>>> csd lock thus to not make dire matters worse? After all, the GP may well
>>> complete eventually even without the IPI executing? Perhaps even sooner if the
>>> CPU doing the smp_call wait does some other useful work as well.
>>
>> What does the RCU expedited grace period do instead of waiting?
>>
>> I could imagine an smp_call_function_single() API that did exponential
>> backoff, spinning for a bit, sleeping, spinning for a bit, sleeping
>> for longer and so on. Or did you have something else in mind?
>>
>>>> At first glance, this looks like a stop_machine() request gone bad.
>>>> Please note that I am seeing this on most TREE01 runs and nowhere else.
>>>> So this might be a strange side effect of dynamic callback offloading,
>>>> but perhaps more likely due to TREE01 using more CPUs than it is allowing
>>>> for, that is, telling qemu "-smp 43", the kernel "maxcpus=8 nr_cpus=43",
>>>> but forcing the guest OS to run on only eight CPUs. (Why??? Well,
>>>> back in the day, there was an RCU bug exposed by this.)
>>>>
>>>> All that aside, this is one of the more spectacular RCU CPU stall warnings
>>>> I have ever seen, and that is with me leaving off the NMI stack traces
>>>> for most of the CPUs. ;-)
>>>
>>> IIRC, NMI stack tracing on ARM is unreliable due to raisins.
>>
>> Ah, true, older ARM hardware lacks NMIs.
>>
>>>> If there is interest, I could post a tarball of a few of the full
>>>> console logs.
>>>>
>>>> Come to think of it, even if there isn't interest, here you go! ;-)
>>>>
>>>> https://drive.google.com/file/d/1JKmCYqK6kAwhlJZUJQeTle-o62aJXkUQ/view?usp=sharing
>>>
>>> TREE01 in this trace seems to be a different splat I think:
>>>
>>> [ 71.612482] rcu: Offline CPU 1 blocking current GP.
>>>
>>> Causing the stall I think. Something to do with hotplug? I wonder if without
>>> hotplug testing, it will trigger or not with the same CPU count settings. It may
>>> be worth adding the ARM folks as well.
>>
>> I could try going back to the overload case and disabling CPU hotplug.
>> But the problem seems to be that ARM is taking the extra 35 CPUs much
>> more seriously than does x86, which could cause trouble given that the
>> rcutorture scripting is jamming all 43 of them onto eight real CPUs.
>> The strange thing if that they are online as far as the (de)offloading
>> tests are concerned, but they show no sign of ever having been brought
>> online.
>>
>> No, I take it back, they were brought online, it is just that ARM's CPU
>> ID space is way different than I would expect: 0x1, 0x2, 0x3, ..., 0xe,
>> 0xf, 0x100, 0x101, ...
>>
>> With then change to TREE01, there are only ever eight of them.
>>
>> Either way, the next step seems to be to remove the "CONFIG_NR_CPUS=8"
>> to see what happens.
>
> Which causes all 43 CPUs and the stall warnings to reappear, and with
> the stop-machine code again at the scene of the crime. Which is not
> at all surprising: 43 vCPUs are trying to spin with interrupts disabled
> on only 8 real CPUs, which just is never going to end well.
>
> So this might just be ARM making heavier use of stop-machine than does
> x86. Or maybe x86 bringing the systems only sort of online (which was
> what I was seeing last I looked).
>
> At this point I am tempted to remove the CPU-oversubscription aspect
> of TREE01. What are your thoughts?
I am also of similar opinion. Or maybe oversubscribe it lesser but still
oversubscribe? :) Since you mentioned there is an RCU bug this tests.
It sounds like you want to test vCPU preemption more by having a configuration
where vCPU >> pCPU. If not, then maybe the cpu_count in kvm.sh shouldn't
oversubscribe like that?
It could also be a 'bug' in ARM KVM which is not allowing the scheduling of the
vCPU threads correctly or something.
- Joel
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2025-05-06 19:11 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2025-05-05 19:03 [BUG] RCU CPU stall warnings on TREE01 on arm64 Paul E. McKenney
2025-05-05 22:44 ` Paul E. McKenney
2025-05-06 0:09 ` Paul E. McKenney
2025-05-06 14:09 ` Joel Fernandes
2025-05-06 18:03 ` Paul E. McKenney
2025-05-06 18:21 ` Paul E. McKenney
2025-05-06 19:10 ` Joel Fernandes
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).