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

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

[Leon Romanovsky]

From: Leon Romanovsky <leonro@mellanox.com>

clockevents_switch_state() calls printk() from under hrtimer_bases.lock.
That causes lock inversion on scheduler locks because printk() can call
into the scheduler. Lockdep puts it as:

 [  728.464312] ====================================================================================================
 [  735.312580] TSC deadline timer enabled
 [  735.324143]
 [  735.324146] ======================================================
 [  735.324148] WARNING: possible circular locking dependency detected
 [  735.324150] 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 #1 Not tainted
 [  735.324152] ------------------------------------------------------
 [  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
 [  735.324171]
 [  735.324173] which lock already depends on the new lock.
 [  735.324174]
 [  735.324175]
 [  735.324177] the existing dependency chain (in reverse order) is:
 [  735.324179]
 [  735.324180] -> #4 (hrtimer_bases.lock){-.-.}-{2:2}:
 [  735.324186]        _raw_spin_lock_irqsave+0x3c/0x4b
 [  735.324187]        lock_hrtimer_base+0x71/0x120
 [  735.324189]        hrtimer_start_range_ns+0xc6/0xaa0
 [  735.324191]        __enqueue_rt_entity+0xc44/0xf50
 [  735.324192]        enqueue_rt_entity+0x79/0xc0
 [  735.324194]        enqueue_task_rt+0x5c/0x2e0
 [  735.324195]        activate_task+0x15a/0x2c0
 [  735.324197]        ttwu_do_activate+0xcf/0x120
 [  735.324199]        sched_ttwu_pending+0x160/0x230
 [  735.324200]        scheduler_ipi+0x1c0/0x530
 [  735.324202]        reschedule_interrupt+0xf/0x20
 [  735.324204]        tick_nohz_idle_enter+0x16c/0x250
 [  735.324205]        do_idle+0x90/0x530
 [  735.324207]        cpu_startup_entry+0x19/0x20
 [  735.324208]        start_secondary+0x2ee/0x3e0
 [  735.324210]        secondary_startup_64+0xa4/0xb0
 [  735.324211]
 [  735.324212] -> #3 (&rt_b->rt_runtime_lock){-...}-{2:2}:
 [  735.324218]        _raw_spin_lock+0x25/0x30
 [  735.324219]        rq_online_rt+0x288/0x550
 [  735.324221]        set_rq_online+0x11f/0x190
 [  735.324223]        sched_cpu_activate+0x1d4/0x390
 [  735.324225]        cpuhp_invoke_callback+0x1c5/0x1560
 [  735.324226]        cpuhp_thread_fun+0x3f8/0x6f0
 [  735.324228]        smpboot_thread_fn+0x305/0x5f0
 [  735.324229]        kthread+0x2f8/0x3b0
 [  735.324231]        ret_from_fork+0x24/0x30
 [  735.324232]
 [  735.324233] -> #2 (&rq->lock){-.-.}-{2:2}:
 [  735.324238]        _raw_spin_lock+0x25/0x30
 [  735.324240]        task_fork_fair+0x34/0x430
 [  735.324241]        sched_fork+0x48a/0xa60
 [  735.324243]        copy_process+0x15df/0x5970
 [  735.324244]        _do_fork+0x106/0xcd0
 [  735.324246]        kernel_thread+0x9e/0xe0
 [  735.324247]        rest_init+0x28/0x330
 [  735.324249]        start_kernel+0x6ac/0x6ed
 [  735.324251]        secondary_startup_64+0xa4/0xb0
 [  735.324252]
 [  735.324253] -> #1 (&p->pi_lock){-.-.}-{2:2}:
 [  735.324258]        _raw_spin_lock_irqsave+0x3c/0x4b
 [  735.324260]        try_to_wake_up+0x9a/0x1700
 [  735.324261]        up+0x7a/0xb0
 [  735.324263]        __up_console_sem+0x3c/0x70
 [  735.324264]        console_unlock+0x4f4/0xab0
 [  735.324266]        con_font_op+0x907/0x1010
 [  735.324267]        vt_ioctl+0x10a6/0x2890
 [  735.324269]        tty_ioctl+0x257/0x1240
 [  735.324270]        ksys_ioctl+0x3e9/0x1190
 [  735.324272]        __x64_sys_ioctl+0x6f/0xb0
 [  735.324273]        do_syscall_64+0xe7/0x12c0
 [  735.324275]        entry_SYSCALL_64_after_hwframe+0x49/0xb3
 [  735.324276]
 [  735.324277] -> #0 ((console_sem).lock){-...}-{2:2}:
 [  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
 [  735.324310]
 [  735.324311] other info that might help us debug this:
 [  735.324312]
 [  735.324314] Chain exists of:
 [  735.324315]   (console_sem).lock --> &rt_b->rt_runtime_lock --> hrtimer_bases.lock
 [  735.324322]
 [  735.324324]  Possible unsafe locking scenario:
 [  735.324325]
 [  735.324327]        CPU0                    CPU1
 [  735.324328]        ----                    ----
 [  735.324329]   lock(hrtimer_bases.lock);
 [  735.324333]                                lock(&rt_b->rt_runtime_lock);
 [  735.324337]                                lock(hrtimer_bases.lock);
 [  735.324341]   lock((console_sem).lock);
 [  735.324344]
 [  735.324345]  *** DEADLOCK ***
 [  735.324346]
 [  735.324348] 1 lock held by swapper/3/0:
 [  735.324349]  #0: ffff88842dfb9958 (hrtimer_bases.lock){-.-.}-{2:2}, at: lock_hrtimer_base+0x71/0x120
 [  735.324356]
 [  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
 [  735.324363] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
 [  735.324364] Call Trace:
 [  735.324366]  dump_stack+0xb7/0x10b
 [  735.324367]  check_noncircular+0x37f/0x460
 [  735.324369]  ? arch_stack_walk+0x7c/0xd0
 [  735.324370]  ? print_circular_bug+0x4e0/0x4e0
 [  735.324372]  ? mark_lock+0x1a4/0xb60
 [  735.324373]  ? __lock_acquire+0x374a/0x5210
 [  735.324375]  __lock_acquire+0x374a/0x5210
 [  735.324376]  ? register_lock_class+0x17e0/0x17e0
 [  735.324378]  ? register_lock_class+0x17e0/0x17e0
 [  735.324380]  lock_acquire+0x1b9/0x920
 [  735.324381]  ? down_trylock+0x13/0x70
 [  735.324383]  ? check_flags.part.29+0x450/0x450
 [  735.324384]  ? lock_downgrade+0x760/0x760
 [  735.324386]  ? vprintk_emit+0xec/0x370
 [  735.324387]  _raw_spin_lock_irqsave+0x3c/0x4b
 [  735.324389]  ? down_trylock+0x13/0x70
 [  735.324390]  down_trylock+0x13/0x70
 [  735.324392]  __down_trylock_console_sem+0x33/0xa0
 [  735.324393]  console_trylock+0x13/0x60
 [  735.324395]  vprintk_emit+0xec/0x370
 [  735.324396]  printk+0x9c/0xc3
 [  735.324398]  ? kmsg_dump_rewind_nolock+0xd9/0xd9
 [  735.324399]  lapic_timer_set_oneshot+0x4e/0x60
 [  735.324401]  clockevents_switch_state+0x1e1/0x360
 [  735.324402]  ? enqueue_hrtimer+0x116/0x310
 [  735.324404]  tick_program_event+0xae/0xc0
 [  735.324406]  hrtimer_start_range_ns+0x4b6/0xaa0
 [  735.324407]  ? hrtimer_run_softirq+0x210/0x210
 [  735.324409]  ? rcu_read_lock_sched_held+0xab/0xe0
 [  735.324410]  ? rcu_read_lock_bh_held+0xe0/0xe0
 [  735.324412]  tick_nohz_idle_stop_tick+0x67c/0xa90
 [  735.324413]  ? tsc_verify_tsc_adjust+0x71/0x290
 [  735.324415]  do_idle+0x326/0x530
 [  735.324416]  ? arch_cpu_idle_exit+0x40/0x40
 [  735.324418]  cpu_startup_entry+0x19/0x20
 [  735.324419]  start_secondary+0x2ee/0x3e0
 [  735.324421]  ? set_cpu_sibling_map+0x2f70/0x2f70
 [  735.324423]  secondary_startup_64+0xa4/0xb0
 [  760.028504] ====================================================================================================

Fix by using deferred variant of printk which doesn't call to the scheduler.

Fixes: 279f1461432c ("x86: apic: Use tsc deadline for oneshot when available")
Signed-off-by: Leon Romanovsky <leonro@mellanox.com>
---
It is far away from my main expertise and I'm not sure that the solution
is correct, but it definitely fixed our regression.
---
 arch/x86/kernel/apic/apic.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index d254cebdd3c3..6706b2cd9aec 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -353,7 +353,7 @@ static void __setup_APIC_LVTT(unsigned int clocks, int oneshot, int irqen)
 		 */
 		asm volatile("mfence" : : : "memory");

-		printk_once(KERN_DEBUG "TSC deadline timer enabled\n");
+		printk_deferred_once(KERN_DEBUG "TSC deadline timer enabled\n");
 		return;
 	}

--
2.25.1

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

[Leon Romanovsky]

Hi,

Any feedback?
https://lore.kernel.org/lkml/20200407170925.1775019-1-leon@kernel.org/

Thanks

On Tue, Apr 07, 2020 at 08:09:25PM +0300, Leon Romanovsky wrote:
> From: Leon Romanovsky <leonro@mellanox.com>
>
> clockevents_switch_state() calls printk() from under hrtimer_bases.lock.
> That causes lock inversion on scheduler locks because printk() can call
> into the scheduler. Lockdep puts it as:
>
>  [  728.464312] ====================================================================================================
>  [  735.312580] TSC deadline timer enabled
>  [  735.324143]
>  [  735.324146] ======================================================
>  [  735.324148] WARNING: possible circular locking dependency detected
>  [  735.324150] 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 #1 Not tainted
>  [  735.324152] ------------------------------------------------------
>  [  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
>  [  735.324171]
>  [  735.324173] which lock already depends on the new lock.
>  [  735.324174]
>  [  735.324175]
>  [  735.324177] the existing dependency chain (in reverse order) is:
>  [  735.324179]
>  [  735.324180] -> #4 (hrtimer_bases.lock){-.-.}-{2:2}:
>  [  735.324186]        _raw_spin_lock_irqsave+0x3c/0x4b
>  [  735.324187]        lock_hrtimer_base+0x71/0x120
>  [  735.324189]        hrtimer_start_range_ns+0xc6/0xaa0
>  [  735.324191]        __enqueue_rt_entity+0xc44/0xf50
>  [  735.324192]        enqueue_rt_entity+0x79/0xc0
>  [  735.324194]        enqueue_task_rt+0x5c/0x2e0
>  [  735.324195]        activate_task+0x15a/0x2c0
>  [  735.324197]        ttwu_do_activate+0xcf/0x120
>  [  735.324199]        sched_ttwu_pending+0x160/0x230
>  [  735.324200]        scheduler_ipi+0x1c0/0x530
>  [  735.324202]        reschedule_interrupt+0xf/0x20
>  [  735.324204]        tick_nohz_idle_enter+0x16c/0x250
>  [  735.324205]        do_idle+0x90/0x530
>  [  735.324207]        cpu_startup_entry+0x19/0x20
>  [  735.324208]        start_secondary+0x2ee/0x3e0
>  [  735.324210]        secondary_startup_64+0xa4/0xb0
>  [  735.324211]
>  [  735.324212] -> #3 (&rt_b->rt_runtime_lock){-...}-{2:2}:
>  [  735.324218]        _raw_spin_lock+0x25/0x30
>  [  735.324219]        rq_online_rt+0x288/0x550
>  [  735.324221]        set_rq_online+0x11f/0x190
>  [  735.324223]        sched_cpu_activate+0x1d4/0x390
>  [  735.324225]        cpuhp_invoke_callback+0x1c5/0x1560
>  [  735.324226]        cpuhp_thread_fun+0x3f8/0x6f0
>  [  735.324228]        smpboot_thread_fn+0x305/0x5f0
>  [  735.324229]        kthread+0x2f8/0x3b0
>  [  735.324231]        ret_from_fork+0x24/0x30
>  [  735.324232]
>  [  735.324233] -> #2 (&rq->lock){-.-.}-{2:2}:
>  [  735.324238]        _raw_spin_lock+0x25/0x30
>  [  735.324240]        task_fork_fair+0x34/0x430
>  [  735.324241]        sched_fork+0x48a/0xa60
>  [  735.324243]        copy_process+0x15df/0x5970
>  [  735.324244]        _do_fork+0x106/0xcd0
>  [  735.324246]        kernel_thread+0x9e/0xe0
>  [  735.324247]        rest_init+0x28/0x330
>  [  735.324249]        start_kernel+0x6ac/0x6ed
>  [  735.324251]        secondary_startup_64+0xa4/0xb0
>  [  735.324252]
>  [  735.324253] -> #1 (&p->pi_lock){-.-.}-{2:2}:
>  [  735.324258]        _raw_spin_lock_irqsave+0x3c/0x4b
>  [  735.324260]        try_to_wake_up+0x9a/0x1700
>  [  735.324261]        up+0x7a/0xb0
>  [  735.324263]        __up_console_sem+0x3c/0x70
>  [  735.324264]        console_unlock+0x4f4/0xab0
>  [  735.324266]        con_font_op+0x907/0x1010
>  [  735.324267]        vt_ioctl+0x10a6/0x2890
>  [  735.324269]        tty_ioctl+0x257/0x1240
>  [  735.324270]        ksys_ioctl+0x3e9/0x1190
>  [  735.324272]        __x64_sys_ioctl+0x6f/0xb0
>  [  735.324273]        do_syscall_64+0xe7/0x12c0
>  [  735.324275]        entry_SYSCALL_64_after_hwframe+0x49/0xb3
>  [  735.324276]
>  [  735.324277] -> #0 ((console_sem).lock){-...}-{2:2}:
>  [  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
>  [  735.324310]
>  [  735.324311] other info that might help us debug this:
>  [  735.324312]
>  [  735.324314] Chain exists of:
>  [  735.324315]   (console_sem).lock --> &rt_b->rt_runtime_lock --> hrtimer_bases.lock
>  [  735.324322]
>  [  735.324324]  Possible unsafe locking scenario:
>  [  735.324325]
>  [  735.324327]        CPU0                    CPU1
>  [  735.324328]        ----                    ----
>  [  735.324329]   lock(hrtimer_bases.lock);
>  [  735.324333]                                lock(&rt_b->rt_runtime_lock);
>  [  735.324337]                                lock(hrtimer_bases.lock);
>  [  735.324341]   lock((console_sem).lock);
>  [  735.324344]
>  [  735.324345]  *** DEADLOCK ***
>  [  735.324346]
>  [  735.324348] 1 lock held by swapper/3/0:
>  [  735.324349]  #0: ffff88842dfb9958 (hrtimer_bases.lock){-.-.}-{2:2}, at: lock_hrtimer_base+0x71/0x120
>  [  735.324356]
>  [  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
>  [  735.324363] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
>  [  735.324364] Call Trace:
>  [  735.324366]  dump_stack+0xb7/0x10b
>  [  735.324367]  check_noncircular+0x37f/0x460
>  [  735.324369]  ? arch_stack_walk+0x7c/0xd0
>  [  735.324370]  ? print_circular_bug+0x4e0/0x4e0
>  [  735.324372]  ? mark_lock+0x1a4/0xb60
>  [  735.324373]  ? __lock_acquire+0x374a/0x5210
>  [  735.324375]  __lock_acquire+0x374a/0x5210
>  [  735.324376]  ? register_lock_class+0x17e0/0x17e0
>  [  735.324378]  ? register_lock_class+0x17e0/0x17e0
>  [  735.324380]  lock_acquire+0x1b9/0x920
>  [  735.324381]  ? down_trylock+0x13/0x70
>  [  735.324383]  ? check_flags.part.29+0x450/0x450
>  [  735.324384]  ? lock_downgrade+0x760/0x760
>  [  735.324386]  ? vprintk_emit+0xec/0x370
>  [  735.324387]  _raw_spin_lock_irqsave+0x3c/0x4b
>  [  735.324389]  ? down_trylock+0x13/0x70
>  [  735.324390]  down_trylock+0x13/0x70
>  [  735.324392]  __down_trylock_console_sem+0x33/0xa0
>  [  735.324393]  console_trylock+0x13/0x60
>  [  735.324395]  vprintk_emit+0xec/0x370
>  [  735.324396]  printk+0x9c/0xc3
>  [  735.324398]  ? kmsg_dump_rewind_nolock+0xd9/0xd9
>  [  735.324399]  lapic_timer_set_oneshot+0x4e/0x60
>  [  735.324401]  clockevents_switch_state+0x1e1/0x360
>  [  735.324402]  ? enqueue_hrtimer+0x116/0x310
>  [  735.324404]  tick_program_event+0xae/0xc0
>  [  735.324406]  hrtimer_start_range_ns+0x4b6/0xaa0
>  [  735.324407]  ? hrtimer_run_softirq+0x210/0x210
>  [  735.324409]  ? rcu_read_lock_sched_held+0xab/0xe0
>  [  735.324410]  ? rcu_read_lock_bh_held+0xe0/0xe0
>  [  735.324412]  tick_nohz_idle_stop_tick+0x67c/0xa90
>  [  735.324413]  ? tsc_verify_tsc_adjust+0x71/0x290
>  [  735.324415]  do_idle+0x326/0x530
>  [  735.324416]  ? arch_cpu_idle_exit+0x40/0x40
>  [  735.324418]  cpu_startup_entry+0x19/0x20
>  [  735.324419]  start_secondary+0x2ee/0x3e0
>  [  735.324421]  ? set_cpu_sibling_map+0x2f70/0x2f70
>  [  735.324423]  secondary_startup_64+0xa4/0xb0
>  [  760.028504] ====================================================================================================
>
> Fix by using deferred variant of printk which doesn't call to the scheduler.
>
> Fixes: 279f1461432c ("x86: apic: Use tsc deadline for oneshot when available")
> Signed-off-by: Leon Romanovsky <leonro@mellanox.com>
> ---
> It is far away from my main expertise and I'm not sure that the solution
> is correct, but it definitely fixed our regression.
> ---
>  arch/x86/kernel/apic/apic.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> index d254cebdd3c3..6706b2cd9aec 100644
> --- a/arch/x86/kernel/apic/apic.c
> +++ b/arch/x86/kernel/apic/apic.c
> @@ -353,7 +353,7 @@ static void __setup_APIC_LVTT(unsigned int clocks, int oneshot, int irqen)
>  		 */
>  		asm volatile("mfence" : : : "memory");
>
> -		printk_once(KERN_DEBUG "TSC deadline timer enabled\n");
> +		printk_deferred_once(KERN_DEBUG "TSC deadline timer enabled\n");
>  		return;
>  	}
>
> --
> 2.25.1
>

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

[Ingo Molnar]

* Leon Romanovsky <leon@kernel.org> wrote:

> Hi,
> 
> Any feedback?
> https://lore.kernel.org/lkml/20200407170925.1775019-1-leon@kernel.org/

The fix definitely looks legit, lockdep is right that we shouldn't take 
the console_sem.lock even under trylock.

It's only a printk_once(), yet I'm wondering why in the last ~8 years 
this never triggered. Nobody ever ran lockdep and debug console level 
enabled on such hardware, or did something else change?

One possibility would be that apic_check_deadline_errata() marked almost 
all Intel systems as broken and the TSC-deadline hardware never actually 
got activated. In that case you have triggered rarely tested code and 
might see other weirdnesses. Just saying. :-)

Or a bootup with "debug" specified is much more rare in production 
systems, hence the 8 years old bug.

> > It is far away from my main expertise and I'm not sure that the solution
> > is correct, but it definitely fixed our regression.
> > ---
> >  arch/x86/kernel/apic/apic.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> > index d254cebdd3c3..6706b2cd9aec 100644
> > --- a/arch/x86/kernel/apic/apic.c
> > +++ b/arch/x86/kernel/apic/apic.c
> > @@ -353,7 +353,7 @@ static void __setup_APIC_LVTT(unsigned int clocks, int oneshot, int irqen)
> >  		 */
> >  		asm volatile("mfence" : : : "memory");
> >
> > -		printk_once(KERN_DEBUG "TSC deadline timer enabled\n");
> > +		printk_deferred_once(KERN_DEBUG "TSC deadline timer enabled\n");

I think we should move this essentially initialization-time message much 
earlier during bootup, when we are not holding any hrtimer locks.

One good place would be apic_check_deadline_errata(). This place:

        if (boot_cpu_data.microcode >= rev)
                return;

        setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
        pr_err(FW_BUG "TSC_DEADLINE disabled due to Errata; "
               "please update microcode to version: 0x%x (or later)\n", rev);

Could be something like:

        if (boot_cpu_data.microcode >= rev) {
		pr_debug("x86/apic: TSC deadline timer enabled.\n");
                return;
	}

        setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
        pr_err(FW_BUG "TSC_DEADLINE disabled due to CPU errata, please update microcode to version: 0x%x (or later)\n", rev);

(Note the small fixes I did to the errata message - we should do that and 
also move all user-facing messages into a single line while at it.)

Thanks,

	Ingo

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

[Leon Romanovsky]

On Tue, Apr 14, 2020 at 08:24:54AM +0200, Ingo Molnar wrote:
>
> * Leon Romanovsky <leon@kernel.org> wrote:
>
> > Hi,
> >
> > Any feedback?
> > https://lore.kernel.org/lkml/20200407170925.1775019-1-leon@kernel.org/
>
> The fix definitely looks legit, lockdep is right that we shouldn't take
> the console_sem.lock even under trylock.
>
> It's only a printk_once(), yet I'm wondering why in the last ~8 years
> this never triggered. Nobody ever ran lockdep and debug console level
> enabled on such hardware, or did something else change?
>
> One possibility would be that apic_check_deadline_errata() marked almost
> all Intel systems as broken and the TSC-deadline hardware never actually
> got activated. In that case you have triggered rarely tested code and
> might see other weirdnesses. Just saying. :-)

It is hard to say what was changed, but after -rc1, we started to see
those lockdep splats almost in every run.

But if we are talking about other weirdnesses, I have another splat in my
QEMU machine, which is different, but from the same code area.

[    1.383968] ACPI: Added _OSI(Module Device)
[    1.385684] ACPI: Added _OSI(Processor Device)
[    1.389345] ACPI: Added _OSI(3.0 _SCP Extensions)
[    1.389345] ACPI: Added _OSI(Processor Aggregator Device)
[    1.393454] ACPI: Added _OSI(Linux-Dell-Video)
[    1.394920] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    1.396481] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    1.793418] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    1.845452]
[    1.846768] =============================
[    1.849293] [ BUG: Invalid wait context ]
[    1.849293] 5.7.0-rc1+ #1229 Not tainted
[    1.849293] -----------------------------
[    1.849293] swapper/1/0 is trying to lock:
[    1.849293] ffff88806c8a4418 (&n->list_lock){-...}-{3:3}, at: deactivate_slab.isra.0+0x304/0x6d0
[    1.849293] other info that might help us debug this:
[    1.849293] context-{2:2}
[    1.849293] 1 lock held by swapper/1/0:
[    1.849293]  #0: ffffffff826cb000 (rcu_callback){....}-{0:0}, at: rcu_core+0x317/0x9e0
[    1.849293] stack backtrace:
[    1.849293] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.7.0-rc1+ #1229
[    1.849293] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 0
4/01/2014
[    1.849293] Call Trace:
[    1.849293]  <IRQ>
[    1.849293]  dump_stack+0x97/0xe0
[    1.849293]  __lock_acquire.cold+0xd6/0x354
[    1.849293]  ? sched_clock_cpu+0x11f/0x140
[    1.849293]  ? mark_held_locks+0x90/0x90
[    1.849293]  ? __lock_acquire+0x8bf/0x3800
[    1.849293]  lock_acquire+0x155/0x4f0
[    1.849293]  ? deactivate_slab.isra.0+0x304/0x6d0
[    1.849293]  ? lock_release+0x660/0x660
[    1.849293]  ? sched_clock_local+0x99/0xc0
[    1.849293]  ? sched_clock_cpu+0x11f/0x140
[    1.849293]  _raw_spin_lock+0x31/0x80
[    1.849293]  ? deactivate_slab.isra.0+0x304/0x6d0
[    1.849293]  deactivate_slab.isra.0+0x304/0x6d0
[    1.849293]  ? pvclock_clocksource_read+0xd9/0x190
[    1.849293]  ? slub_cpu_dead+0xd0/0xd0
[    1.849293]  flush_cpu_slab+0x36/0x50
[    1.849293]  flush_smp_call_function_queue+0xc2/0x1e0
[    1.849293]  smp_call_function_interrupt+0x93/0x2f0
[    1.849293]  call_function_interrupt+0xf/0x20
[    1.849293] RIP: 0010:quarantine_put+0xba/0x150
[    1.849293] Code: e8 bb bb ec ff 48 8b 44 24 18 65 48 33 04 25 28 00 00 00 0f 85 a0 00 00 00 48 83 c4 20 5b 5d 41 5
c c3 e8 39 b8 ec ff 41 54 9d <eb> d9 48 89 e6 e8 cc fe ff ff 48 c7 c7 60 e3 76 82 e8 c0 f3 6b 00
[    1.849293] RSP: 0000:ffff88806d209db0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff03
[    1.849293] RAX: 0000000000000000 RBX: ffff88806be33658 RCX: dffffc0000000000
[    1.849293] RDX: 0000000000000007 RSI: 0000000000000002 RDI: ffff88806cb5876c
[    1.849293] RBP: ffff88806c80de00 R08: ffffffff811656ed R09: 0000000000000000
[    1.849293] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000246
[    1.849293] R13: ffff88806c80de00 R14: 0000000000000206 R15: 0000000000000000
[    1.849293]  ? call_function_interrupt+0xa/0x20
[    1.849293]  ? lockdep_hardirqs_on+0x17d/0x270
[    1.849293]  __kasan_slab_free+0x144/0x180
[    1.849293]  ? rcu_core+0x35c/0x9e0
[    1.849293]  kmem_cache_free+0xc6/0x370
[    1.849293]  ? migrate_pages+0xa70/0xa70
[    1.849293]  rcu_core+0x35c/0x9e0
[    1.849293]  ? rcu_core+0x317/0x9e0
[    1.849293]  ? rcu_note_context_switch+0x300/0x300
[    1.849293]  ? rcu_read_lock_sched_held+0xa1/0xd0
[    1.849293]  ? rcu_read_lock_bh_held+0xb0/0xb0
[    1.849293]  ? run_rebalance_domains+0x11d/0x140
[    1.849293]  __do_softirq+0x11c/0x612
[    1.849293]  ? rcu_read_lock_bh_held+0xb0/0xb0
[    1.849293]  irq_exit+0xfb/0x100
[    1.849293]  smp_apic_timer_interrupt+0x12e/0x360
[    1.849293]  apic_timer_interrupt+0xf/0x20
[    1.849293]  </IRQ>
[    1.849293] RIP: 0010:default_idle+0x6e/0x250
[    1.849293] Code: c7 c7 40 11 01 83 e8 f1 ec 93 ff 48 c7 c7 40 11 01 83 e8 b5 0c 94 ff 8b 05 6f a8 5f 01 85 c0 7e 0
7 0f 00 2d 84 f4 5f 00 fb f4 <be> 04 00 00 00 48 c7 c7 c8 bc 98 82 65 8b 2d 4f 48 60 7e e8 ba ec
[    1.849293] RSP: 0000:ffff88806cb67dc8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
[    1.849293] RAX: 0000000000000000 RBX: ffff88806cb58000 RCX: dffffc0000000000
[    1.849293] RDX: 0000000000000003 RSI: 0000000000000004 RDI: ffffffff83011140
[    1.849293] RBP: 0000000000000001 R08: ffffffff81a168cb R09: fffffbfff0602229
[    1.849293] R10: 0000000000000003 R11: fffffbfff0602228 R12: ffffffff829a13f0
[    1.849293] R13: 0000000000000000 R14: ffff88806cb58000 R15: 0000000000000000
[    1.849293]  ? default_idle+0x5b/0x250
[    1.849293]  ? default_idle+0x5b/0x250
[    1.849293]  do_idle+0x321/0x380
[    1.849293]  ? arch_cpu_idle_exit+0x40/0x40
[    1.849293]  ? mark_held_locks+0x1d/0x90
[    1.849293]  ? _raw_spin_unlock_irqrestore+0x3e/0x50
[    1.849293]  cpu_startup_entry+0x19/0x20
[    1.849293]  start_secondary+0x214/0x280
[    1.849293]  ? set_cpu_sibling_map+0x9e0/0x9e0
[    1.849293]  secondary_startup_64+0xa4/0xb0
[    2.093362] ACPI: Interpreter enabled

