Re: printk() from NMI backtrace can delay a lot

From: Sergey Senozhatsky
Date: Tue Jul 03 2018 - 12:31:53 EST


Hello, Tejun

On (07/03/18 08:29), Tejun Heo wrote:
> Hello, Sergey.
>
> On Tue, Jul 03, 2018 at 01:30:21PM +0900, Sergey Senozhatsky wrote:
> > Cc-ing Linus, Tejun, Andrew
> > [I'll keep the entire lockdep report]
> >
> > On (07/02/18 19:26), Tetsuo Handa wrote:
> > [..]
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606834] swapper/0/0 is trying to acquire lock:
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606835] 00000000316e1432 (console_owner){-.-.}, at: console_unlock+0x1ce/0x8b0
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606840]
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606841] but task is already holding lock:
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606842] 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606847]
> > > 2018-07-02 12:13:13 192.168.159.129:6666 [ 151.606848] which lock already depends on the new lock.
> ...
> > But anyway. So we can have [but I'm not completely sure. Maybe lockdep has
> > something else on its mind] something like this:
> >
> > CPU1 CPU0
> >
> > #IRQ #soft irq
> > serial8250_handle_irq() wq_watchdog_timer_fn()
> > spin_lock(&uart_port->lock) show_workqueue_state()
> > serial8250_rx_chars() spin_lock(&pool->lock)
> > tty_flip_buffer_push() printk()
> > tty_schedule_flip() serial8250_console_write()
> > queue_work() spin_lock(&uart_port->lock)
> > __queue_work()
> > spin_lock(&pool->lock)
> >
> > We need to break the pool->lock -> uart_port->lock chain.
> >
> > - use printk_deferred() to show WQs states [show_workqueue_state() is
> > a timer callback, so local IRQs are enabled]. But show_workqueue_state()
> > is also available via sysrq.
> >
> > - what Alan Cox suggested: use spin_trylock() in serial8250_console_write()
> > and just discard (do not print anything on console) console->writes() that
> > can deadlock us [uart_port->lock is already locked]. This basically means
> > that sometimes there will be no output on a serial console, or there
> > will be missing line. Which kind of contradicts the purpose of print
> > out.
> >
> > We are facing the risk of no output on serial consoles in both case. Thus
> > there must be some other way out of this.
>
> show_workqueue_state() is only used when something is already horribly
> broken or when invoked through sysrq.

Tetsuo is hammering sysrq for fun and profit ;)

> I'm not sure it's worthwhile to make invasive changes to avoid lockdep
> warnings. If anything, we should make show_workqueue_state() avoid
> grabbing pool->lock (e.g. use trylock and fallback to probe_kernel_reads
> if that fails). I'm a bit skeptical how actually useful that'd be tho.

So, I agree.

Another option *possibly* could be...

... maybe we can brake another lock dependency. I don't quite understand,
and surely I'm missing something here, why serial driver call
tty_flip_buffer_push() under uart_port->lock. E.g.

serial_driver_handle_irq()
{
spin_lock(uart_port->lock);

.. TX() / RX()

tty_flip_buffer_push(uart_port->tty_port);
spin_unlock(uart_port->lock);
}

it might be the case that we can do

serial_driver_handle_irq()
{
spin_loc(uart_port->lock);

.. TX / RX

spin_unlock(uart_port->lock);

tty_flip_buffer_push(uart_port->tty_port);
}

This should break this chain

uart_port->lock -> pool->lock // -> sheduler/etc.


Can we do it? What am I missing?

-ss