lkml.org 
[lkml]   [2018]   [Jul]   [10]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: printk() from NMI backtrace can delay a lot
On Wed 2018-07-04 01:31:45, Sergey Senozhatsky wrote:
> 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);

Hmm, this looks racy. For example, I see the following in
serial_lpc32xx_interrupt():

tty_insert_flip_char(tport, 0, TTY_OVERRUN);
tty_schedule_flip(tport);

where tty_insert_flip_char() manipulates flag/char/used:

*flag_buf_ptr(tb, tb->used) = flag;
*char_buf_ptr(tb, tb->used++) = ch;

and tty_schedule_flip() copies "used" -> "commit":

smp_store_release(&buf->tail->commit, buf->tail->used);
queue_work(system_unbound_wq, &buf->work);

I do not have the entire picture but I guess that we need to
commit only correctly set characters and flags. Therefore
the manipulation of flag/ch/used/commit need to be synchronized.
It seems that &port->lock is used for this.


Sigh, I am not aware of any good solution.

I agree with Tejun that using printk_deferred() in
show_workqueue_state() is questionable. Basically any deferring
is risky. There is no guarantee that the deferred operation will
get realized.

Also Alan Cox's idea: "use spin_trylock() in
serial8250_console_write()" has problems. Sergey already mentioned
that we might then miss random lines on a particular console.

So far, the best (and realistic?) idea seems to be switching to
printk_deferred() context when port->lock is taken. It would
be a well defined pattern that people might get used to.

Of course, the best solution would be to have printk and
console->write() lock-less. But this would mean a lot of
tricky code unless anyone comes with a brilliant design.

Best Regards,
Petr

\
 
 \ /
  Last update: 2018-07-10 13:51    [W:0.112 / U:4.056 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site