>
> Or a bootup with "debug" specified is much more rare in production
> systems, hence the 8 years old bug.
>
> > > It is far away from my main expertise and I'm not sure that the solution
> > > is correct, but it definitely fixed our regression.
> > > ---
> > >  arch/x86/kernel/apic/apic.c | 2 +-
> > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > >
> > > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> > > index d254cebdd3c3..6706b2cd9aec 100644
> > > --- a/arch/x86/kernel/apic/apic.c
> > > +++ b/arch/x86/kernel/apic/apic.c
> > > @@ -353,7 +353,7 @@ static void __setup_APIC_LVTT(unsigned int clocks, int oneshot, int irqen)
> > >  		 */
> > >  		asm volatile("mfence" : : : "memory");
> > >
> > > -		printk_once(KERN_DEBUG "TSC deadline timer enabled\n");
> > > +		printk_deferred_once(KERN_DEBUG "TSC deadline timer enabled\n");
>
> I think we should move this essentially initialization-time message much
> earlier during bootup, when we are not holding any hrtimer locks.
>
> One good place would be apic_check_deadline_errata(). This place:
>
>         if (boot_cpu_data.microcode >= rev)
>                 return;
>
>         setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
>         pr_err(FW_BUG "TSC_DEADLINE disabled due to Errata; "
>                "please update microcode to version: 0x%x (or later)\n", rev);
>
> Could be something like:
>
>         if (boot_cpu_data.microcode >= rev) {
> 		pr_debug("x86/apic: TSC deadline timer enabled.\n");
>                 return;
> 	}
>
>         setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
>         pr_err(FW_BUG "TSC_DEADLINE disabled due to CPU errata, please update microcode to version: 0x%x (or later)\n", rev);

