linux-kernel - Re: [PATCH] x86/apic: Fix circular locking dependency between console and hrtimer locks

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20200427134130.GE134660@unreal>
Date:   Mon, 27 Apr 2020 16:41:30 +0300
From:   Leon Romanovsky <leon@...nel.org>
To:     Thomas Gleixner <tglx@...utronix.de>
Cc:     Ingo Molnar <mingo@...nel.org>, Ingo Molnar <mingo@...hat.com>,
        Borislav Petkov <bp@...en8.de>,
        "H. Peter Anvin" <hpa@...or.com>, x86 <x86@...nel.org>,
        Suresh Siddha <suresh.b.siddha@...el.com>,
        linux-kernel@...r.kernel.org
Subject: Re: [PATCH] x86/apic: Fix circular locking dependency between
 console and hrtimer locks

On Mon, Apr 27, 2020 at 02:59:00PM +0200, Thomas Gleixner wrote:
> Leon Romanovsky <leon@...nel.org> writes:
> > On Mon, Apr 27, 2020 at 01:09:49PM +0200, Thomas Gleixner wrote:
> >> The local APIC timer (in this case the TSC deadline timer) is set up
> >> during early boot on the boot CPU (before SMP setup) with this call
> >> chain:
> >>
> >> smp_prepare_cpus()
> >>  native_smp_prepare_cpus()
> >>    x86_init.timers.setup_percpu_clockev()
> >>      setup_boot_APIC_clock()
> >>        setup_APIC_timer()
> >>          clockevents_config_and_register()
> >>            tick_check_new_device()
> >>              tick_setup_device()
> >>                tick_setup_oneshot()
> >>                  clockevents_switch_state()
> >>                    lapic_timer_set_oneshot()
> >>                      __setup_APIC_LVTT()
> >>                        printk_once(...)
> >>
> >> Nothing holds hrtimer.base_lock in this call chain.
> >
> > Can't printk hold that lock through console/netconsole?
>
> How so?

OK, I consulted with verification people and back then the trigger was:
Reproduce when run "echo 1 > /sys/kernel/debug/clear_warn_once" after reboot

>
> The lockdep splat is about this:
>
>  [  735.324154] swapper/3/0 is trying to acquire lock:
>  [  735.324155] ffffffff8442c858 ((console_sem).lock){-...}-{2:2}, at: down_trylock+0x13/0x70
>  [  735.324162]
>  [  735.324164] but task is already holding lock:
>  [  735.324165] ffff88842dfb9958 (hrtimer_bases.lock){-.-.}-{2:2}, at: lock_hrtimer_base+0x71/0x120
>
> and the call chain is:
>
>  [  735.324283]        __lock_acquire+0x374a/0x5210
>  [  735.324284]        lock_acquire+0x1b9/0x920
>  [  735.324286]        _raw_spin_lock_irqsave+0x3c/0x4b
>  [  735.324288]        down_trylock+0x13/0x70
>  [  735.324289]        __down_trylock_console_sem+0x33/0xa0
>  [  735.324291]        console_trylock+0x13/0x60
>  [  735.324292]        vprintk_emit+0xec/0x370
>  [  735.324294]        printk+0x9c/0xc3
>  [  735.324296]        lapic_timer_set_oneshot+0x4e/0x60
>  [  735.324297]        clockevents_switch_state+0x1e1/0x360
>  [  735.324299]        tick_program_event+0xae/0xc0
>  [  735.324301]        hrtimer_start_range_ns+0x4b6/0xaa0
>  [  735.324302]        tick_nohz_idle_stop_tick+0x67c/0xa90
>  [  735.324304]        do_idle+0x326/0x530
>  [  735.324305]        cpu_startup_entry+0x19/0x20
>  [  735.324307]        start_secondary+0x2ee/0x3e0
>  [  735.324309]        secondary_startup_64+0xa4/0xb0
>
> hrtimer_start_range_ns() clearly holds htimer_base::lock
>
> >> But the lockdep splat clearly says:
> >>
> >>  [  735.324357] stack backtrace:
> >>  [  735.324360] CPU: 3 PID: 0 Comm: swapper/3 Not tainted 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 #1
> >>
> >> ...
> >>
> >> So how can that be the first invocation of that printk_once()?
> >>
> >> While the patch looks innocent, it papers over the underlying problem
> >> and wild theories are not really helping here.
> >>
> >> Here is a boot log excerpt with lockdep enabled and 'debug' on the
> >> command line:
> >>
> >> [    0.000000] Linux version 5.7.0-rc3 ...
> >> ...
> >> [    3.992125] TSC deadline timer enabled
> >> [    3.995820] smpboot: CPU0: Intel(R) ....
> >> ...
> >> [    4.050766] smp: Bringing up secondary CPUs ...
> >>
> >> No splat nothing. The real question is WHY this triggers on Leons
> >> machine 735 seconds after boot and on CPU3.
> >
> > I want to believe that the timestamp are not correct, have no clue if it
> > is even possible.
>
> It does not matter whether the timestamps are correct or not. Even if
> they are not, then this does not change the fact that this happens on
> CPU3 way after the first invocation of __setup_APIC_LVTT() on CPU0 which
> simply cannot trigger this splat.
>
> Can you please provide the full dmesg with the splat?

Attached

>
> > But let's talk about facts:
> > 1. It is started after -rc1 (we don't test linux-next).
>
> Is that a plain kernel from Linus tree or do you have other patches
> applied?

It is clean one.

>
> A .config file would be appreciated as well along with information about
> the hardware or whatever this runs on.

This is passthrough VM with Mellanox NICs in it, everything else is
virtual.

>
> > 2. This workaround helped to eliminate the splat.
>
> It's eliminating the symptom, but this does not make the root cause go
> away nor does it explain anything.
>
> > 3. My machine experiences the extra splat all the time
> > https://lore.kernel.org/lkml/20200414070502.GR334007@unreal/
>
> which is completely unrelated.
>
> Thanks,
>
>         tglx

View attachment "bug_2131735" of type "text/plain" (53071 bytes)

Download attachment "config.gz" of type "application/gzip" (41017 bytes)