sched: serial port lockdep warning when offlining CPUs

sched: serial port lockdep warning when offlining CPUs

[Sasha Levin]

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

Re: sched: serial port lockdep warning when offlining CPUs

[Peter Zijlstra]

On Thu, Sep 28, 2017 at 02:19:46AM -0700, Sasha Levin wrote:
> 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

This is because you hit a printk() from the scheduler, that's known
broken (along with the rest of printk).

You forgot to actually include that printk() though I suspect it reads
like:

  "process %d (%s) no longer affine to cpu%d\n"

Now that uses printk_deferred() which _should_ work lots better, but
clearly the printk() stuff went wobbly again.

> [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)

Also, could you pretty please not line wrap logs?

Re: sched: serial port lockdep warning when offlining CPUs

[Sergey Senozhatsky]

Hi all,

Peter, thanks for Cc-ing.

On (09/28/17 11:38), Peter Zijlstra wrote:
> On Thu, Sep 28, 2017 at 02:19:46AM -0700, Sasha Levin wrote:
> > 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
> 
> This is because you hit a printk() from the scheduler, that's known
> broken (along with the rest of printk).
> 
> You forgot to actually include that printk() though I suspect it reads
> like:
> 
>   "process %d (%s) no longer affine to cpu%d\n"
> 
> Now that uses printk_deferred() which _should_ work lots better, but
> clearly the printk() stuff went wobbly again.
> 
> > [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)
> 
> Also, could you pretty please not line wrap logs?

I think it's

	if (p->mm && printk_ratelimit())

which calls int ___ratelimit(), which ends up doing

	pr_warn("%s: %d callbacks suppressed\n", func, rs->missed);


which is a "normal" printk from within the scheduler.


out of curiosity, will the following fix the warning

---

 lib/ratelimit.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/lib/ratelimit.c b/lib/ratelimit.c
index 08f8043cac61..bddc55834c2e 100644
--- a/lib/ratelimit.c
+++ b/lib/ratelimit.c
@@ -48,7 +48,8 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
 	if (time_is_before_jiffies(rs->begin + rs->interval)) {
 		if (rs->missed) {
 			if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
-				pr_warn("%s: %d callbacks suppressed\n", func, rs->missed);
+				printk_deferred(KERN_WARN "%s: %d callbacks suppressed\n",
+						func, rs->missed);
 				rs->missed = 0;
 			}
 		}

Re: sched: serial port lockdep warning when offlining CPUs

[Sergey Senozhatsky]

On (09/28/17 19:30), Sergey Senozhatsky wrote:
>  lib/ratelimit.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/lib/ratelimit.c b/lib/ratelimit.c
> index 08f8043cac61..bddc55834c2e 100644
> --- a/lib/ratelimit.c
> +++ b/lib/ratelimit.c
> @@ -48,7 +48,8 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
>  	if (time_is_before_jiffies(rs->begin + rs->interval)) {
>  		if (rs->missed) {
>  			if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
> -				pr_warn("%s: %d callbacks suppressed\n", func, rs->missed);
> +				printk_deferred(KERN_WARN "%s: %d callbacks suppressed\n",

oops...				s/KERN_WARN/KERN_WARNING/

sorry about that.

> +						func, rs->missed);
>  				rs->missed = 0;
>  			}
>  		}


---
 lib/ratelimit.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/lib/ratelimit.c b/lib/ratelimit.c
index 08f8043cac61..d01f47135239 100644
--- a/lib/ratelimit.c
+++ b/lib/ratelimit.c
@@ -48,7 +48,9 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
 	if (time_is_before_jiffies(rs->begin + rs->interval)) {
 		if (rs->missed) {
 			if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
-				pr_warn("%s: %d callbacks suppressed\n", func, rs->missed);
+				printk_deferred(KERN_WARNING
+						"%s: %d callbacks suppressed\n",
+						func, rs->missed);
 				rs->missed = 0;
 			}
 		}
-- 
2.14.2

Re: sched: serial port lockdep warning when offlining CPUs

[Levin, Alexander (Sasha Levin)]