I don't know what is x2apic_mode, but won't x2apic_mode == 1 prevent from setting timer?
If yes, we will print "enabled" message too early.

2091 void __init init_apic_mappings(void)
<...>
2095         apic_check_deadline_errata();
2096
2097         if (x2apic_mode) {
2098                 boot_cpu_physical_apicid = read_apic_id();
2099                 return;
2100         }

>
> (Note the small fixes I did to the errata message - we should do that and
> also move all user-facing messages into a single line while at it.)
>
> Thanks,
>
> 	Ingo

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

[Leon Romanovsky]

On Tue, Apr 14, 2020 at 10:05:02AM +0300, Leon Romanovsky wrote:
> On Tue, Apr 14, 2020 at 08:24:54AM +0200, Ingo Molnar wrote:
> >
> > * Leon Romanovsky <leon@kernel.org> wrote:
> >
> > > Hi,
> > >
> > > Any feedback?
> > > https://lore.kernel.org/lkml/20200407170925.1775019-1-leon@kernel.org/
> >
> > The fix definitely looks legit, lockdep is right that we shouldn't take
> > the console_sem.lock even under trylock.
> >
> > It's only a printk_once(), yet I'm wondering why in the last ~8 years
> > this never triggered. Nobody ever ran lockdep and debug console level
> > enabled on such hardware, or did something else change?
> >
> > One possibility would be that apic_check_deadline_errata() marked almost
> > all Intel systems as broken and the TSC-deadline hardware never actually
> > got activated. In that case you have triggered rarely tested code and
> > might see other weirdnesses. Just saying. :-)
>
> It is hard to say what was changed, but after -rc1, we started to see
> those lockdep splats almost in every run.

Anything that I can help to speed up this patch?
Are you expecting anything from me that I missed to do?

Our regression is flooded with ACPI splats.

Thanks

>
> But if we are talking about other weirdnesses, I have another splat in my
> QEMU machine, which is different, but from the same code area.
>
> [    1.383968] ACPI: Added _OSI(Module Device)
> [    1.385684] ACPI: Added _OSI(Processor Device)
> [    1.389345] ACPI: Added _OSI(3.0 _SCP Extensions)
> [    1.389345] ACPI: Added _OSI(Processor Aggregator Device)
> [    1.393454] ACPI: Added _OSI(Linux-Dell-Video)
> [    1.394920] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
> [    1.396481] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
> [    1.793418] ACPI: 1 ACPI AML tables successfully acquired and loaded
> [    1.845452]
> [    1.846768] =============================
> [    1.849293] [ BUG: Invalid wait context ]
> [    1.849293] 5.7.0-rc1+ #1229 Not tainted
> [    1.849293] -----------------------------
> [    1.849293] swapper/1/0 is trying to lock:
> [    1.849293] ffff88806c8a4418 (&n->list_lock){-...}-{3:3}, at: deactivate_slab.isra.0+0x304/0x6d0
> [    1.849293] other info that might help us debug this:
> [    1.849293] context-{2:2}
> [    1.849293] 1 lock held by swapper/1/0:
> [    1.849293]  #0: ffffffff826cb000 (rcu_callback){....}-{0:0}, at: rcu_core+0x317/0x9e0
> [    1.849293] stack backtrace:
> [    1.849293] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.7.0-rc1+ #1229
> [    1.849293] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 0
> 4/01/2014
> [    1.849293] Call Trace:
> [    1.849293]  <IRQ>
> [    1.849293]  dump_stack+0x97/0xe0
> [    1.849293]  __lock_acquire.cold+0xd6/0x354
> [    1.849293]  ? sched_clock_cpu+0x11f/0x140
> [    1.849293]  ? mark_held_locks+0x90/0x90
> [    1.849293]  ? __lock_acquire+0x8bf/0x3800
> [    1.849293]  lock_acquire+0x155/0x4f0
> [    1.849293]  ? deactivate_slab.isra.0+0x304/0x6d0
> [    1.849293]  ? lock_release+0x660/0x660
> [    1.849293]  ? sched_clock_local+0x99/0xc0
> [    1.849293]  ? sched_clock_cpu+0x11f/0x140
> [    1.849293]  _raw_spin_lock+0x31/0x80
> [    1.849293]  ? deactivate_slab.isra.0+0x304/0x6d0
> [    1.849293]  deactivate_slab.isra.0+0x304/0x6d0
> [    1.849293]  ? pvclock_clocksource_read+0xd9/0x190
> [    1.849293]  ? slub_cpu_dead+0xd0/0xd0
> [    1.849293]  flush_cpu_slab+0x36/0x50
> [    1.849293]  flush_smp_call_function_queue+0xc2/0x1e0
> [    1.849293]  smp_call_function_interrupt+0x93/0x2f0
> [    1.849293]  call_function_interrupt+0xf/0x20
> [    1.849293] RIP: 0010:quarantine_put+0xba/0x150
> [    1.849293] Code: e8 bb bb ec ff 48 8b 44 24 18 65 48 33 04 25 28 00 00 00 0f 85 a0 00 00 00 48 83 c4 20 5b 5d 41 5
> c c3 e8 39 b8 ec ff 41 54 9d <eb> d9 48 89 e6 e8 cc fe ff ff 48 c7 c7 60 e3 76 82 e8 c0 f3 6b 00
> [    1.849293] RSP: 0000:ffff88806d209db0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff03
> [    1.849293] RAX: 0000000000000000 RBX: ffff88806be33658 RCX: dffffc0000000000
> [    1.849293] RDX: 0000000000000007 RSI: 0000000000000002 RDI: ffff88806cb5876c
> [    1.849293] RBP: ffff88806c80de00 R08: ffffffff811656ed R09: 0000000000000000
> [    1.849293] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000246
> [    1.849293] R13: ffff88806c80de00 R14: 0000000000000206 R15: 0000000000000000
> [    1.849293]  ? call_function_interrupt+0xa/0x20
> [    1.849293]  ? lockdep_hardirqs_on+0x17d/0x270
> [    1.849293]  __kasan_slab_free+0x144/0x180
> [    1.849293]  ? rcu_core+0x35c/0x9e0
> [    1.849293]  kmem_cache_free+0xc6/0x370
> [    1.849293]  ? migrate_pages+0xa70/0xa70
> [    1.849293]  rcu_core+0x35c/0x9e0
> [    1.849293]  ? rcu_core+0x317/0x9e0
> [    1.849293]  ? rcu_note_context_switch+0x300/0x300
> [    1.849293]  ? rcu_read_lock_sched_held+0xa1/0xd0
> [    1.849293]  ? rcu_read_lock_bh_held+0xb0/0xb0
> [    1.849293]  ? run_rebalance_domains+0x11d/0x140
> [    1.849293]  __do_softirq+0x11c/0x612
> [    1.849293]  ? rcu_read_lock_bh_held+0xb0/0xb0
> [    1.849293]  irq_exit+0xfb/0x100
> [    1.849293]  smp_apic_timer_interrupt+0x12e/0x360
> [    1.849293]  apic_timer_interrupt+0xf/0x20
> [    1.849293]  </IRQ>
> [    1.849293] RIP: 0010:default_idle+0x6e/0x250
> [    1.849293] Code: c7 c7 40 11 01 83 e8 f1 ec 93 ff 48 c7 c7 40 11 01 83 e8 b5 0c 94 ff 8b 05 6f a8 5f 01 85 c0 7e 0
> 7 0f 00 2d 84 f4 5f 00 fb f4 <be> 04 00 00 00 48 c7 c7 c8 bc 98 82 65 8b 2d 4f 48 60 7e e8 ba ec
> [    1.849293] RSP: 0000:ffff88806cb67dc8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
> [    1.849293] RAX: 0000000000000000 RBX: ffff88806cb58000 RCX: dffffc0000000000
> [    1.849293] RDX: 0000000000000003 RSI: 0000000000000004 RDI: ffffffff83011140
> [    1.849293] RBP: 0000000000000001 R08: ffffffff81a168cb R09: fffffbfff0602229
> [    1.849293] R10: 0000000000000003 R11: fffffbfff0602228 R12: ffffffff829a13f0
> [    1.849293] R13: 0000000000000000 R14: ffff88806cb58000 R15: 0000000000000000
> [    1.849293]  ? default_idle+0x5b/0x250
> [    1.849293]  ? default_idle+0x5b/0x250
> [    1.849293]  do_idle+0x321/0x380
> [    1.849293]  ? arch_cpu_idle_exit+0x40/0x40
> [    1.849293]  ? mark_held_locks+0x1d/0x90
> [    1.849293]  ? _raw_spin_unlock_irqrestore+0x3e/0x50
> [    1.849293]  cpu_startup_entry+0x19/0x20
> [    1.849293]  start_secondary+0x214/0x280
> [    1.849293]  ? set_cpu_sibling_map+0x9e0/0x9e0
> [    1.849293]  secondary_startup_64+0xa4/0xb0
> [    2.093362] ACPI: Interpreter enabled
>
> >
> > Or a bootup with "debug" specified is much more rare in production
> > systems, hence the 8 years old bug.
> >
> > > > It is far away from my main expertise and I'm not sure that the solution
> > > > is correct, but it definitely fixed our regression.
> > > > ---
> > > >  arch/x86/kernel/apic/apic.c | 2 +-
> > > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > > >
> > > > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> > > > index d254cebdd3c3..6706b2cd9aec 100644
> > > > --- a/arch/x86/kernel/apic/apic.c
> > > > +++ b/arch/x86/kernel/apic/apic.c
> > > > @@ -353,7 +353,7 @@ static void __setup_APIC_LVTT(unsigned int clocks, int oneshot, int irqen)
> > > >  		 */
> > > >  		asm volatile("mfence" : : : "memory");
> > > >
> > > > -		printk_once(KERN_DEBUG "TSC deadline timer enabled\n");
> > > > +		printk_deferred_once(KERN_DEBUG "TSC deadline timer enabled\n");
> >
> > I think we should move this essentially initialization-time message much
> > earlier during bootup, when we are not holding any hrtimer locks.
> >
> > One good place would be apic_check_deadline_errata(). This place:
> >
> >         if (boot_cpu_data.microcode >= rev)
> >                 return;
> >
> >         setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
> >         pr_err(FW_BUG "TSC_DEADLINE disabled due to Errata; "
> >                "please update microcode to version: 0x%x (or later)\n", rev);
> >
> > Could be something like:
> >
> >         if (boot_cpu_data.microcode >= rev) {
> > 		pr_debug("x86/apic: TSC deadline timer enabled.\n");
> >                 return;
> > 	}
> >
> >         setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
> >         pr_err(FW_BUG "TSC_DEADLINE disabled due to CPU errata, please update microcode to version: 0x%x (or later)\n", rev);
>
> I don't know what is x2apic_mode, but won't x2apic_mode == 1 prevent from setting timer?
> If yes, we will print "enabled" message too early.
>
> 2091 void __init init_apic_mappings(void)
> <...>
> 2095         apic_check_deadline_errata();
> 2096
> 2097         if (x2apic_mode) {
> 2098                 boot_cpu_physical_apicid = read_apic_id();
> 2099                 return;
> 2100         }
>
> >
> > (Note the small fixes I did to the errata message - we should do that and
> > also move all user-facing messages into a single line while at it.)
> >
> > Thanks,
> >
> > 	Ingo

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

[Thomas Gleixner]

Leon Romanovsky <leon@kernel.org> writes:
> But if we are talking about other weirdnesses, I have another splat in my
> QEMU machine, which is different, but from the same code area.

It's a completely different code area, really. This triggers in
deactivate_slab().

> [    1.383968] ACPI: Added _OSI(Module Device)
> [    1.385684] ACPI: Added _OSI(Processor Device)
> [    1.389345] ACPI: Added _OSI(3.0 _SCP Extensions)
> [    1.389345] ACPI: Added _OSI(Processor Aggregator Device)
> [    1.393454] ACPI: Added _OSI(Linux-Dell-Video)
> [    1.394920] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
> [    1.396481] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
> [    1.793418] ACPI: 1 ACPI AML tables successfully acquired and loaded
> [    1.845452]
> [    1.846768] =============================
> [    1.849293] [ BUG: Invalid wait context ]

Do you have CONFIG_PROVE_RAW_LOCK_NESTING enabled? If yes, please
disable it. The Kconfig option explains that this will trigger
splats.

If not, then this is mysterious but has absolutely nothing to do with
the other thing. It's also completely unrelated to ACPI ...

Thanks,

        tglx

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

[Leon Romanovsky]

