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

[Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>]

Cc-ng Alan, Greg, Jiri
A lockdep report: https://lore.kernel.org/lkml/20180703043021.GA547@jagdpanzerIV/T/#u

On (07/10/18 13:50), Petr Mladek wrote:
> > 
> > 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'm lacking some ["a lot of", actually] knowledge here.

Alan, Jiri could you help us?

Correct me if I'm wrong. I thought that flip buffers are used to "cache"
received chars/commands from the device before device "sends" (flushes)
them to ldisc. So chars are added to flip buffers by the device itself - RX
function, which is most commonly called from the device's IRQ handler.
That's why we see things like

	foo_irq_handler()
	{
	...	spin_lock(uart_port->lock);

		foo_TX_chars();
		tty_flip_buffer_push();  // tty_schedule_flip()
	...
		spin_unlock(uart_port->lock);
	}

or

	foo_irq_handler()
	{
	...	spin_lock(uart_port->lock);

		foo_TX_chars()
		{
			...
			tty_insert_flip_char();
			tty_schedule_flip();
		}
	...
		spin_unlock(uart_port->lock);
	}

So it seems that flip buffers are for RX routines. Is this right?

Thus, if foo_irq_handler()->tty_flip_buffer_push() raced with something, then
it must have been another IRQ that appended data to the same uart_port flip
buffer. Which, probably, should not happen. There should be no other race
conditions. Correct?

So I'm still wondering if we can safely change this

	foo_irq_handler()
	{
	...	spin_lock(uart_port->lock);

		foo_TX_chars();
		tty_flip_buffer_push();  // tty_schedule_flip()
	...
		spin_unlock(uart_port->lock);
	}

to this

	foo_irq_handler()
	{
	...	spin_lock(uart_port->lock);

		foo_TX_chars();
	...
		spin_unlock(uart_port->lock);

		tty_flip_buffer_push();  // tty_schedule_flip()
	}

Alan, Jiri, can we do this?

> 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.

Hmm. Not sure, maybe I'm missing something. In this particular case we
don't call printk() under port->lock, so it doesn't matter if we are in
"normal" printk mode or in some "safe" printk mode. What we have is:

	UART port->lock --> WQ pool->lock

Which is OK, and port->lock is sort of "innocent".

It's the stuff that we do under WQ pool->lock that hurts (deadlock).

	WQ pool->lock -> printk -> UART port->lock

If we want printk_deferred() / printk_safe() to help us here, then
we need to switch to printk_deferred() / printk_safe() every time
we take WQ pool->lock. Which is, basically, what I have already
suggested.

But I'd rather try to move tty_flip_buffer_push() out of uart_port->lock
scope [if possible], so we would break the
		uart_port->lock -> WQ pool->lock
dependency.

	-ss