On Thu, Sep 28, 2017 at 08:36:07PM +0900, Sergey Senozhatsky wrote:
>On (09/28/17 19:30), Sergey Senozhatsky wrote:
>>  lib/ratelimit.c | 3 ++-
>>  1 file changed, 2 insertions(+), 1 deletion(-)
>>
>> diff --git a/lib/ratelimit.c b/lib/ratelimit.c
>> index 08f8043cac61..bddc55834c2e 100644
>> --- a/lib/ratelimit.c
>> +++ b/lib/ratelimit.c
>> @@ -48,7 +48,8 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
>>  	if (time_is_before_jiffies(rs->begin + rs->interval)) {
>>  		if (rs->missed) {
>>  			if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
>> -				pr_warn("%s: %d callbacks suppressed\n", func, rs->missed);
>> +				printk_deferred(KERN_WARN "%s: %d callbacks suppressed\n",
>
>oops...				s/KERN_WARN/KERN_WARNING/
>
>sorry about that.

Okay, that seems to have delt with the callbacks supressed issue.

I also seem to be hitting it as a result of the scheduler triggering a WARN, where print_stack_trace(), for example, just uses printk().

Now I'm not sure what's your approach here, do we keep converting printk to printk_deferred one by one until we whacked every mole?

-- 

Thanks,
Sasha

Re: sched: serial port lockdep warning when offlining CPUs

[Sergey Senozhatsky]

On (09/28/17 11:45), Levin, Alexander (Sasha Levin) wrote:
[..]

> Now I'm not sure what's your approach here, do we keep converting printk to printk_deferred one by one until we whacked every mole?

well... basically, yes.

	-ss

Re: sched: serial port lockdep warning when offlining CPUs

[Peter Zijlstra]

(please linewrap normal text at 72 chars)

On Thu, Sep 28, 2017 at 11:45:30AM +0000, Levin, Alexander (Sasha Levin) wrote:
> Okay, that seems to have delt with the callbacks supressed issue.
> 
> I also seem to be hitting it as a result of the scheduler triggering a
> WARN, where print_stack_trace(), for example, just uses printk().
> 
> Now I'm not sure what's your approach here, do we keep converting
> printk to printk_deferred one by one until we whacked every mole?

Nah.. WARN's _should_ not trigger. If they do we fix that.

Getting a lockdep splat after a WARN is something I can live with.

And you really don't want that deferred nonsense for WARNs, because that
means you'll risk not over getting the output.

Re: sched: serial port lockdep warning when offlining CPUs

[Peter Zijlstra]

On Thu, Sep 28, 2017 at 02:05:32PM +0200, Peter Zijlstra wrote:
> (please linewrap normal text at 72 chars)
> 
> On Thu, Sep 28, 2017 at 11:45:30AM +0000, Levin, Alexander (Sasha Levin) wrote:
> > Okay, that seems to have delt with the callbacks supressed issue.
> > 
> > I also seem to be hitting it as a result of the scheduler triggering a
> > WARN, where print_stack_trace(), for example, just uses printk().
> > 
> > Now I'm not sure what's your approach here, do we keep converting
> > printk to printk_deferred one by one until we whacked every mole?
> 
> Nah.. WARN's _should_ not trigger. If they do we fix that.
> 
> Getting a lockdep splat after a WARN is something I can live with.
> 
> And you really don't want that deferred nonsense for WARNs, because that
> means you'll risk not over getting the output.

Note that I'm not likely to care too much either way, because I'm simply
not using any of that printk() nonsense ;-)


I'll repost my patches now; otherwise I'll forget again anyway.

Re: sched: serial port lockdep warning when offlining CPUs

[Sergey Senozhatsky]

On (09/28/17 14:07), Peter Zijlstra wrote:
[..]
> > Nah.. WARN's _should_ not trigger. If they do we fix that.
> > 
> > Getting a lockdep splat after a WARN is something I can live with.
> > 
> > And you really don't want that deferred nonsense for WARNs, because that
> > means you'll risk not over getting the output.
> 
> Note that I'm not likely to care too much either way, because I'm simply
> not using any of that printk() nonsense ;-)
> 
> 
> I'll repost my patches now; otherwise I'll forget again anyway.

#define printk printk_deferred

should also do the trick and... make the kernel great again!  :)

	-ss

Re: sched: serial port lockdep warning when offlining CPUs

[Peter Zijlstra]

On Thu, Sep 28, 2017 at 09:15:21PM +0900, Sergey Senozhatsky wrote:
> > I'll repost my patches now; otherwise I'll forget again anyway.
> 
> #define printk printk_deferred
> 
> should also do the trick and... make the kernel great again!  :)

That makes the kernel die silently, instead of first telling me wtf
happend ;-)

Re: sched: serial port lockdep warning when offlining CPUs

[Peter Zijlstra]

On Thu, Sep 28, 2017 at 07:30:32PM +0900, Sergey Senozhatsky wrote:
> ---
> 
>  lib/ratelimit.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/lib/ratelimit.c b/lib/ratelimit.c
> index 08f8043cac61..bddc55834c2e 100644
> --- a/lib/ratelimit.c
> +++ b/lib/ratelimit.c
> @@ -48,7 +48,8 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
>  	if (time_is_before_jiffies(rs->begin + rs->interval)) {
>  		if (rs->missed) {
>  			if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
> -				pr_warn("%s: %d callbacks suppressed\n", func, rs->missed);
> +				printk_deferred(KERN_WARN "%s: %d callbacks suppressed\n",
> +						func, rs->missed);
>  				rs->missed = 0;
>  			}
>  		}