On Mon, Apr 27, 2020 at 05:35:18PM +0200, Thomas Gleixner wrote:
> Leon Romanovsky <leon@kernel.org> writes:
> > But if we are talking about other weirdnesses, I have another splat in my
> > QEMU machine, which is different, but from the same code area.
>
> It's a completely different code area, really. This triggers in
> deactivate_slab().
>
> > [    1.383968] ACPI: Added _OSI(Module Device)
> > [    1.385684] ACPI: Added _OSI(Processor Device)
> > [    1.389345] ACPI: Added _OSI(3.0 _SCP Extensions)
> > [    1.389345] ACPI: Added _OSI(Processor Aggregator Device)
> > [    1.393454] ACPI: Added _OSI(Linux-Dell-Video)
> > [    1.394920] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
> > [    1.396481] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
> > [    1.793418] ACPI: 1 ACPI AML tables successfully acquired and loaded
> > [    1.845452]
> > [    1.846768] =============================
> > [    1.849293] [ BUG: Invalid wait context ]
>
> Do you have CONFIG_PROVE_RAW_LOCK_NESTING enabled? If yes, please
> disable it. The Kconfig option explains that this will trigger
> splats.

Yes, I have it enabled.

Thanks for the tip.

>
> If not, then this is mysterious but has absolutely nothing to do with
> the other thing. It's also completely unrelated to ACPI ...
>
> Thanks,
>
>         tglx

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

[Thomas Gleixner]

Ingo Molnar <mingo@kernel.org> writes:
> * Leon Romanovsky <leon@kernel.org> wrote:
> The fix definitely looks legit, lockdep is right that we shouldn't take 
> the console_sem.lock even under trylock.
>
> It's only a printk_once(), yet I'm wondering why in the last ~8 years 
> this never triggered. Nobody ever ran lockdep and debug console level 
> enabled on such hardware, or did something else change?
>
> One possibility would be that apic_check_deadline_errata() marked almost 
> all Intel systems as broken and the TSC-deadline hardware never actually 
> got activated. In that case you have triggered rarely tested code and 
> might see other weirdnesses. Just saying. :-)
>
> Or a bootup with "debug" specified is much more rare in production 
> systems, hence the 8 years old bug.

None of this makes any sense at all.

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.

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.

Thanks,

        tglx

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

[Leon Romanovsky]

On Mon, Apr 27, 2020 at 01:09:49PM +0200, Thomas Gleixner wrote:
> Ingo Molnar <mingo@kernel.org> writes:
> > * Leon Romanovsky <leon@kernel.org> wrote:
> > The fix definitely looks legit, lockdep is right that we shouldn't take
> > the console_sem.lock even under trylock.
> >
> > It's only a printk_once(), yet I'm wondering why in the last ~8 years
> > this never triggered. Nobody ever ran lockdep and debug console level
> > enabled on such hardware, or did something else change?
> >
> > One possibility would be that apic_check_deadline_errata() marked almost
> > all Intel systems as broken and the TSC-deadline hardware never actually
> > got activated. In that case you have triggered rarely tested code and
> > might see other weirdnesses. Just saying. :-)
> >
> > Or a bootup with "debug" specified is much more rare in production
> > systems, hence the 8 years old bug.
>
> None of this makes any sense at all.
>
> 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?

>
> 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.

