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

[Sergey Senozhatsky]

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