Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752520AbdI1JUJ (ORCPT ); Thu, 28 Sep 2017 05:20:09 -0400 Received: from mail-qt0-f195.google.com ([209.85.216.195]:34914 "EHLO mail-qt0-f195.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752376AbdI1JUH (ORCPT ); Thu, 28 Sep 2017 05:20:07 -0400 X-Google-Smtp-Source: AOwi7QBOC8vy8KZ/j9GfRz17ph0iNNBKWbc8eJMl4MMZNHLf9VOmtXJ8FFnKTwYhM38exlTEUdrPS1hhdajicbfXigg= MIME-Version: 1.0 From: Sasha Levin Date: Thu, 28 Sep 2017 02:19:46 -0700 Message-ID: Subject: sched: serial port lockdep warning when offlining CPUs To: Peter Zijlstra , Thomas Gleixner , Ingo Molnar Cc: "linux-kernel@vger.kernel.org List" , alexander.levin@verizon.com Content-Type: text/plain; charset="UTF-8" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 14858 Lines: 277 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