But let's talk about facts:
1. It is started after -rc1 (we don't test linux-next).
2. This workaround helped to eliminate the splat.
3. My machine experiences the extra splat all the time
https://lore.kernel.org/lkml/20200414070502.GR334007@unreal/

Unfortunately, I can't bisect because the failure mentioned in the
commit message because it  doesn't happen on one machine all the time,
but when we are talking about night run regression, at least one of the
runners hits such lockdep prints.

I can add to our regression any debug patch and get results day after,
if it helps.

Thanks

>
> Thanks,
>
>         tglx

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

[Thomas Gleixner]

Leon Romanovsky <leon@kernel.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?

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?

> 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?

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

> 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

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

[Leon Romanovsky]

[-- Attachment #1: Type: text/plain, Size: 4569 bytes --]

On Mon, Apr 27, 2020 at 02:59:00PM +0200, Thomas Gleixner wrote:
> Leon Romanovsky <leon@kernel.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

[-- Attachment #2: bug_2131735 --]
[-- Type: text/plain, Size: 53071 bytes --]

[    0.000000] Linux version 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 (jenkins@281120a7fa96) (gcc version 7.3.1 20180130 (Red Hat 7.3.1-2) (GCC)) #1 SMP Fri Apr 3 07:53:30 UTC 2020
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 root=UUID=d6ebbea4-17a0-43ef-b491-695fef2aeb1c ro net.ifnames=0 biosdevname=0 console=tty0 console=ttyS1,115200 audit=0
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x008: 'MPX bounds registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x010: 'MPX CSR'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x020: 'AVX-512 opmask'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x040: 'AVX-512 Hi256'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x080: 'AVX-512 ZMM_Hi256'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x200: 'Protection Keys User registers'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: xstate_offset[3]:  832, xstate_sizes[3]:   64
[    0.000000] x86/fpu: xstate_offset[4]:  896, xstate_sizes[4]:   64
[    0.000000] x86/fpu: xstate_offset[5]:  960, xstate_sizes[5]:   64
[    0.000000] x86/fpu: xstate_offset[6]: 1024, xstate_sizes[6]:  512
[    0.000000] x86/fpu: xstate_offset[7]: 1536, xstate_sizes[7]: 1024
[    0.000000] x86/fpu: xstate_offset[9]: 2560, xstate_sizes[9]:    8
[    0.000000] x86/fpu: Enabled xstate features 0x2ff, context size is 2568 bytes, using 'compacted' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007ffddfff] usable
[    0.000000] BIOS-e820: [mem 0x000000007ffde000-0x000000007fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000047fffffff] usable
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.8 present.
[    0.000000] DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
[    0.000000] Hypervisor detected: KVM
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000001] kvm-clock: cpu 0, msr 599c001, primary cpu clock
[    0.000001] kvm-clock: using sched offset of 25664996450613 cycles
[    0.000013] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000029] tsc: Detected 2294.614 MHz processor
[    0.002225] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.002229] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.002237] last_pfn = 0x480000 max_arch_pfn = 0x400000000
[    0.002280] MTRR default type: write-back
[    0.002282] MTRR fixed ranges enabled:
[    0.002285]   00000-9FFFF write-back
[    0.002288]   A0000-BFFFF uncachable
[    0.002291]   C0000-FFFFF write-protect
[    0.002293] MTRR variable ranges enabled:
[    0.002296]   0 base 00C0000000 mask FFC0000000 uncachable
[    0.002298]   1 disabled
[    0.002301]   2 disabled
[    0.002303]   3 disabled
[    0.002305]   4 disabled
[    0.002307]   5 disabled
[    0.002309]   6 disabled
[    0.002311]   7 disabled
[    0.002335] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT  
[    0.002355] last_pfn = 0x7ffde max_arch_pfn = 0x400000000
[    0.004933] Using GB pages for direct mapping
[    0.004945] BRK [0x07401000, 0x07401fff] PGTABLE
[    0.004948] BRK [0x07402000, 0x07402fff] PGTABLE
[    0.004951] BRK [0x07403000, 0x07403fff] PGTABLE
[    0.005567] RAMDISK: [mem 0x362f1000-0x37170fff]
[    0.005588] ACPI: Early table checksum verification disabled
[    0.005620] ACPI: RSDP 0x00000000000F59F0 000014 (v00 BOCHS )
[    0.005629] ACPI: RSDT 0x000000007FFE2014 000034 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
[    0.005648] ACPI: FACP 0x000000007FFE1DEC 0000F4 (v03 BOCHS  BXPCFACP 00000001 BXPC 00000001)
[    0.005667] ACPI: DSDT 0x000000007FFDFC40 0021AC (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
[    0.005675] ACPI: FACS 0x000000007FFDFC00 000040
[    0.005683] ACPI: APIC 0x000000007FFE1EE0 0000C0 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
[    0.005691] ACPI: HPET 0x000000007FFE1FA0 000038 (v01 BOCHS  BXPCHPET 00000001 BXPC 00000001)
[    0.005699] ACPI: MCFG 0x000000007FFE1FD8 00003C (v01 BOCHS  BXPCMCFG 00000001 BXPC 00000001)
[    0.005719] ACPI: Local APIC address 0xfee00000
[    0.006053] No NUMA configuration found
[    0.006057] Faking a node at [mem 0x0000000000000000-0x000000047fffffff]
[    0.006093] NODE_DATA(0) allocated [mem 0x47ffdc000-0x47fffdfff]
[    0.006219] Zone ranges:
[    0.006223]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.006228]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
[    0.006232]   Normal   [mem 0x0000000100000000-0x000000047fffffff]
[    0.006236] Movable zone start for each node
[    0.006243] Early memory node ranges
[    0.006247]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.006251]   node   0: [mem 0x0000000000100000-0x000000007ffddfff]
[    0.006255]   node   0: [mem 0x0000000100000000-0x000000047fffffff]
[    0.006279] Zeroed struct page in unavailable ranges: 132 pages
[    0.006281] Initmem setup node 0 [mem 0x0000000000001000-0x000000047fffffff]
[    0.006287] On node 0 totalpages: 4194172
[    0.006293]   DMA zone: 64 pages used for memmap
[    0.006295]   DMA zone: 21 pages reserved
[    0.006298]   DMA zone: 3998 pages, LIFO batch:0
[    0.006479]   DMA32 zone: 8128 pages used for memmap
[    0.006481]   DMA32 zone: 520158 pages, LIFO batch:63
[    0.027897]   Normal zone: 57344 pages used for memmap
[    0.027901]   Normal zone: 3670016 pages, LIFO batch:63
[    0.398641] kasan: KernelAddressSanitizer initialized
[    0.401443] ACPI: PM-Timer IO Port: 0x608
[    0.401451] ACPI: Local APIC address 0xfee00000
[    0.401473] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.401538] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.401553] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.401559] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.401563] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.401573] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.401578] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.401583] ACPI: IRQ0 used by override.
[    0.401586] ACPI: IRQ5 used by override.
[    0.401589] ACPI: IRQ9 used by override.
[    0.401592] ACPI: IRQ10 used by override.
[    0.401594] ACPI: IRQ11 used by override.
[    0.401599] Using ACPI (MADT) for SMP configuration information
[    0.401604] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.401626] smpboot: Allowing 10 CPUs, 0 hotplug CPUs
[    0.401658] KVM setup pv remote TLB flush
[    0.401713] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.401719] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.401723] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff]
[    0.401727] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[    0.401733] PM: hibernation: Registered nosave memory: [mem 0x7ffde000-0x7fffffff]
[    0.401737] PM: hibernation: Registered nosave memory: [mem 0x80000000-0xafffffff]
[    0.401741] PM: hibernation: Registered nosave memory: [mem 0xb0000000-0xbfffffff]
[    0.401745] PM: hibernation: Registered nosave memory: [mem 0xc0000000-0xfed1bfff]
[    0.401749] PM: hibernation: Registered nosave memory: [mem 0xfed1c000-0xfed1ffff]
[    0.401752] PM: hibernation: Registered nosave memory: [mem 0xfed20000-0xfeffbfff]
[    0.401756] PM: hibernation: Registered nosave memory: [mem 0xfeffc000-0xfeffffff]
[    0.401760] PM: hibernation: Registered nosave memory: [mem 0xff000000-0xfffbffff]
[    0.401764] PM: hibernation: Registered nosave memory: [mem 0xfffc0000-0xffffffff]
[    0.401775] [mem 0xc0000000-0xfed1bfff] available for PCI devices
[    0.401779] Booting paravirtualized kernel on KVM
[    0.401794] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.446614] setup_percpu: NR_CPUS:512 nr_cpumask_bits:512 nr_cpu_ids:10 nr_node_ids:1
[    0.447773] percpu: Embedded 82 pages/cpu s296464 r8192 d31216 u524288
[    0.447805] pcpu-alloc: s296464 r8192 d31216 u524288 alloc=1*2097152
[    0.447808] pcpu-alloc: [0] 00 01 02 03 [0] 04 05 06 07 
[    0.447816] pcpu-alloc: [0] 08 09 -- -- 
[    0.447878] KVM setup async PF for cpu 0
[    0.447886] kvm-stealtime: cpu 0, msr 42de22a80
[    0.447910] Built 1 zonelists, mobility grouping on.  Total pages: 4128615
[    0.447914] Policy zone: Normal
[    0.447920] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 root=UUID=d6ebbea4-17a0-43ef-b491-695fef2aeb1c ro net.ifnames=0 biosdevname=0 console=tty0 console=ttyS1,115200 audit=0
[    0.448205] audit: disabled (until reboot)
[    0.449936] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)
[    0.450862] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
[    0.451077] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.694475] Memory: 14178092K/16776688K available (38916K kernel code, 15192K rwdata, 8212K rodata, 2748K init, 27204K bss, 2598596K reserved, 0K cma-reserved)
[    0.695842] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=10, Nodes=1
[    0.696122] Kernel/User page tables isolation: enabled
[    0.696242] ftrace: allocating 39452 entries in 155 pages
[    0.719655] ftrace: allocated 155 pages with 5 groups
[    0.720860] Running RCU self tests
[    0.720869] rcu: Hierarchical RCU implementation.
[    0.720873] rcu: 	RCU event tracing is enabled.
[    0.720876] rcu: 	RCU lockdep checking is enabled.
[    0.720883] rcu: 	RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=10.
[    0.720889] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
[    0.720893] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=10
[    0.732329] NR_IRQS: 33024, nr_irqs: 504, preallocated irqs: 16
[    0.733272] random: get_random_bytes called from start_kernel+0x3bb/0x6ed with crng_init=0
[    0.750313] Console: colour VGA+ 80x25
[    0.801061] printk: console [tty0] enabled
[    0.888177] printk: console [ttyS1] enabled
[    0.888983] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.890409] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.891207] ... MAX_LOCK_DEPTH:          48
[    0.892025] ... MAX_LOCKDEP_KEYS:        8192
[    0.892861] ... CLASSHASH_SIZE:          4096
[    0.893674] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.894494] ... MAX_LOCKDEP_CHAINS:      65536
[    0.895321] ... CHAINHASH_SIZE:          32768
[    0.896153]  memory used by lock dependency info: 6301 kB
[    0.897103]  memory used for stack traces: 4224 kB
[    0.897980]  per task-struct memory footprint: 1920 bytes
[    0.899258] ACPI: Core revision 20200214
[    0.901057] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    0.902823] APIC: Switch to symmetric I/O mode setup
[    0.904077] x2apic enabled
[    0.904974] Switched APIC routing to physical x2apic.
[    0.905939] KVM setup pv IPIs
[    0.908175] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.909259] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x211354f4cc6, max_idle_ns: 440795207008 ns
[    0.911120] Calibrating delay loop (skipped) preset value.. 4589.22 BogoMIPS (lpj=2294614)
[    0.912110] pid_max: default: 32768 minimum: 301
[    0.914876] LSM: Security Framework initializing
[    0.915335] SELinux:  Initializing.
[    0.917291] *** VALIDATE selinux ***
[    0.918379] Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.919157] Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.921263] *** VALIDATE tmpfs ***
[    0.924393] *** VALIDATE proc ***
[    0.926406] *** VALIDATE cgroup ***
[    0.927112] *** VALIDATE cgroup2 ***
[    0.928176] x86/cpu: User Mode Instruction Prevention (UMIP) activated
[    0.929239] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.930109] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    0.931116] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.932110] Spectre V2 : Spectre mitigation: kernel not compiled with retpoline; no mitigation available!
[    0.932112] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.934118] TAA: Vulnerable: Clear CPU buffers attempted, no microcode
[    0.935109] MDS: Vulnerable: Clear CPU buffers attempted, no microcode
[    0.937310] Freeing SMP alternatives memory: 32K
[    0.940471] TSC deadline timer enabled
[    0.940491] smpboot: CPU0: Intel(R) Xeon(R) Gold 6140 CPU @ 2.30GHz (family: 0x6, model: 0x55, stepping: 0x4)
[    0.942049] Performance Events: Skylake events, Intel PMU driver.
[    0.942130] ... version:                2
[    0.943112] ... bit width:              48
[    0.944111] ... generic registers:      4
[    0.945112] ... value mask:             0000ffffffffffff
[    0.946112] ... max period:             000000007fffffff
[    0.947111] ... fixed-purpose events:   3
[    0.948111] ... event mask:             000000070000000f
[    0.949519] rcu: Hierarchical SRCU implementation.
[    0.953374] smp: Bringing up secondary CPUs ...
[    0.955315] x86: Booting SMP configuration:
[    0.956116] .... node  #0, CPUs:        #1
[    0.173935] kvm-clock: cpu 1, msr 599c041, secondary cpu clock
[    0.173935] smpboot: CPU 1 Converting physical 0 to logical die 1
[    0.963260] KVM setup async PF for cpu 1
[    0.964103] kvm-stealtime: cpu 1, msr 42dea2a80
[    0.966516]   #2
[    0.173935] kvm-clock: cpu 2, msr 599c081, secondary cpu clock
[    0.173935] smpboot: CPU 2 Converting physical 0 to logical die 2
[    0.972195] KVM setup async PF for cpu 2
[    0.973103] kvm-stealtime: cpu 2, msr 42df22a80
[    0.975272]   #3
[    0.173935] kvm-clock: cpu 3, msr 599c0c1, secondary cpu clock
[    0.173935] smpboot: CPU 3 Converting physical 0 to logical die 3
[    0.981219] KVM setup async PF for cpu 3
[    0.982103] kvm-stealtime: cpu 3, msr 42dfa2a80
[    0.984408]   #4
[    0.173935] kvm-clock: cpu 4, msr 599c101, secondary cpu clock
[    0.173935] smpboot: CPU 4 Converting physical 0 to logical die 4
[    0.990206] KVM setup async PF for cpu 4
[    0.991103] kvm-stealtime: cpu 4, msr 42e022a80
[    0.995764]   #5
[    0.173935] kvm-clock: cpu 5, msr 599c141, secondary cpu clock
[    0.173935] smpboot: CPU 5 Converting physical 0 to logical die 5
[    1.002202] KVM setup async PF for cpu 5
[    1.003103] kvm-stealtime: cpu 5, msr 42e0a2a80
[    1.005239]   #6
[    0.173935] kvm-clock: cpu 6, msr 599c181, secondary cpu clock
[    0.173935] smpboot: CPU 6 Converting physical 0 to logical die 6
[    1.011192] KVM setup async PF for cpu 6
[    1.012103] kvm-stealtime: cpu 6, msr 42e122a80
[    1.014267]   #7
[    0.173935] kvm-clock: cpu 7, msr 599c1c1, secondary cpu clock
[    0.173935] smpboot: CPU 7 Converting physical 0 to logical die 7
[    1.020195] KVM setup async PF for cpu 7
[    1.021103] kvm-stealtime: cpu 7, msr 42e1a2a80
[    1.023314]   #8
[    0.173935] kvm-clock: cpu 8, msr 599c201, secondary cpu clock
[    0.173935] smpboot: CPU 8 Converting physical 0 to logical die 8
[    1.029212] KVM setup async PF for cpu 8
[    1.030103] kvm-stealtime: cpu 8, msr 42e222a80
[    1.032424]   #9
[    0.173935] kvm-clock: cpu 9, msr 599c241, secondary cpu clock
[    0.173935] smpboot: CPU 9 Converting physical 0 to logical die 9
[    1.038200] KVM setup async PF for cpu 9
[    1.039103] kvm-stealtime: cpu 9, msr 42e2a2a80
[    1.040367] smp: Brought up 1 node, 10 CPUs
[    1.041114] smpboot: Max logical packages: 10
[    1.042120] smpboot: Total of 10 processors activated (45892.28 BogoMIPS)
[    1.049809] devtmpfs: initialized
[    1.050960] x86/mm: Memory block size: 128MB
[    1.091201] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    1.092738] futex hash table entries: 4096 (order: 7, 524288 bytes, linear)
[    1.095407] thermal_sys: Registered thermal governor 'fair_share'
[    1.095409] thermal_sys: Registered thermal governor 'bang_bang'
[    1.096116] thermal_sys: Registered thermal governor 'step_wise'
[    1.097113] thermal_sys: Registered thermal governor 'user_space'
[    1.100212] NET: Registered protocol family 16
[    1.105565] cpuidle: using governor menu
[    1.106630] ACPI: bus type PCI registered
[    1.108103] PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xb0000000-0xbfffffff] (base 0xb0000000)
[    1.109167] PCI: MMCONFIG at [mem 0xb0000000-0xbfffffff] reserved in E820
[    1.110194] PCI: Using configuration type 1 for base access
[    1.157410] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    1.158539] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    1.219204] cryptd: max_cpu_qlen set to 1000
[    1.274150] ACPI: Added _OSI(Module Device)
[    1.276163] ACPI: Added _OSI(Processor Device)
[    1.278141] ACPI: Added _OSI(3.0 _SCP Extensions)
[    1.280121] ACPI: Added _OSI(Processor Aggregator Device)
[    1.282160] ACPI: Added _OSI(Linux-Dell-Video)
[    1.283144] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    1.285129] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    1.361730] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    1.377763] ACPI: Interpreter enabled
[    1.379330] ACPI: (supports S0 S3 S4 S5)
[    1.380113] ACPI: Using IOAPIC for interrupt routing
[    1.382530] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    1.387159] ACPI: Enabled 1 GPEs in block 00 to 3F
[    1.484822] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    1.485160] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]
[    1.491006] acpi PNP0A08:00: _OSC: platform does not support [LTR]
[    1.495630] acpi PNP0A08:00: _OSC: OS now controls [PME AER PCIeCapability]
[    1.498186] PCI host bridge to bus 0000:00
[    1.499207] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    1.500126] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    1.501125] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    1.502124] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window]
[    1.503124] pci_bus 0000:00: root bus resource [mem 0x480000000-0xc7fffffff window]
[    1.504127] pci_bus 0000:00: root bus resource [bus 00-ff]
[    1.505348] pci 0000:00:00.0: [8086:29c0] type 00 class 0x060000
[    1.508420] pci 0000:00:01.0: [1234:1111] type 00 class 0x030000
[    1.511119] pci 0000:00:01.0: reg 0x10: [mem 0xfc000000-0xfcffffff pref]
[    1.516118] pci 0000:00:01.0: reg 0x18: [mem 0xfea10000-0xfea10fff]
[    1.523118] pci 0000:00:01.0: reg 0x30: [mem 0xfea00000-0xfea0ffff pref]
[    1.525911] pci 0000:00:02.0: [1b36:000c] type 01 class 0x060400
[    1.527668] pci 0000:00:02.0: reg 0x10: [mem 0xfea11000-0xfea11fff]
[    1.533388] pci 0000:00:02.1: [1b36:000c] type 01 class 0x060400
[    1.535712] pci 0000:00:02.1: reg 0x10: [mem 0xfea12000-0xfea12fff]
[    1.540788] pci 0000:00:02.2: [1b36:000c] type 01 class 0x060400
[    1.542737] pci 0000:00:02.2: reg 0x10: [mem 0xfea13000-0xfea13fff]
[    1.548382] pci 0000:00:02.3: [1b36:000c] type 01 class 0x060400
[    1.550700] pci 0000:00:02.3: reg 0x10: [mem 0xfea14000-0xfea14fff]
[    1.556383] pci 0000:00:02.4: [1b36:000c] type 01 class 0x060400
[    1.558665] pci 0000:00:02.4: reg 0x10: [mem 0xfea15000-0xfea15fff]
[    1.563951] pci 0000:00:08.0: [15b3:1017] type 00 class 0x020000
[    1.565118] pci 0000:00:08.0: reg 0x10: [mem 0xf8000000-0xf9ffffff 64bit pref]
[    1.572902] pci 0000:00:08.0: PME# supported from D3cold
[    1.575415] pci 0000:00:08.1: [15b3:1017] type 00 class 0x020000
[    1.577118] pci 0000:00:08.1: reg 0x10: [mem 0xfa000000-0xfbffffff 64bit pref]
[    1.584891] pci 0000:00:08.1: PME# supported from D3cold
[    1.586770] pci 0000:00:1f.0: [8086:2918] type 00 class 0x060100
[    1.587503] pci 0000:00:1f.0: quirk: [io  0x0600-0x067f] claimed by ICH6 ACPI/GPIO/TCO
[    1.589755] pci 0000:00:1f.2: [8086:2922] type 00 class 0x010601
[    1.595117] pci 0000:00:1f.2: reg 0x20: [io  0xc040-0xc05f]
[    1.597737] pci 0000:00:1f.2: reg 0x24: [mem 0xfea16000-0xfea16fff]
[    1.600342] pci 0000:00:1f.3: [8086:2930] type 00 class 0x0c0500
[    1.603672] pci 0000:00:1f.3: reg 0x20: [io  0x0700-0x073f]
[    1.618639] pci 0000:01:00.0: [1b36:000d] type 00 class 0x0c0330
[    1.619747] pci 0000:01:00.0: reg 0x10: [mem 0xfe800000-0xfe803fff 64bit]
[    1.624305] pci 0000:00:02.0: PCI bridge to [bus 01]
[    1.625138] pci 0000:00:02.0:   bridge window [mem 0xfe800000-0xfe9fffff]
[    1.626134] pci 0000:00:02.0:   bridge window [mem 0xfd800000-0xfd9fffff 64bit pref]
[    1.628287] pci 0000:02:00.0: [1af4:1042] type 00 class 0x010000
[    1.631742] pci 0000:02:00.0: reg 0x14: [mem 0xfe600000-0xfe600fff]
[    1.635118] pci 0000:02:00.0: reg 0x20: [mem 0xfd600000-0xfd603fff 64bit pref]
[    1.638537] pci 0000:00:02.1: PCI bridge to [bus 02]
[    1.639139] pci 0000:00:02.1:   bridge window [mem 0xfe600000-0xfe7fffff]
[    1.640135] pci 0000:00:02.1:   bridge window [mem 0xfd600000-0xfd7fffff 64bit pref]
[    1.642251] pci 0000:03:00.0: [1af4:1045] type 00 class 0x00ff00
[    1.645676] pci 0000:03:00.0: reg 0x20: [mem 0xfd400000-0xfd403fff 64bit pref]
[    1.648009] pci 0000:00:02.2: PCI bridge to [bus 03]
[    1.648139] pci 0000:00:02.2:   bridge window [mem 0xfe400000-0xfe5fffff]
[    1.649134] pci 0000:00:02.2:   bridge window [mem 0xfd400000-0xfd5fffff 64bit pref]
[    1.651280] pci 0000:04:00.0: [1af4:1041] type 00 class 0x020000
[    1.654117] pci 0000:04:00.0: reg 0x14: [mem 0xfe240000-0xfe240fff]
[    1.658117] pci 0000:04:00.0: reg 0x20: [mem 0xfd200000-0xfd203fff 64bit pref]
[    1.661118] pci 0000:04:00.0: reg 0x30: [mem 0xfe200000-0xfe23ffff pref]
[    1.663515] pci 0000:00:02.3: PCI bridge to [bus 04]
[    1.664138] pci 0000:00:02.3:   bridge window [mem 0xfe200000-0xfe3fffff]
[    1.665135] pci 0000:00:02.3:   bridge window [mem 0xfd200000-0xfd3fffff 64bit pref]
[    1.667248] pci 0000:05:00.0: [1af4:1041] type 00 class 0x020000
[    1.670117] pci 0000:05:00.0: reg 0x14: [mem 0xfe040000-0xfe040fff]
[    1.674117] pci 0000:05:00.0: reg 0x20: [mem 0xfd000000-0xfd003fff 64bit pref]
[    1.676118] pci 0000:05:00.0: reg 0x30: [mem 0xfe000000-0xfe03ffff pref]
[    1.678511] pci 0000:00:02.4: PCI bridge to [bus 05]
[    1.679137] pci 0000:00:02.4:   bridge window [mem 0xfe000000-0xfe1fffff]
[    1.680135] pci 0000:00:02.4:   bridge window [mem 0xfd000000-0xfd1fffff 64bit pref]
[    1.693160] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[    1.696453] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    1.699441] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    1.702358] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[    1.705436] ACPI: PCI Interrupt Link [LNKE] (IRQs 5 *10 11)
[    1.714449] ACPI: PCI Interrupt Link [LNKF] (IRQs 5 *10 11)
[    1.723402] ACPI: PCI Interrupt Link [LNKG] (IRQs 5 10 *11)
[    1.728798] ACPI: PCI Interrupt Link [LNKH] (IRQs 5 10 *11)
[    1.729693] ACPI: PCI Interrupt Link [GSIA] (IRQs *16)
[    1.730487] ACPI: PCI Interrupt Link [GSIB] (IRQs *17)
[    1.731467] ACPI: PCI Interrupt Link [GSIC] (IRQs *18)
[    1.732484] ACPI: PCI Interrupt Link [GSID] (IRQs *19)
[    1.733476] ACPI: PCI Interrupt Link [GSIE] (IRQs *20)
[    1.734475] ACPI: PCI Interrupt Link [GSIF] (IRQs *21)
[    1.735487] ACPI: PCI Interrupt Link [GSIG] (IRQs *22)
[    1.736482] ACPI: PCI Interrupt Link [GSIH] (IRQs *23)
[    1.753566] iommu: Default domain type: Translated 
[    1.759447] pci 0000:00:01.0: vgaarb: setting as boot VGA device
[    1.760103] pci 0000:00:01.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[    1.760130] pci 0000:00:01.0: vgaarb: bridge control possible
[    1.761113] vgaarb: loaded
[    1.764356] SCSI subsystem initialized
[    1.765425] libata version 3.00 loaded.
[    1.766202] ACPI: bus type USB registered
[    1.767490] usbcore: registered new interface driver usbfs
[    1.768318] usbcore: registered new interface driver hub
[    1.769404] usbcore: registered new device driver usb
[    1.770804] EDAC MC: Ver: 3.0.0
[    1.773554] PCI: Using ACPI for IRQ routing
[    1.813467] PCI: pci_cache_line_size set to 64 bytes
[    1.813697] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[    1.813737] e820: reserve RAM buffer [mem 0x7ffde000-0x7fffffff]
[    1.816463] NetLabel: Initializing
[    1.817117] NetLabel:  domain hash size = 128
[    1.818112] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    1.819411] NetLabel:  unlabeled traffic allowed by default
[    1.820363] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    1.821129] hpet0: 3 comparators, 64-bit 100.000000 MHz counter
[    1.824313] clocksource: Switched to clocksource kvm-clock
[    2.149834] *** VALIDATE bpf ***
[    2.155561] VFS: Disk quotas dquot_6.6.0
[    2.157070] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    2.158881] *** VALIDATE ramfs ***
[    2.160000] *** VALIDATE hugetlbfs ***
[    2.162105] pnp: PnP ACPI init
[    2.163890] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[    2.164528] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
[    2.165047] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active)
[    2.166456] pnp 00:03: Plug and Play ACPI device, IDs PNP0501 (active)
[    2.167383] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)
[    2.173646] pnp: PnP ACPI: found 5 devices
[    2.208854] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    2.211044] pci 0000:00:02.0: bridge window [io  0x1000-0x0fff] to [bus 01] add_size 1000
[    2.213093] pci 0000:00:02.1: bridge window [io  0x1000-0x0fff] to [bus 02] add_size 1000
[    2.215147] pci 0000:00:02.2: bridge window [io  0x1000-0x0fff] to [bus 03] add_size 1000
[    2.217167] pci 0000:00:02.3: bridge window [io  0x1000-0x0fff] to [bus 04] add_size 1000
[    2.219216] pci 0000:00:02.4: bridge window [io  0x1000-0x0fff] to [bus 05] add_size 1000
[    2.221366] pci 0000:00:02.0: BAR 13: assigned [io  0x1000-0x1fff]
[    2.222738] pci 0000:00:02.1: BAR 13: assigned [io  0x2000-0x2fff]
[    2.224060] pci 0000:00:02.2: BAR 13: assigned [io  0x3000-0x3fff]
[    2.225381] pci 0000:00:02.3: BAR 13: assigned [io  0x4000-0x4fff]
[    2.226758] pci 0000:00:02.4: BAR 13: assigned [io  0x5000-0x5fff]
[    2.228155] pci 0000:00:02.0: PCI bridge to [bus 01]
[    2.229328] pci 0000:00:02.0:   bridge window [io  0x1000-0x1fff]
[    2.232317] pci 0000:00:02.0:   bridge window [mem 0xfe800000-0xfe9fffff]
[    2.234823] pci 0000:00:02.0:   bridge window [mem 0xfd800000-0xfd9fffff 64bit pref]
[    2.238786] pci 0000:00:02.1: PCI bridge to [bus 02]
[    2.239977] pci 0000:00:02.1:   bridge window [io  0x2000-0x2fff]
[    2.242794] pci 0000:00:02.1:   bridge window [mem 0xfe600000-0xfe7fffff]
[    2.245173] pci 0000:00:02.1:   bridge window [mem 0xfd600000-0xfd7fffff 64bit pref]
[    2.249070] pci 0000:00:02.2: PCI bridge to [bus 03]
[    2.250278] pci 0000:00:02.2:   bridge window [io  0x3000-0x3fff]
[    2.253697] pci 0000:00:02.2:   bridge window [mem 0xfe400000-0xfe5fffff]
[    2.255810] pci 0000:00:02.2:   bridge window [mem 0xfd400000-0xfd5fffff 64bit pref]
[    2.259141] pci 0000:00:02.3: PCI bridge to [bus 04]
[    2.260334] pci 0000:00:02.3:   bridge window [io  0x4000-0x4fff]
[    2.262932] pci 0000:00:02.3:   bridge window [mem 0xfe200000-0xfe3fffff]
[    2.266295] pci 0000:00:02.3:   bridge window [mem 0xfd200000-0xfd3fffff 64bit pref]
[    2.269449] pci 0000:00:02.4: PCI bridge to [bus 05]
[    2.270691] pci 0000:00:02.4:   bridge window [io  0x5000-0x5fff]
[    2.272949] pci 0000:00:02.4:   bridge window [mem 0xfe000000-0xfe1fffff]
[    2.276015] pci 0000:00:02.4:   bridge window [mem 0xfd000000-0xfd1fffff 64bit pref]
[    2.279220] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    2.280564] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    2.281885] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    2.283322] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window]
[    2.284786] pci_bus 0000:00: resource 8 [mem 0x480000000-0xc7fffffff window]
[    2.286237] pci_bus 0000:01: resource 0 [io  0x1000-0x1fff]
[    2.287539] pci_bus 0000:01: resource 1 [mem 0xfe800000-0xfe9fffff]
[    2.288871] pci_bus 0000:01: resource 2 [mem 0xfd800000-0xfd9fffff 64bit pref]
[    2.290797] pci_bus 0000:02: resource 0 [io  0x2000-0x2fff]
[    2.292034] pci_bus 0000:02: resource 1 [mem 0xfe600000-0xfe7fffff]
[    2.293365] pci_bus 0000:02: resource 2 [mem 0xfd600000-0xfd7fffff 64bit pref]
[    2.295259] pci_bus 0000:03: resource 0 [io  0x3000-0x3fff]
[    2.296558] pci_bus 0000:03: resource 1 [mem 0xfe400000-0xfe5fffff]
[    2.297892] pci_bus 0000:03: resource 2 [mem 0xfd400000-0xfd5fffff 64bit pref]
[    2.299782] pci_bus 0000:04: resource 0 [io  0x4000-0x4fff]
[    2.301026] pci_bus 0000:04: resource 1 [mem 0xfe200000-0xfe3fffff]
[    2.302360] pci_bus 0000:04: resource 2 [mem 0xfd200000-0xfd3fffff 64bit pref]
[    2.304260] pci_bus 0000:05: resource 0 [io  0x5000-0x5fff]
[    2.305507] pci_bus 0000:05: resource 1 [mem 0xfe000000-0xfe1fffff]
[    2.306900] pci_bus 0000:05: resource 2 [mem 0xfd000000-0xfd1fffff 64bit pref]
[    2.309633] NET: Registered protocol family 2
[    2.313633] tcp_listen_portaddr_hash hash table entries: 8192 (order: 7, 655360 bytes, linear)
[    2.316426] TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[    2.319370] TCP bind hash table entries: 65536 (order: 10, 4718592 bytes, vmalloc)
[    2.323702] TCP: Hash tables configured (established 131072 bind 65536)
[    2.325956] UDP hash table entries: 8192 (order: 8, 1310720 bytes, linear)
[    2.328809] UDP-Lite hash table entries: 8192 (order: 8, 1310720 bytes, linear)
[    2.332794] NET: Registered protocol family 1
[    2.333977] NET: Registered protocol family 44
[    2.335232] pci 0000:00:01.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    2.352992] PCI Interrupt Link [GSIG] enabled at IRQ 22
[    2.384530] pci 0000:01:00.0: quirk_usb_early_handoff+0x0/0xbd0 took 46018 usecs
[    2.388815] PCI: CLS 0 bytes, default 64
[    2.390576] Trying to unpack rootfs image as initramfs...
[    3.030135] Freeing initrd memory: 14848K
[    3.033914] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    3.035315] software IO TLB: mapped [mem 0x7bfde000-0x7ffde000] (64MB)
[    3.036870] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x211354f4cc6, max_idle_ns: 440795207008 ns
[    3.082631] Initialise system trusted keyrings
[    3.084884] workingset: timestamp_bits=36 max_order=22 bucket_order=0
[    3.171329] NET: Registered protocol family 38
[    3.173216] Key type asymmetric registered
[    3.174982] Asymmetric key parser 'x509' registered
[    3.177173] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    3.182969] io scheduler bfq registered
[    3.186843] atomic64_test: passed for x86-64 platform with CX8 and with SSE
[    3.193125] pcieport 0000:00:02.0: PME: Signaling with IRQ 24
[    3.195911] pcieport 0000:00:02.0: AER: enabled with IRQ 24
[    3.218905] pcieport 0000:00:02.1: PME: Signaling with IRQ 25
[    3.221610] pcieport 0000:00:02.1: AER: enabled with IRQ 25
[    3.246498] pcieport 0000:00:02.2: PME: Signaling with IRQ 26
[    3.249149] pcieport 0000:00:02.2: AER: enabled with IRQ 26
[    3.281560] pcieport 0000:00:02.3: PME: Signaling with IRQ 27
[    3.284365] pcieport 0000:00:02.3: AER: enabled with IRQ 27
[    3.307761] pcieport 0000:00:02.4: PME: Signaling with IRQ 28
[    3.310430] pcieport 0000:00:02.4: AER: enabled with IRQ 28
[    3.313297] intel_idle: Please enable MWAIT in BIOS SETUP
[    3.394351] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    3.396253] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    3.399948] 00:04: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[    3.415877] Non-volatile memory driver v1.3
[    3.417485] Linux agpgart interface v0.103
[    3.454826] virtio_blk virtio0: [vda] 73400320 512-byte logical blocks (37.6 GB/35.0 GiB)
[    3.456895] vda: detected capacity change from 0 to 37580963840
[    3.460536]  vda: vda1
[    3.464687] Loading iSCSI transport class v2.0-870.
[    3.468359] rdac: device handler registered
[    3.469993] hp_sw: device handler registered
[    3.471101] emc: device handler registered
[    3.472589] alua: device handler registered
[    3.474127] iscsi: registered transport (tcp)
[    3.475267] isci: Intel(R) C600 SAS Controller Driver - version 1.2.0
[    3.477127] mpt3sas version 33.100.00.00 loaded
[    3.479592] libcxgbi:libcxgbi_init_module: Chelsio iSCSI driver library libcxgbi v0.9.1-ko (Apr. 2015)
[    3.481860] Chelsio T3 iSCSI Driver cxgb3i v2.0.1-ko (Apr. 2015)
[    3.483354] iscsi: registered transport (cxgb3i)
[    3.484504] Chelsio T4-T6 iSCSI Driver cxgb4i v0.9.5-ko (Apr. 2015)
[    3.486081] iscsi: registered transport (cxgb4i)
[    3.487292] QLogic NetXtreme II iSCSI Driver bnx2i v2.7.10.1 (Jul 16, 2014)
[    3.488884] iscsi: registered transport (bnx2i)
[    3.495820] ahci 0000:00:1f.2: version 3.0
[    3.514879] PCI Interrupt Link [GSIA] enabled at IRQ 16
[    3.517637] ahci 0000:00:1f.2: AHCI 0001.0000 32 slots 6 ports 1.5 Gbps 0x3f impl SATA mode
[    3.519737] ahci 0000:00:1f.2: flags: 64bit ncq only 
[    3.531690] scsi host0: ahci
[    3.535534] scsi host1: ahci
[    3.540802] scsi host2: ahci
[    3.543791] scsi host3: ahci
[    3.546775] scsi host4: ahci
[    3.549766] scsi host5: ahci
[    3.552069] ata1: SATA max UDMA/133 abar m4096@0xfea16000 port 0xfea16100 irq 31
[    3.554075] ata2: SATA max UDMA/133 abar m4096@0xfea16000 port 0xfea16180 irq 31
[    3.556078] ata3: SATA max UDMA/133 abar m4096@0xfea16000 port 0xfea16200 irq 31
[    3.557975] ata4: SATA max UDMA/133 abar m4096@0xfea16000 port 0xfea16280 irq 31
[    3.559960] ata5: SATA max UDMA/133 abar m4096@0xfea16000 port 0xfea16300 irq 31
[    3.570916] ata6: SATA max UDMA/133 abar m4096@0xfea16000 port 0xfea16380 irq 31
[    3.575557] libphy: Fixed MDIO Bus: probed
[    3.576854] cnic: QLogic cnicDriver v2.5.22 (July 20, 2015)
[    3.579043] Fusion MPT base driver 3.04.20
[    3.580150] Copyright (c) 1999-2008 LSI Corporation
[    3.581357] Fusion MPT SAS Host driver 3.04.20
[    3.583498] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    3.584968] ehci-pci: EHCI PCI platform driver
[    3.586245] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    3.587658] ohci-pci: OHCI PCI platform driver
[    3.588872] uhci_hcd: USB Universal Host Controller Interface driver
[    3.610205] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    3.612660] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    3.615522] xhci_hcd 0000:01:00.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010
[    3.625878] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.06
[    3.628018] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    3.630422] usb usb1: Product: xHCI Host Controller
[    3.631629] usb usb1: Manufacturer: Linux 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 xhci-hcd
[    3.633786] usb usb1: SerialNumber: 0000:01:00.0
[    3.639522] hub 1-0:1.0: USB hub found
[    3.640843] hub 1-0:1.0: 4 ports detected
[    3.645548] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    3.647686] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    3.649638] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    3.651369] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[    3.654043] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.06
[    3.656202] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    3.658061] usb usb2: Product: xHCI Host Controller
[    3.659287] usb usb2: Manufacturer: Linux 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 xhci-hcd
[    3.661451] usb usb2: SerialNumber: 0000:01:00.0
[    3.664937] hub 2-0:1.0: USB hub found
[    3.666268] hub 2-0:1.0: 4 ports detected
[    3.671080] usbcore: registered new interface driver usbserial_generic
[    3.672697] usbserial: USB Serial support registered for generic
[    3.674369] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    3.677733] serio: i8042 KBD port at 0x60,0x64 irq 1
[    3.679056] serio: i8042 AUX port at 0x60,0x64 irq 12
[    3.682273] mousedev: PS/2 mouse device common for all mice
[    3.684926] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    3.689785] rtc_cmos 00:00: RTC can wake from S4
[    3.702702] rtc_cmos 00:00: registered as rtc0
[    3.704227] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram, hpet irqs
[    3.706303] intel_pstate: CPU model not supported
[    3.709280] No iBFT detected.
[    3.710417] hid: raw HID events driver (C) Jiri Kosina
[    3.713557] usbcore: registered new interface driver usbhid
[    3.714851] usbhid: USB HID core driver
[    3.716229] drop_monitor: Initializing network drop monitor service
[    3.721618] NET: Registered protocol family 10
[    3.728644] Segment Routing with IPv6
[    3.729821] NET: Registered protocol family 17
[    3.747947] IPI shorthand broadcast: enabled
[    3.749402] AVX2 version of gcm_enc/dec engaged.
[    3.750924] AES CTR mode by8 optimization enabled
[    3.880576] ata2: SATA link down (SStatus 0 SControl 300)
[    3.882372] ata1: SATA link down (SStatus 0 SControl 300)
[    3.886836] ata3: SATA link down (SStatus 0 SControl 300)
[    3.888517] ata6: SATA link down (SStatus 0 SControl 300)
[    3.890247] ata5: SATA link down (SStatus 0 SControl 300)
[    3.894988] ata4: SATA link down (SStatus 0 SControl 300)
[    3.998971] sched_clock: Marking stable (3825962125, 172935552)->(4387522858, -388625181)
[    4.002875] registered taskstats version 1
[    4.004204] Loading compiled-in X.509 certificates
[    4.049597] Loaded X.509 cert 'Build time autogenerated kernel key: 46dec4a16668423e305ae94ef227cc4428ba7bf4'
[    4.061618] zswap: default zpool zbud not available
[    4.063195] zswap: pool creation failed
[    4.065861] kmemleak: Kernel memory leak detector initialized (mem pool available: 14078)
[    4.065871] kmemleak: Automatic memory scanning thread started
[    4.069001] ima: No TPM chip found, activating TPM-bypass!
[    4.072227] ima: Allocated hash algorithm: sha1
[    4.073801] ima: No architecture policies found
[    4.079788] rtc_cmos 00:00: setting system clock to 2020-04-27T16:34:48 UTC (1588005288)
[    4.101321] Freeing unused kernel image (initmem) memory: 2748K
[    4.117572] Write protecting the kernel read-only data: 51200k
[    4.122454] Freeing unused kernel image (text/rodata gap) memory: 2040K
[    4.125894] Freeing unused kernel image (rodata/data gap) memory: 2028K
[    4.127633] Run /init as init process
[    4.128663]   with arguments:
[    4.128666]     /init
[    4.128668]   with environment:
[    4.128670]     HOME=/
[    4.128673]     TERM=linux
[    4.128675]     BOOT_IMAGE=/boot/vmlinuz-5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70
[    4.128678]     biosdevname=0
[    4.266090] systemd[1]: systemd 234 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN default-hierarchy=hybrid)
[    4.270505] systemd[1]: Detected virtualization kvm.
[    4.271721] systemd[1]: Detected architecture x86-64.
[    4.272926] systemd[1]: Running in initial RAM disk.
[    4.277038] systemd[1]: Set hostname to <localhost.localdomain>.
[    4.553360] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2
[    4.637324] random: systemd: uninitialized urandom read (16 bytes read)
[    4.639485] systemd[1]: Reached target Local File Systems.
[    4.642999] random: systemd: uninitialized urandom read (16 bytes read)
[    4.644459] systemd[1]: Reached target Swap.
[    4.647957] random: systemd: uninitialized urandom read (16 bytes read)
[    4.649951] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    4.655306] systemd[1]: Listening on Journal Socket (/dev/log).
[    4.664604] systemd[1]: Created slice System Slice.
[    6.140856] EXT4-fs (vda1): mounted filesystem with ordered data mode. Opts: (null)
[    6.686768] random: fast init done
[    6.934859] systemd-journald[284]: Received SIGTERM from PID 1 (systemd).
[    7.120034] printk: systemd: 20 output lines suppressed due to ratelimiting
[    7.221895] SELinux:  Runtime disable is deprecated, use selinux=0 on the kernel cmdline.
[    7.224066] SELinux:  Disabled at runtime.
[    7.268669] systemd[1]: RTC configured in localtime, applying delta of 180 minutes to system time.
[    8.031138] systemd-journald[419]: File /run/log/journal/0a211f346c314823a8416b5687b4ad98/system.journal corrupted or uncleanly shut down, renaming and replacing.
[    8.054540] EXT4-fs (vda1): re-mounted. Opts: (null)
[    8.445058] systemd-journald[419]: Received request to flush runtime journal from PID 1
[    8.896199] Adding 2097148k swap on /swapfile.  Priority:-2 extents:2 across:2236412k FS
[    9.000665] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
[    9.004961] ACPI: Power Button [PWRF]
[    9.163767] pps_core: LinuxPPS API ver. 1 registered
[    9.165119] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    9.170377] lpc_ich 0000:00:1f.0: I/O space for GPIO uninitialized
[    9.187884] PTP clock support registered
[    9.265570] input: PC Speaker as /devices/platform/pcspkr/input/input4
[    9.270176] RPC: Registered named UNIX socket transport module.
[    9.271618] RPC: Registered udp transport module.
[    9.272911] RPC: Registered tcp transport module.
[    9.274284] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    9.330799] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt
[    9.653328] iTCO_vendor_support: vendor-support=0
[    9.658086] PCI Interrupt Link [GSIE] enabled at IRQ 20
[    9.659764] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.11
[    9.660254] iTCO_wdt: Found a ICH9 TCO device (Version=2, TCOBASE=0x0660)
[    9.662052] mlx5_core 0000:00:08.0: firmware version: 16.27.2048
[    9.662134] mlx5_core 0000:00:08.0: 0.000 Gb/s available PCIe bandwidth (Unknown speed x255 link)
[    9.662647] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
[    9.913070] Rounding down aligned max_sectors from 4294967295 to 4294967288
[    9.915992] db_root: cannot open: /etc/target
[   10.025122] iscsi: registered transport (iser)
[   10.409292] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   10.431387] RPC: Registered rdma transport module.
[   10.432680] RPC: Registered rdma backchannel transport module.
[   10.435718] mlx5_core 0000:00:08.0: Rate limit: 127 rates are supported, range: 0Mbps to 97656Mbps
[   10.439354] mlx5_core 0000:00:08.0: E-Switch: Total vports 2, per vport: max uc(1024) max mc(16384)
[   10.481002] mlx5_core 0000:00:08.0: Port module event: module 0, Cable plugged
[   10.483782] mlx5_core 0000:00:08.0: mlx5_pcie_event:296:(pid 182): PCIe slot advertised sufficient power (75W).
[   10.547504] PCI Interrupt Link [GSIF] enabled at IRQ 21
[   10.550501] mlx5_core 0000:00:08.1: firmware version: 16.27.2048
[   10.551914] mlx5_core 0000:00:08.1: 0.000 Gb/s available PCIe bandwidth (Unknown speed x255 link)
[   11.227431] mlx5_core 0000:00:08.1: Rate limit: 127 rates are supported, range: 0Mbps to 97656Mbps
[   11.233521] mlx5_core 0000:00:08.1: E-Switch: Total vports 2, per vport: max uc(1024) max mc(16384)
[   11.276441] mlx5_core 0000:00:08.1: Port module event: module 1, Cable plugged
[   11.284457] mlx5_core 0000:00:08.1: mlx5_pcie_event:296:(pid 180): PCIe slot advertised sufficient power (75W).
[   11.316383] mlx5_core 0000:00:08.0: MLX5E: StrdRq(1) RqSz(8) StrdSz(2048) RxCqeCmprss(0)
[   11.546350] mlx5_core 0000:00:08.1: MLX5E: StrdRq(1) RqSz(8) StrdSz(2048) RxCqeCmprss(0)
[   11.831729] mlx5_ib: Mellanox Connect-IB Infiniband driver v5.0-0
[   12.243248] random: crng init done
[   12.244300] random: 7 urandom warning(s) missed due to ratelimiting
[   13.199541] FS-Cache: Loaded
[   13.286377] FS-Cache: Netfs 'nfs' registered for caching
[   13.294924] *** VALIDATE nfs ***
[   13.300966] *** VALIDATE nfs4 ***
[   13.318863] Key type dns_resolver registered
[   13.572240] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[   13.582633] Bridge firewalling registered
[   13.586043] NFS: Registering the id_resolver key type
[   13.587377] Key type id_resolver registered
[   13.588516] Key type id_legacy registered
[   90.771014] NFS4: Couldn't follow remote path
[   90.778825] NFS4: Couldn't follow remote path
[   90.783949] NFS4: Couldn't follow remote path
[  132.549020] TSC deadline timer enabled

