Re: [PATCH v3 00/51] cpuidle,rcu: Clean up the mess

Mark Rutland
2023-01-16T17:21:25Z

On Thu, Jan 12, 2023 at 08:43:14PM +0100, Peter Zijlstra wrote:
> Hi All!

Hi Peter,

> The (hopefully) final respin of cpuidle vs rcu cleanup patches. Barring any
> objections I'll be queueing these patches in tip/sched/core in the next few
> days.

I'm sorry to have to bear some bad news on that front. :(

I just had a go at testing this on a Juno dev board, using your queue.git
sched/idle branch and defconfig + CONFIG_PROVE_LOCKING=y +
CONFIG_DEBUG_LOCKDEP=y + CONFIG_DEBUG_ATOMIC_SLEEP=y.

With that I consistently see RCU at boot time (log below).

| =============================
| WARNING: suspicious RCU usage
| 6.2.0-rc3-00051-gced9b6eecb31 #1 Not tainted
| -----------------------------
| include/trace/events/ipi.h:19 suspicious rcu_dereference_check() usage!
|
| other info that might help us debug this:
|
|
| rcu_scheduler_active = 2, debug_locks = 1
| RCU used illegally from extended quiescent state!
| no locks held by swapper/0/0.
|
| stack backtrace:
| CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.2.0-rc3-00051-gced9b6eecb31 #1
| Hardware name: ARM LTD ARM Juno Development Platform/ARM Juno Development Platform, BIOS EDK II May 16 2021
| Call trace:
| dump_backtrace.part.0+0xe4/0xf0
| show_stack+0x18/0x30
| dump_stack_lvl+0x98/0xd4
| dump_stack+0x18/0x34
| lockdep_rcu_suspicious+0xf8/0x10c
| trace_ipi_raise+0x1a8/0x1b0
| arch_irq_work_raise+0x4c/0x70
| __irq_work_queue_local+0x48/0x80
| irq_work_queue+0x50/0x80
| __wake_up_klogd.part.0+0x98/0xe0
| defer_console_output+0x20/0x30
| vprintk+0x98/0xf0
| _printk+0x5c/0x84
| lockdep_rcu_suspicious+0x34/0x10c
| trace_lock_acquire+0x174/0x180
| lock_acquire+0x3c/0x8c
| _raw_spin_lock_irqsave+0x70/0x150
| down_trylock+0x18/0x50
| __down_trylock_console_sem+0x3c/0xd0
| console_trylock+0x28/0x90
| vprintk_emit+0x11c/0x354
| vprintk_default+0x38/0x4c
| vprintk+0xd4/0xf0
| _printk+0x5c/0x84
| lockdep_rcu_suspicious+0x34/0x10c
| printk_sprint+0x238/0x240
| vprintk_store+0x32c/0x4b0
| vprintk_emit+0x104/0x354
| vprintk_default+0x38/0x4c
| vprintk+0xd4/0xf0
| _printk+0x5c/0x84
| lockdep_rcu_suspicious+0x34/0x10c
| trace_irq_disable+0x1ac/0x1b0
| trace_hardirqs_off+0xe8/0x110
| cpu_suspend+0x4c/0xfc
| psci_cpu_suspend_enter+0x58/0x6c
| psci_enter_idle_state+0x70/0x170
| cpuidle_enter_state+0xc4/0x464
| cpuidle_enter+0x38/0x50
| do_idle+0x230/0x2c0
| cpu_startup_entry+0x24/0x30
| rest_init+0x110/0x190
| arch_post_acpi_subsys_init+0x0/0x18
| start_kernel+0x6f8/0x738
| __primary_switched+0xbc/0xc4

IIUC what's happenign here is the PSCI cpuidle driver has entered idle and RCU
is no longer watching when arm64's cpu_suspend() manipulates DAIF. Our
local_daif_*() helpers poke lockdep and tracing, hence the call to
trace_hardirqs_off() and the RCU usage.

I think we need RCU to be watching all the way down to cpu_suspend(), and it's
cpu_suspend() that should actually enter/exit idle context. That and we need to
make cpu_suspend() and the low-level PSCI invocation noinstr.

I'm not sure whether 32-bit will have a similar issue or not.

I'm surprised no-one else who has tested has seen this; I suspect people
haven't enabled lockdep and friends. :/

Thanks,
Mark.