BUG: Invalid wait context at: mc146818_avoid_UIP tick_freeze

BUG: Invalid wait context at: mc146818_avoid_UIP tick_freeze

[Chris Bainbridge]

This splat happens on suspend/resume on a HP laptop. It doesn't appear
to be a recent regression, as a bisect only leads to 560af5dc839e
("lockdep: Enable PROVE_RAW_LOCK_NESTING with PROVE_LOCKING.") - so
most likely the issue has been around for a while, but a recent kernel
build with lockdep enabled will now show it.

Log is from 6.12.0-12114-g410839faa596:

[   33.831760] PM: suspend entry (s2idle)
[   34.072873] Filesystems sync: 0.241 seconds
[   34.079438] Freezing user space processes
[   34.082049] Freezing user space processes completed (elapsed 0.002 seconds)
[   34.082092] OOM killer disabled.
[   34.082094] Freezing remaining freezable tasks
[   34.083487] Freezing remaining freezable tasks completed (elapsed
0.001 seconds)
[   34.083595] printk: Suspending console(s) (use no_console_suspend to debug)
[   34.118629] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[   34.248840] ACPI: EC: interrupt blocked
[   34.387850] =============================
[   34.387851] [ BUG: Invalid wait context ]
[   34.387852] 6.12.0-12114-g410839faa596 #70 Not tainted
[   34.387854] -----------------------------
[   34.387855] swapper/0/0 is trying to lock:
[   34.387857] ffffffff98c69d38 (rtc_lock){....}-{3:3}, at:
mc146818_avoid_UIP (drivers/rtc/rtc-mc146818-lib.c:41)
[   34.387868] other info that might help us debug this:
[   34.387869] context-{5:5}
[   34.387869] 1 lock held by swapper/0/0:
[   34.387870] #0: ffffffff98e5cc18 (tick_freeze_lock){....}-{2:2},
at: tick_freeze (kernel/time/tick-common.c:527)
[   34.387878] stack backtrace:
[   34.387880] CPU: 0 UID: 0 PID: 0 Comm: swapper/0 Not tainted
6.12.0-12114-g410839faa596 #70
[   34.387882] Hardware name: HP HP Pavilion Aero Laptop
13-be0xxx/8916, BIOS F.16 08/01/2024
[   34.387883] Call Trace:
[   34.387884]  <TASK>
[   34.387885] dump_stack_lvl (lib/dump_stack.c:123)
[   34.387889] dump_stack (lib/dump_stack.c:130)
[   34.387890] __lock_acquire (kernel/locking/lockdep.c:4828
kernel/locking/lockdep.c:4898 kernel/locking/lockdep.c:5176)
[   34.387895] lock_acquire (kernel/locking/lockdep.c:467
kernel/locking/lockdep.c:5851 kernel/locking/lockdep.c:5814)
[   34.387897] ? mc146818_avoid_UIP (drivers/rtc/rtc-mc146818-lib.c:41)
[   34.387898] ? __lock_acquire (kernel/locking/lockdep.c:4670
kernel/locking/lockdep.c:5180)
[   34.387900] _raw_spin_lock_irqsave
(./include/linux/spinlock_api_smp.h:111 kernel/locking/spinlock.c:162)
[   34.387907] ? mc146818_avoid_UIP (drivers/rtc/rtc-mc146818-lib.c:41)
[   34.387908] mc146818_avoid_UIP (drivers/rtc/rtc-mc146818-lib.c:41)
[   34.387910] ? rtc_get_dev_attribute_groups
(drivers/rtc/rtc-mc146818-lib.c:112)
[   34.387911] mc146818_get_time (drivers/rtc/rtc-mc146818-lib.c:160)
[   34.387913] mach_get_cmos_time (arch/x86/kernel/rtc.c:69)
[   34.387920] read_persistent_clock64 (arch/x86/kernel/rtc.c:111)
[   34.387921] timekeeping_suspend (kernel/time/timekeeping.c:1924)
[   34.387925] tick_freeze (kernel/time/tick-common.c:538)
[   34.387926] enter_s2idle_proper (drivers/cpuidle/cpuidle.c:161)
[   34.387929] cpuidle_enter_s2idle (drivers/cpuidle/cpuidle.c:203)
[   34.387934] do_idle (kernel/sched/idle.c:205 kernel/sched/idle.c:325)
[   34.387937] cpu_startup_entry (kernel/sched/idle.c:422 (discriminator 1))
[   34.387938] rest_init (./include/linux/rcupdate.h:850 init/main.c:718)
[   34.387939] start_kernel (init/main.c:448 init/main.c:927)
[   34.387944] x86_64_start_reservations (arch/x86/kernel/head64.c:495)
[   34.387951] x86_64_start_kernel (arch/x86/kernel/head64.c:437
(discriminator 17))
[   34.387954] common_startup_64 (arch/x86/kernel/head_64.S:415)
[   34.387966]  </TASK>
[   34.949164] ACPI: EC: interrupt unblocked
[   34.978854] i2c_hid_acpi i2c-ELAN074E:00: i2c_hid_get_input:
incomplete report (14/516)
[   34.979597] [drm] PCIE GART of 1024M enabled.
[   34.979600] [drm] PTB located at 0x000000F41FC00000

Re: BUG: Invalid wait context at: mc146818_avoid_UIP tick_freeze

[Mateusz Jończyk]

W dniu 1.12.2024 o 18:05, Chris Bainbridge pisze:
> This splat happens on suspend/resume on a HP laptop. It doesn't appear
> to be a recent regression, as a bisect only leads to 560af5dc839e
> ("lockdep: Enable PROVE_RAW_LOCK_NESTING with PROVE_LOCKING.") - so
> most likely the issue has been around for a while, but a recent kernel
> build with lockdep enabled will now show it.

Hello,

Thank you for this bug report.

The cause is that timekeeping_suspend takes a raw spinlock called "tick_freeze_lock". With this lock taken, this function indirectly calls mc146818_avoid_UIP, which takes a normal spinlockcalled
"rtc_lock".

It is not permissible to take a normal spinlock while holding a raw spinlock due to issues on PREEMPT_RT kernels:

https://docs.kernel.org/locking/locktypes.html#raw-spinlock-t-on-rt

From what I can see, this has been so for a very long time. I was able to trigger the bug on Linux 6.1.0 with CONFIG_PROVE_RAW_LOCK_NESTING enabled.

A solution to the problem would be to turn the rtc_lock into a raw spinlock. This requires that the critical section (during which the lock is held) is small. Reading full time from the RTC requires
in one critical section over 10 CMOS_READ invocations, writing full time - around 15 CMOS_READ/CMOS_WRITE invocations. This cannot really be broken down AFAIK - I hope that the critical section would
be small enough.

The rtc_lock is used on 7 architectures (mips, sparc64, powerpc, alpha, x86, arm, m68k/atari), so this will require a bit of work. I'll try and see what I'll be able to do.

Greetings & merry Christmas,

Mateusz