[  132.575308] ======================================================
[  132.575308] WARNING: possible circular locking dependency detected
[  132.575309] 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 #1 Not tainted
[  132.575310] ------------------------------------------------------
[  132.575311] swapper/7/0 is trying to acquire lock:
[  132.575311] ffffffff8442c858 ((console_sem).lock){-...}-{2:2}, at: down_trylock+0x13/0x70

[  132.575314] but task is already holding lock:
[  132.575315] ffff88842e1b9958 (hrtimer_bases.lock){-.-.}-{2:2}, at: lock_hrtimer_base+0x71/0x120

[  132.575317] which lock already depends on the new lock.


[  132.575319] the existing dependency chain (in reverse order) is:

[  132.575320] -> #4 (hrtimer_bases.lock){-.-.}-{2:2}:
[  132.575322]        _raw_spin_lock_irqsave+0x3c/0x4b
[  132.575322]        lock_hrtimer_base+0x71/0x120
[  132.575323]        hrtimer_start_range_ns+0xc6/0xaa0
[  132.575323]        __enqueue_rt_entity+0xc44/0xf50
[  132.575324]        enqueue_rt_entity+0x79/0xc0
[  132.575325]        enqueue_task_rt+0x5c/0x2e0
[  132.575325]        activate_task+0x15a/0x2c0
[  132.575326]        ttwu_do_activate+0xcf/0x120
[  132.575326]        sched_ttwu_pending+0x160/0x230
[  132.575327]        do_idle+0x2cf/0x530
[  132.575327]        cpu_startup_entry+0x19/0x20
[  132.575328]        start_secondary+0x2ee/0x3e0
[  132.575328]        secondary_startup_64+0xa4/0xb0