Oh cute; I figured it was the syslog daemon suppressing multiple
identical lines, but yes the above looks very plausible.

Re: sched: serial port lockdep warning when offlining CPUs

[Sergey Senozhatsky]

On (09/28/17 13:47), Peter Zijlstra wrote:
> On Thu, Sep 28, 2017 at 07:30:32PM +0900, Sergey Senozhatsky wrote:
> > ---
> > 
> >  lib/ratelimit.c | 3 ++-
> >  1 file changed, 2 insertions(+), 1 deletion(-)
> > 
> > diff --git a/lib/ratelimit.c b/lib/ratelimit.c
> > index 08f8043cac61..bddc55834c2e 100644
> > --- a/lib/ratelimit.c
> > +++ b/lib/ratelimit.c
> > @@ -48,7 +48,8 @@ int ___ratelimit(struct ratelimit_state *rs, const char *func)
> >  	if (time_is_before_jiffies(rs->begin + rs->interval)) {
> >  		if (rs->missed) {
> >  			if (!(rs->flags & RATELIMIT_MSG_ON_RELEASE)) {
> > -				pr_warn("%s: %d callbacks suppressed\n", func, rs->missed);
> > +				printk_deferred(KERN_WARN "%s: %d callbacks suppressed\n",
> > +						func, rs->missed);
> >  				rs->missed = 0;
> >  			}
> >  		}
> 
> Oh cute; I figured it was the syslog daemon suppressing multiple
> identical lines, but yes the above looks very plausible.

seems to be stable v4.8+ material.

Fixes: 6b1d174b0c27b ("ratelimit: extend to print suppressed messages on release")

I'll send out a patch.

	-ss

Re: sched: serial port lockdep warning when offlining CPUs

[Levin, Alexander (Sasha Levin)]

On Thu, Sep 28, 2017 at 11:38:47AM +0200, Peter Zijlstra wrote:
>On Thu, Sep 28, 2017 at 02:19:46AM -0700, Sasha Levin wrote:
>> 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
>
>This is because you hit a printk() from the scheduler, that's known
>broken (along with the rest of printk).
>
>You forgot to actually include that printk() though I suspect it reads
>like:
>
>  "process %d (%s) no longer affine to cpu%d\n"
>
>Now that uses printk_deferred() which _should_ work lots better, but
>clearly the printk() stuff went wobbly again.

Hm, so is this an actual possible lockup, or just a false positive?

>> [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)
>
>Also, could you pretty please not line wrap logs?

Sure, I had to resort to using gmail at a conference :(

-- 

Thanks,
Sasha

Re: sched: serial port lockdep warning when offlining CPUs

[Sergey Senozhatsky]

On (09/28/17 11:04), Levin, Alexander (Sasha Levin) wrote:
> On Thu, Sep 28, 2017 at 11:38:47AM +0200, Peter Zijlstra wrote:
> >On Thu, Sep 28, 2017 at 02:19:46AM -0700, Sasha Levin wrote:
> >> 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
> >
> >This is because you hit a printk() from the scheduler, that's known
> >broken (along with the rest of printk).
> >
> >You forgot to actually include that printk() though I suspect it reads
> >like:
> >
> >  "process %d (%s) no longer affine to cpu%d\n"
> >
> >Now that uses printk_deferred() which _should_ work lots better, but
> >clearly the printk() stuff went wobbly again.
> 
> Hm, so is this an actual possible lockup, or just a false positive?

a possible one.

printk() used to lockdep_off()/lockdep_on() in "dangerous places"
before, but not anymore.

	-ss

Re: sched: serial port lockdep warning when offlining CPUs

[Peter Zijlstra]

On Thu, Sep 28, 2017 at 08:13:26PM +0900, Sergey Senozhatsky wrote:
> On (09/28/17 11:04), Levin, Alexander (Sasha Levin) wrote:
> > On Thu, Sep 28, 2017 at 11:38:47AM +0200, Peter Zijlstra wrote:
> > >On Thu, Sep 28, 2017 at 02:19:46AM -0700, Sasha Levin wrote:
> > >> 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
> > >
> > >This is because you hit a printk() from the scheduler, that's known
> > >broken (along with the rest of printk).
> > >
> > >You forgot to actually include that printk() though I suspect it reads
> > >like:
> > >
> > >  "process %d (%s) no longer affine to cpu%d\n"
> > >
> > >Now that uses printk_deferred() which _should_ work lots better, but
> > >clearly the printk() stuff went wobbly again.
> > 
> > Hm, so is this an actual possible lockup, or just a false positive?
> 
> a possible one.

Yeah, printk() can deadlock when used from scheduler locks / NMI context
and a few other crucial places. printk_deferred() used to be 'safe'
though.