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

[Tejun Heo]

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

Thanks.

-- 
tejun