[  132.575329] -> #3 (&rt_b->rt_runtime_lock){-...}-{2:2}:
[  132.575331]        _raw_spin_lock+0x25/0x30
[  132.575331]        rq_online_rt+0x288/0x550
[  132.575332]        set_rq_online+0x11f/0x190
[  132.575332]        sched_cpu_activate+0x1d4/0x390
[  132.575333]        cpuhp_invoke_callback+0x1c5/0x1560
[  132.575333]        cpuhp_thread_fun+0x3f8/0x6f0
[  132.575334]        smpboot_thread_fn+0x305/0x5f0
[  132.575335]        kthread+0x2f8/0x3b0
[  132.575335]        ret_from_fork+0x24/0x30

[  132.575336] -> #2 (&rq->lock){-.-.}-{2:2}:
[  132.575338]        _raw_spin_lock+0x25/0x30
[  132.575338]        task_fork_fair+0x34/0x430
[  132.575339]        sched_fork+0x48a/0xa60
[  132.575339]        copy_process+0x15df/0x5970
[  132.575340]        _do_fork+0x106/0xcd0
[  132.575340]        kernel_thread+0x9e/0xe0
[  132.575341]        rest_init+0x28/0x330
[  132.575341]        start_kernel+0x6ac/0x6ed
[  132.575342]        secondary_startup_64+0xa4/0xb0

[  132.575342] -> #1 (&p->pi_lock){-.-.}-{2:2}:
[  132.575344]        _raw_spin_lock_irqsave+0x3c/0x4b
[  132.575345]        try_to_wake_up+0x9a/0x1700
[  132.575345]        up+0x7a/0xb0
[  132.575346]        __up_console_sem+0x3c/0x70
[  132.575346]        console_unlock+0x4f4/0xab0
[  132.575347]        con_font_op+0x907/0x1010
[  132.575347]        vt_ioctl+0x10a6/0x2890
[  132.575348]        tty_ioctl+0x257/0x1240
[  132.575348]        ksys_ioctl+0x3e9/0x1190
[  132.575349]        __x64_sys_ioctl+0x6f/0xb0
[  132.575349]        do_syscall_64+0xe7/0x12c0
[  132.575350]        entry_SYSCALL_64_after_hwframe+0x49/0xb3

[  132.575350] -> #0 ((console_sem).lock){-...}-{2:2}:
[  132.575352]        __lock_acquire+0x374a/0x5210
[  132.575353]        lock_acquire+0x1b9/0x920
[  132.575353]        _raw_spin_lock_irqsave+0x3c/0x4b
[  132.575354]        down_trylock+0x13/0x70
[  132.575354]        __down_trylock_console_sem+0x33/0xa0
[  132.575355]        console_trylock+0x13/0x60
[  132.575356]        vprintk_emit+0xec/0x370
[  132.575356]        printk+0x9c/0xc3
[  132.575357]        lapic_timer_set_oneshot+0x4e/0x60
[  132.575357]        clockevents_switch_state+0x1e1/0x360
[  132.575358]        tick_program_event+0xae/0xc0
[  132.575358]        hrtimer_start_range_ns+0x4b6/0xaa0
[  132.575359]        __tick_nohz_idle_restart_tick+0x2a9/0x380
[  132.575359]        tick_nohz_idle_exit+0x149/0x190
[  132.575360]        do_idle+0x2b8/0x530
[  132.575360]        cpu_startup_entry+0x19/0x20
[  132.575361]        start_secondary+0x2ee/0x3e0
[  132.575361]        secondary_startup_64+0xa4/0xb0

[  132.575362] other info that might help us debug this:

