Message-ID: <CA+1xoqf6kLXzaBgwmaaqffju1WHPSQtDaxiub1Ag_MsTWcKb6g@mail.gmail.com>
Date:   Thu, 28 Sep 2017 02:19:46 -0700
From:   Sasha Levin <levinsasha928@...il.com>
To:     Peter Zijlstra <peterz@...radead.org>,
        Thomas Gleixner <tglx@...utronix.de>,
        Ingo Molnar <mingo@...e.hu>
Cc:     "linux-kernel@...r.kernel.org List" <linux-kernel@...r.kernel.org>,
        alexander.levin@...izon.com
Subject: sched: serial port lockdep warning when offlining CPUs

Hi all,

I seem to be hitting the following warning when offlining CPUs on the
latest -next kernel:

[289683102.607076] Unregister pv shared memory for cpu 8
[289683102.622922] select_fallback_rq: 3 callbacks suppressed
[289683102.625834] process 8583 (trinity-c78) no longer affine to cpu8
[289683102.625868]
[289683102.625871] ======================================================
[289683102.625874] WARNING: possible circular locking dependency detected
[289683102.625876] 4.14.0-rc2-next-20170927+ #252 Not tainted
[289683102.625879] ------------------------------------------------------
[289683102.625881] migration/8/62 is trying to acquire lock:
[289683102.625887] (&port_lock_key){-.-.}, at:
serial8250_console_write (drivers/tty/serial/8250/8250_port.c:3222)
[289683102.625897]
[289683102.625899] but task is already holding lock:
[289683102.625900] (&rq->lock){-.-.}, at: sched_cpu_dying
(kernel/sched/sched.h:937 kernel/sched/sched.h:1739
kernel/sched/core.c:5486 kernel/sched/core.c:5687)
[289683102.625906]
[289683102.625908] which lock already depends on the new lock.
[289683102.625909]
[289683102.625911]
[289683102.625917] the existing dependency chain (in reverse order) is:
[289683102.625920]
[289683102.625921] -> #3 (&rq->lock){-.-.}:
[289683102.625929] __lock_acquire (kernel/locking/lockdep.c:2022
kernel/locking/lockdep.c:2469 kernel/locking/lockdep.c:3498)
[289683102.625931] lock_acquire (kernel/locking/lockdep.c:4004)
[289683102.625934] _raw_spin_lock
(./include/linux/spinlock_api_smp.h:143 kernel/locking/spinlock.c:151)
[289683102.625936] task_fork_fair (kernel/sched/sched.h:917
kernel/sched/sched.h:1731 kernel/sched/fair.c:9117)
[289683102.625938] sched_fork (kernel/sched/core.c:2395)
[289683102.625940] copy_process.part.31 (kernel/fork.c:1707)
[289683102.625942] _do_fork (kernel/fork.c:2036)
[289683102.625943] kernel_thread (kernel/fork.c:2093)
[289683102.625946] rest_init (init/main.c:401)
[289683102.625948] start_kernel (init/main.c:510)
[289683102.625950] x86_64_start_reservations (arch/x86/kernel/head64.c:378)
[289683102.625952] x86_64_start_kernel (arch/x86/kernel/head64.c:359)
[289683102.625954] verify_cpu (arch/x86/kernel/verify_cpu.S:37)
[289683102.625955]
[289683102.625956] -> #2 (&p->pi_lock){-.-.}:
[289683102.625964] __lock_acquire (kernel/locking/lockdep.c:2022
kernel/locking/lockdep.c:2469 kernel/locking/lockdep.c:3498)
[289683102.625966] lock_acquire (kernel/locking/lockdep.c:4004)
[289683102.625968] _raw_spin_lock_irqsave
(./include/linux/spinlock_api_smp.h:117 kernel/locking/spinlock.c:159)
[289683102.625970] try_to_wake_up (kernel/sched/core.c:1978)
[289683102.625972] default_wake_function (kernel/sched/core.c:3628)
[289683102.625974] woken_wake_function (kernel/sched/wait.c:447)
[289683102.625976] __wake_up_common (kernel/sched/wait.c:98)
[289683102.625978] __wake_up_common_lock
(./include/linux/spinlock.h:371 kernel/sched/wait.c:126)
[289683102.625980] __wake_up (kernel/sched/wait.c:150)
[289683102.625981] tty_wakeup (drivers/tty/tty_io.c:536)
[289683102.625983] tty_port_default_wakeup (drivers/tty/tty_port.c:50)
[289683102.625985] tty_port_tty_wakeup (drivers/tty/tty_port.c:390)
[289683102.625987] uart_write_wakeup (drivers/tty/serial/serial_core.c:117)
[289683102.625989] serial8250_tx_chars
(drivers/tty/serial/8250/8250_port.c:1799)
[289683102.625991] serial8250_handle_irq.part.25
(drivers/tty/serial/8250/8250_port.c:1871)
[289683102.625993] serial8250_default_handle_irq
(drivers/tty/serial/8250/8250_port.c:1891
drivers/tty/serial/8250/8250_port.c:1887)
[289683102.625995] serial8250_interrupt
(drivers/tty/serial/8250/8250_core.c:129)
[289683102.625997] __handle_irq_event_percpu (kernel/irq/handle.c:147)
[289683102.625999] handle_irq_event_percpu (kernel/irq/handle.c:189)
[289683102.626001] handle_irq_event (kernel/irq/handle.c:206)
[289683102.626004] handle_level_irq (kernel/irq/chip.c:646)
[289683102.626006] handle_irq (arch/x86/kernel/irq_64.c:78)
[289683102.626007] do_IRQ (arch/x86/kernel/irq.c:241)
[289683102.626009] ret_from_intr (arch/x86/entry/entry_64.S:601)
[289683102.626011] native_safe_halt (./arch/x86/include/asm/irqflags.h:54)
[289683102.626013] default_idle (./arch/x86/include/asm/paravirt.h:93
arch/x86/kernel/process.c:341)
[289683102.626015] arch_cpu_idle (arch/x86/kernel/process.c:333)
[289683102.626017] default_idle_call (kernel/sched/idle.c:101)
[289683102.626019] do_idle (kernel/sched/idle.c:156 kernel/sched/idle.c:246)
[289683102.626021] cpu_startup_entry (kernel/sched/idle.c:351 (discriminator 1))
[289683102.626023] rest_init (init/main.c:436)
[289683102.626025] start_kernel (init/main.c:510)
[289683102.626027] x86_64_start_reservations (arch/x86/kernel/head64.c:378)
[289683102.626029] x86_64_start_kernel (arch/x86/kernel/head64.c:359)
[289683102.626031] verify_cpu (arch/x86/kernel/verify_cpu.S:37)
[289683102.626032]
[289683102.626033] -> #1 (&tty->write_wait){-.-.}:
[289683102.626040] __lock_acquire (kernel/locking/lockdep.c:2022
kernel/locking/lockdep.c:2469 kernel/locking/lockdep.c:3498)
[289683102.626041] lock_acquire (kernel/locking/lockdep.c:4004)
[289683102.626043] _raw_spin_lock_irqsave
(./include/linux/spinlock_api_smp.h:117 kernel/locking/spinlock.c:159)
[289683102.626045] __wake_up_common_lock (kernel/sched/wait.c:125)
[289683102.626047] __wake_up (kernel/sched/wait.c:150)
[289683102.626049] tty_wakeup (drivers/tty/tty_io.c:536)
[289683102.626051] tty_port_default_wakeup (drivers/tty/tty_port.c:50)
[289683102.626053] tty_port_tty_wakeup (drivers/tty/tty_port.c:390)
[289683102.626054] uart_write_wakeup (drivers/tty/serial/serial_core.c:117)
[289683102.626056] serial8250_tx_chars
(drivers/tty/serial/8250/8250_port.c:1799)
[289683102.626058] serial8250_handle_irq.part.25
(drivers/tty/serial/8250/8250_port.c:1871)
[289683102.626061] serial8250_default_handle_irq
(drivers/tty/serial/8250/8250_port.c:1891
drivers/tty/serial/8250/8250_port.c:1887)
[289683102.626063] serial8250_interrupt
(drivers/tty/serial/8250/8250_core.c:129)
[289683102.626065] __handle_irq_event_percpu (kernel/irq/handle.c:147)
[289683102.626067] handle_irq_event_percpu (kernel/irq/handle.c:189)
[289683102.626069] handle_irq_event (kernel/irq/handle.c:206)
[289683102.626071] handle_level_irq (kernel/irq/chip.c:646)
[289683102.626073] handle_irq (arch/x86/kernel/irq_64.c:78)
[289683102.626075] do_IRQ (arch/x86/kernel/irq.c:241)
[289683102.626077] ret_from_intr (arch/x86/entry/entry_64.S:601)
[289683102.626078] native_safe_halt (./arch/x86/include/asm/irqflags.h:54)
[289683102.626080] default_idle (./arch/x86/include/asm/paravirt.h:93
arch/x86/kernel/process.c:341)
[289683102.626082] arch_cpu_idle (arch/x86/kernel/process.c:333)
[289683102.626084] default_idle_call (kernel/sched/idle.c:101)
[289683102.626086] do_idle (kernel/sched/idle.c:156 kernel/sched/idle.c:246)
[289683102.626087] cpu_startup_entry (kernel/sched/idle.c:351 (discriminator 1))
[289683102.626089] rest_init (init/main.c:436)
[289683102.626091] start_kernel (init/main.c:510)
[289683102.626102] x86_64_start_reservations (arch/x86/kernel/head64.c:378)
[289683102.626105] x86_64_start_kernel (arch/x86/kernel/head64.c:359)
[289683102.626107] verify_cpu (arch/x86/kernel/verify_cpu.S:37)
[289683102.626108]
[289683102.626109] -> #0 (&port_lock_key){-.-.}:
[289683102.626116] check_prev_add (kernel/locking/lockdep.c:1894)
[289683102.626118] __lock_acquire (kernel/locking/lockdep.c:2022
kernel/locking/lockdep.c:2469 kernel/locking/lockdep.c:3498)
[289683102.626120] lock_acquire (kernel/locking/lockdep.c:4004)
[289683102.626123] _raw_spin_lock_irqsave
(./include/linux/spinlock_api_smp.h:117 kernel/locking/spinlock.c:159)
[289683102.626125] serial8250_console_write
(drivers/tty/serial/8250/8250_port.c:3222)
[289683102.626127] univ8250_console_write
(drivers/tty/serial/8250/8250_core.c:598)
[289683102.626129] console_unlock (kernel/printk/printk.c:1693
kernel/printk/printk.c:2353)
[289683102.626131] vprintk_emit (kernel/printk/printk.c:1876)
[289683102.626133] vprintk_default (kernel/printk/printk.c:1918)
[289683102.626135] vprintk_func (kernel/printk/printk_safe.c:382)
[289683102.626136] printk (kernel/printk/printk.c:1943)
[289683102.626138] ___ratelimit (lib/ratelimit.c:52)
[289683102.626140] __printk_ratelimit (kernel/printk/printk.c:2874)
[289683102.626142] select_fallback_rq (kernel/sched/core.c:1525
(discriminator 1))
[289683102.626144] sched_cpu_dying (kernel/sched/core.c:5500
kernel/sched/core.c:5687)
[289683102.626146] cpuhp_invoke_callback (kernel/cpu.c:182)
[289683102.626148] take_cpu_down (kernel/cpu.c:739)
[289683102.626150] multi_cpu_stop (kernel/stop_machine.c:207)
[289683102.626152] cpu_stopper_thread (kernel/stop_machine.c:480)
[289683102.626154] smpboot_thread_fn (kernel/smpboot.c:164)
[289683102.626156] kthread (kernel/kthread.c:242)
[289683102.626158] ret_from_fork (arch/x86/entry/entry_64.S:437)
[289683102.626159]
[289683102.626161] other info that might help us debug this:
[289683102.626162]
[289683102.626164] Chain exists of:
[289683102.626165]   &port_lock_key --> &p->pi_lock --> &rq->lock
[289683102.626174]
[289683102.626176]  Possible unsafe locking scenario:
[289683102.626177]
[289683102.626179]        CPU0                    CPU1
[289683102.626181]        ----                    ----
[289683102.626183]   lock(&rq->lock);
[289683102.626187]                                lock(&p->pi_lock);
[289683102.626192]                                lock(&rq->lock);
[289683102.626196]   lock(&port_lock_key);
[289683102.626200]
[289683102.626202]  *** DEADLOCK ***
[289683102.626203]
[289683102.626205] 4 locks held by migration/8/62:
[289683102.626206] #0: (&p->pi_lock){-.-.}, at: sched_cpu_dying
(kernel/sched/sched.h:1738 kernel/sched/core.c:5486
kernel/sched/core.c:5687)
[289683102.626214] #1: (&rq->lock){-.-.}, at: sched_cpu_dying
(kernel/sched/sched.h:937 kernel/sched/sched.h:1739
kernel/sched/core.c:5486 kernel/sched/core.c:5687)
[289683102.626221] #2: (printk_ratelimit_state.lock){....}, at:
___ratelimit (lib/ratelimit.c:42)
[289683102.626228] #3: (console_lock){+.+.}, at: vprintk_emit
(kernel/printk/printk.c:1875)
[289683102.626236]
[289683102.626237] stack backtrace:
[289683102.626240] CPU: 8 PID: 62 Comm: migration/8 Not tainted
4.14.0-rc2-next-20170927+ #252
[289683102.626242] Call Trace:
[289683102.626243] dump_stack (lib/dump_stack.c:54)
[289683102.626245] print_circular_bug (kernel/locking/lockdep.c:1261)
[289683102.626247] check_prev_add (kernel/locking/lockdep.c:1894)
[289683102.626249] ? add_lock_to_list.isra.26 (kernel/locking/lockdep.c:402)
[289683102.626251] ? check_usage (kernel/locking/lockdep.c:1875)
[289683102.626253] ? kvm_clock_read
(./arch/x86/include/asm/preempt.h:90 arch/x86/kernel/kvmclock.c:95)
[289683102.626255] ? kvm_sched_clock_read (arch/x86/kernel/kvmclock.c:106)
[289683102.626257] ? sched_clock
(./arch/x86/include/asm/paravirt.h:174 arch/x86/kernel/tsc.c:227)
[289683102.626260] ? check_preemption_disabled (lib/smp_processor_id.c:52)
[289683102.626262] __lock_acquire (kernel/locking/lockdep.c:2022
kernel/locking/lockdep.c:2469 kernel/locking/lockdep.c:3498)
[289683102.626263] ? __lock_acquire (kernel/locking/lockdep.c:2022
kernel/locking/lockdep.c:2469 kernel/locking/lockdep.c:3498)
[289683102.626266] ? add_lock_to_list.isra.26 (kernel/locking/lockdep.c:402)
[289683102.626268] ? debug_check_no_locks_freed (kernel/locking/lockdep.c:3355)
[289683102.626269] ? memcpy (mm/kasan/kasan.c:306)
[289683102.626271] lock_acquire (kernel/locking/lockdep.c:4004)
[289683102.626273] ? serial8250_console_write
(drivers/tty/serial/8250/8250_port.c:3222)
[289683102.626275] _raw_spin_lock_irqsave
(./include/linux/spinlock_api_smp.h:117 kernel/locking/spinlock.c:159)
[289683102.626277] ? serial8250_console_write
(drivers/tty/serial/8250/8250_port.c:3222)
[289683102.626279] serial8250_console_write
(drivers/tty/serial/8250/8250_port.c:3222)
[289683102.626281] ? serial8250_start_tx
(drivers/tty/serial/8250/8250_port.c:3207)
[289683102.626282] ? lock_acquire (kernel/locking/lockdep.c:4011)
[289683102.626284] ? memcpy (mm/kasan/kasan.c:306)
[289683102.626286] univ8250_console_write
(drivers/tty/serial/8250/8250_core.c:598)
[289683102.626288] console_unlock (kernel/printk/printk.c:1693
kernel/printk/printk.c:2353)
[289683102.626290] ? __down_trylock_console_sem (kernel/printk/printk.c:234)
[289683102.626292] vprintk_emit (kernel/printk/printk.c:1876)
[289683102.626294] vprintk_default (kernel/printk/printk.c:1918)
[289683102.626295] vprintk_func (kernel/printk/printk_safe.c:382)
[289683102.626297] printk (kernel/printk/printk.c:1943)
[289683102.626299] ? show_regs_print_info (kernel/printk/printk.c:1943)
[289683102.626301] ? lock_acquire (kernel/locking/lockdep.c:4004)
[289683102.626306] ___ratelimit (lib/ratelimit.c:52)
[289683102.626309] __printk_ratelimit (kernel/printk/printk.c:2874)
[289683102.626311] select_fallback_rq (kernel/sched/core.c:1525
(discriminator 1))
[289683102.626313] sched_cpu_dying (kernel/sched/core.c:5500
kernel/sched/core.c:5687)
[289683102.626315] ? sched_cpu_starting (kernel/sched/core.c:5675)
[289683102.626317] ? rcutree_dying_cpu (kernel/rcu/tree.c:2645
(discriminator 9) ./include/linux/jump_label.h:141 (discriminator 9)
./include/trace/events/rcu.h:63 (discriminator 9)
kernel/rcu/tree.c:2652 (discriminator 9) kernel/rcu/tree.c:3865
(discriminator 9))
[289683102.626319] ? sched_cpu_starting (kernel/sched/core.c:5675)
[289683102.626321] cpuhp_invoke_callback (kernel/cpu.c:182)
[289683102.626324] ? cpu_disable_common (arch/x86/kernel/smpboot.c:1522)
[289683102.626326] take_cpu_down (kernel/cpu.c:739)
[289683102.626328] ? trace_hardirqs_off_caller
(kernel/locking/lockdep.c:2972 (discriminator 3))
[289683102.626330] ? cpuhp_invoke_callback (kernel/cpu.c:716)
[289683102.626333] multi_cpu_stop (kernel/stop_machine.c:207)
[289683102.626335] ? __this_cpu_preempt_check (lib/smp_processor_id.c:63)
[289683102.626337] ? cpu_stop_queue_work (kernel/stop_machine.c:176)
[289683102.626339] cpu_stopper_thread (kernel/stop_machine.c:480)
[289683102.626341] ? cpu_stop_create (kernel/stop_machine.c:458)
[289683102.626344] smpboot_thread_fn (kernel/smpboot.c:164)
[289683102.626346] ? sort_range (kernel/smpboot.c:107)
[289683102.626348] ? schedule (./arch/x86/include/asm/bitops.h:324
(discriminator 1) ./include/linux/thread_info.h:79 (discriminator 1)
./include/linux/sched.h:1605 (discriminator 1)
kernel/sched/core.c:3435 (discriminator 1))
[289683102.626350] ? __kthread_parkme (kernel/kthread.c:188)
[289683102.626352] kthread (kernel/kthread.c:242)
[289683102.626354] ? sort_range (kernel/smpboot.c:107)
[289683102.626356] ? kthread_create_on_node (kernel/kthread.c:198)
[289683102.626358] ret_from_fork (arch/x86/entry/entry_64.S:437)
[289683102.631808] process 9121 (trinity-c78) no longer affine to cpu8
[289683102.797340] smpboot: CPU 8 is now offline

Thanks,
Sasha

Powered by blists - more mailing lists