[  132.575363] Chain exists of:
[  132.575364]   (console_sem).lock --> &rt_b->rt_runtime_lock --> hrtimer_bases.lock

[  132.575367]  Possible unsafe locking scenario:

[  132.575368]        CPU0                    CPU1
[  132.575368]        ----                    ----
[  132.575368]   lock(hrtimer_bases.lock);
[  132.575370]                                lock(&rt_b->rt_runtime_lock);
[  132.575371]                                lock(hrtimer_bases.lock);
[  132.575372]   lock((console_sem).lock);

[  132.575374]  *** DEADLOCK ***

[  132.575374] 1 lock held by swapper/7/0:
[  132.575375]  #0: ffff88842e1b9958 (hrtimer_bases.lock){-.-.}-{2:2}, at: lock_hrtimer_base+0x71/0x120

[  132.575377] stack backtrace:
[  132.575378] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 5.6.0-for-upstream-dbg-2020-04-03_10-44-43-70 #1
[  132.575379] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
[  132.575380] Call Trace:
[  132.575380]  dump_stack+0xb7/0x10b
[  132.575381]  check_noncircular+0x37f/0x460
[  132.575381]  ? arch_stack_walk+0x7c/0xd0
[  132.575382]  ? print_circular_bug+0x4e0/0x4e0
[  132.575382]  ? mark_lock+0x1a4/0xb60
[  132.575383]  ? __lock_acquire+0x374a/0x5210
[  132.575383]  __lock_acquire+0x374a/0x5210
[  132.575384]  ? register_lock_class+0x17e0/0x17e0
[  132.575384]  ? register_lock_class+0x17e0/0x17e0
[  132.575385]  lock_acquire+0x1b9/0x920
[  132.575385]  ? down_trylock+0x13/0x70
[  132.575386]  ? check_flags.part.29+0x450/0x450
[  132.575386]  ? lock_downgrade+0x760/0x760
[  132.575387]  ? vprintk_emit+0xec/0x370
[  132.575387]  _raw_spin_lock_irqsave+0x3c/0x4b
[  132.575388]  ? down_trylock+0x13/0x70
[  132.575388]  down_trylock+0x13/0x70
[  132.575389]  __down_trylock_console_sem+0x33/0xa0
[  132.575389]  console_trylock+0x13/0x60
[  132.575390]  vprintk_emit+0xec/0x370
[  132.575390]  printk+0x9c/0xc3
[  132.575391]  ? kmsg_dump_rewind_nolock+0xd9/0xd9
[  132.575391]  lapic_timer_set_oneshot+0x4e/0x60
[  132.575392]  clockevents_switch_state+0x1e1/0x360
[  132.575392]  ? enqueue_hrtimer+0x116/0x310
[  132.575393]  tick_program_event+0xae/0xc0
[  132.575393]  hrtimer_start_range_ns+0x4b6/0xaa0
[  132.575394]  ? _raw_spin_unlock_irqrestore+0x49/0x50
[  132.575394]  ? hrtimer_run_softirq+0x210/0x210
[  132.575395]  ? rcu_read_lock_bh_held+0xe0/0xe0
[  132.575395]  __tick_nohz_idle_restart_tick+0x2a9/0x380
[  132.575396]  tick_nohz_idle_exit+0x149/0x190
[  132.575396]  do_idle+0x2b8/0x530
[  132.575397]  ? arch_cpu_idle_exit+0x40/0x40
[  132.575397]  ? _raw_spin_unlock_irqrestore+0x2d/0x50
[  132.575398]  cpu_startup_entry+0x19/0x20
[  132.575398]  start_secondary+0x2ee/0x3e0
[  132.575399]  ? set_cpu_sibling_map+0x2f70/0x2f70
[  132.575400]  secondary_startup_64+0xa4/0xb0

[-- Attachment #3: config.gz --]
[-- Type: application/gzip, Size: 41017 bytes --]

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

[Thomas Gleixner]

Leon Romanovsky <leon@kernel.org> writes:
> 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

That explains it.

> [    0.937310] Freeing SMP alternatives memory: 32K
> [    0.940471] TSC deadline timer enabled

So here is the first one which sets 'once'. Of course if you clear 'once'
afterwards then this triggers because the context is completely
different.

So the right thing to do is to move this out of __setup_APIC_LVTT() and
be done with it.

Thanks

        tglx

8<-------------------
Subject: x86/apic: Move TSC deadline timer debug printk
From: Thomas Gleixner <tglx@linutronix.de>
Date: Mon, 27 Apr 2020 16:55:57 +0200

Leon reported that the printk_once() in __setup_APIC_LVTT() triggers a
lockdep splat due to a lock order violation between hrtimer_base::lock and
console_sem, when the 'once' condition is reset via
/sys/kernel/debug/clear_warn_once after boot.

The initial printk cannot trigger this because that happens during boot
when the local APIC timer is set up on the boot CPU.

Prevent it by moving the printk to a place which is guaranteed to be only
called once during boot.

Mark the deadline timer check related functions and data __init while at
it.

Reported-by: Leon Romanovsky <leon@kernel.org>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
---
 arch/x86/kernel/apic/apic.c |   27 ++++++++++++++-------------
 1 file changed, 14 insertions(+), 13 deletions(-)

--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -352,8 +352,6 @@ static void __setup_APIC_LVTT(unsigned i
 		 * According to Intel, MFENCE can do the serialization here.
 		 */
 		asm volatile("mfence" : : : "memory");
-
-		printk_once(KERN_DEBUG "TSC deadline timer enabled\n");
 		return;
 	}
 
@@ -546,7 +544,7 @@ static struct clock_event_device lapic_c
 };
 static DEFINE_PER_CPU(struct clock_event_device, lapic_events);
 
-static u32 hsx_deadline_rev(void)
+static __init u32 hsx_deadline_rev(void)
 {
 	switch (boot_cpu_data.x86_stepping) {
 	case 0x02: return 0x3a; /* EP */
@@ -556,7 +554,7 @@ static u32 hsx_deadline_rev(void)
 	return ~0U;
 }
 
-static u32 bdx_deadline_rev(void)
+static __init u32 bdx_deadline_rev(void)
 {
 	switch (boot_cpu_data.x86_stepping) {
 	case 0x02: return 0x00000011;
@@ -568,7 +566,7 @@ static u32 bdx_deadline_rev(void)
 	return ~0U;
 }
 
-static u32 skx_deadline_rev(void)
+static __init u32 skx_deadline_rev(void)
 {
 	switch (boot_cpu_data.x86_stepping) {
 	case 0x03: return 0x01000136;
@@ -581,7 +579,7 @@ static u32 skx_deadline_rev(void)
 	return ~0U;
 }
 
-static const struct x86_cpu_id deadline_match[] = {
+static const struct x86_cpu_id deadline_match[] __initconst = {
 	X86_MATCH_INTEL_FAM6_MODEL( HASWELL_X,		&hsx_deadline_rev),
 	X86_MATCH_INTEL_FAM6_MODEL( BROADWELL_X,	0x0b000020),
 	X86_MATCH_INTEL_FAM6_MODEL( BROADWELL_D,	&bdx_deadline_rev),
@@ -603,18 +601,19 @@ static const struct x86_cpu_id deadline_
 	{},
 };
 
-static void apic_check_deadline_errata(void)
+static __init bool apic_validate_deadline_timer(void)
 {
 	const struct x86_cpu_id *m;
 	u32 rev;
 
-	if (!boot_cpu_has(X86_FEATURE_TSC_DEADLINE_TIMER) ||
-	    boot_cpu_has(X86_FEATURE_HYPERVISOR))
-		return;
+	if (!boot_cpu_has(X86_FEATURE_TSC_DEADLINE_TIMER))
+		return false;
+	if (boot_cpu_has(X86_FEATURE_HYPERVISOR))
+		return true;
 
 	m = x86_match_cpu(deadline_match);
 	if (!m)
-		return;
+		return true;
 
 	/*
 	 * Function pointers will have the MSB set due to address layout,
@@ -626,11 +625,12 @@ static void apic_check_deadline_errata(v
 		rev = (u32)m->driver_data;
 
 	if (boot_cpu_data.microcode >= rev)
-		return;
+		return true;
 
 	setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
 	pr_err(FW_BUG "TSC_DEADLINE disabled due to Errata; "
 	       "please update microcode to version: 0x%x (or later)\n", rev);
+	return false;
 }
 
 /*
@@ -2092,7 +2092,8 @@ void __init init_apic_mappings(void)
 {
 	unsigned int new_apicid;
 
-	apic_check_deadline_errata();
+	if (apic_validate_deadline_timer())
+		pr_debug("TSC deadline timer available\n");
 
 	if (x2apic_mode) {
 		boot_cpu_physical_apicid = read_apic_id();

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

[Leon Romanovsky]

On Mon, Apr 27, 2020 at 05:31:21PM +0200, Thomas Gleixner wrote:
> Leon Romanovsky <leon@kernel.org> writes:
> > 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
>
> That explains it.
>
> > [    0.937310] Freeing SMP alternatives memory: 32K
> > [    0.940471] TSC deadline timer enabled
>
> So here is the first one which sets 'once'. Of course if you clear 'once'
> afterwards then this triggers because the context is completely
> different.
>
> So the right thing to do is to move this out of __setup_APIC_LVTT() and
> be done with it.

Thanks a lot.

[tip: x86/urgent] x86/apic: Move TSC deadline timer debug printk

[tip-bot2 for Thomas Gleixner]

The following commit has been merged into the x86/urgent branch of tip:

Commit-ID:     c84cb3735fd53c91101ccdb191f2e3331a9262cb
Gitweb:        https://git.kernel.org/tip/c84cb3735fd53c91101ccdb191f2e3331a9262cb
Author:        Thomas Gleixner <tglx@linutronix.de>
AuthorDate:    Mon, 27 Apr 2020 16:55:57 +02:00
Committer:     Thomas Gleixner <tglx@linutronix.de>
CommitterDate: Fri, 01 May 2020 19:15:41 +02:00

x86/apic: Move TSC deadline timer debug printk

Leon reported that the printk_once() in __setup_APIC_LVTT() triggers a
lockdep splat due to a lock order violation between hrtimer_base::lock and
console_sem, when the 'once' condition is reset via
/sys/kernel/debug/clear_warn_once after boot.

The initial printk cannot trigger this because that happens during boot
when the local APIC timer is set up on the boot CPU.

Prevent it by moving the printk to a place which is guaranteed to be only
called once during boot.

Mark the deadline timer check related functions and data __init while at
it.

Reported-by: Leon Romanovsky <leon@kernel.org>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Link: https://lkml.kernel.org/r/87y2qhoshi.fsf@nanos.tec.linutronix.de

---
 arch/x86/kernel/apic/apic.c | 27 ++++++++++++++-------------
 1 file changed, 14 insertions(+), 13 deletions(-)

diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index 81b9c63..e53dda2 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -352,8 +352,6 @@ static void __setup_APIC_LVTT(unsigned int clocks, int oneshot, int irqen)
 		 * According to Intel, MFENCE can do the serialization here.
 		 */
 		asm volatile("mfence" : : : "memory");
-
-		printk_once(KERN_DEBUG "TSC deadline timer enabled\n");
 		return;
 	}
 
@@ -546,7 +544,7 @@ static struct clock_event_device lapic_clockevent = {
 };
 static DEFINE_PER_CPU(struct clock_event_device, lapic_events);
 
-static u32 hsx_deadline_rev(void)
+static __init u32 hsx_deadline_rev(void)
 {
 	switch (boot_cpu_data.x86_stepping) {
 	case 0x02: return 0x3a; /* EP */
@@ -556,7 +554,7 @@ static u32 hsx_deadline_rev(void)
 	return ~0U;
 }
 
-static u32 bdx_deadline_rev(void)
+static __init u32 bdx_deadline_rev(void)
 {
 	switch (boot_cpu_data.x86_stepping) {
 	case 0x02: return 0x00000011;
@@ -568,7 +566,7 @@ static u32 bdx_deadline_rev(void)
 	return ~0U;
 }
 
-static u32 skx_deadline_rev(void)
+static __init u32 skx_deadline_rev(void)
 {
 	switch (boot_cpu_data.x86_stepping) {
 	case 0x03: return 0x01000136;
@@ -581,7 +579,7 @@ static u32 skx_deadline_rev(void)
 	return ~0U;
 }
 
-static const struct x86_cpu_id deadline_match[] = {
+static const struct x86_cpu_id deadline_match[] __initconst = {
 	X86_MATCH_INTEL_FAM6_MODEL( HASWELL_X,		&hsx_deadline_rev),
 	X86_MATCH_INTEL_FAM6_MODEL( BROADWELL_X,	0x0b000020),
 	X86_MATCH_INTEL_FAM6_MODEL( BROADWELL_D,	&bdx_deadline_rev),
@@ -603,18 +601,19 @@ static const struct x86_cpu_id deadline_match[] = {
 	{},
 };
 
-static void apic_check_deadline_errata(void)
+static __init bool apic_validate_deadline_timer(void)
 {
 	const struct x86_cpu_id *m;
 	u32 rev;
 
-	if (!boot_cpu_has(X86_FEATURE_TSC_DEADLINE_TIMER) ||
-	    boot_cpu_has(X86_FEATURE_HYPERVISOR))
-		return;
+	if (!boot_cpu_has(X86_FEATURE_TSC_DEADLINE_TIMER))
+		return false;
+	if (boot_cpu_has(X86_FEATURE_HYPERVISOR))
+		return true;
 
 	m = x86_match_cpu(deadline_match);
 	if (!m)
-		return;
+		return true;
 
 	/*
 	 * Function pointers will have the MSB set due to address layout,
@@ -626,11 +625,12 @@ static void apic_check_deadline_errata(void)
 		rev = (u32)m->driver_data;
 
 	if (boot_cpu_data.microcode >= rev)
-		return;
+		return true;
 
 	setup_clear_cpu_cap(X86_FEATURE_TSC_DEADLINE_TIMER);
 	pr_err(FW_BUG "TSC_DEADLINE disabled due to Errata; "
 	       "please update microcode to version: 0x%x (or later)\n", rev);
+	return false;
 }
 
 /*
@@ -2092,7 +2092,8 @@ void __init init_apic_mappings(void)
 {
 	unsigned int new_apicid;
 
-	apic_check_deadline_errata();
+	if (apic_validate_deadline_timer())
+		pr_debug("TSC deadline timer available\n");
 
 	if (x2apic_mode) {
 		boot_cpu_physical_apicid = read_apic_id();