On Thu, Aug 13, 2020 at 10:03:44AM -0700, Guenter Roeck wrote: > On 8/13/20 8:33 AM, Guenter Roeck wrote: > > On 8/13/20 7:20 AM, Andy Shevchenko wrote: > >> On Thu, Aug 13, 2020 at 01:59:48PM +0200, Greg KH wrote: > >>> On Wed, Aug 12, 2020 at 10:06:29PM -0700, Guenter Roeck wrote: > >>>> On Wed, Aug 12, 2020 at 08:48:13AM -0700, Guenter Roeck wrote: > >>>>> Hi, > >>>>> > >>>>> crbug.com/1114800 reports a hard lockup due to circular locking in the > >>>>> 8250 console driver. This is seen if CONFIG_PROVE_LOCKING is enabled. > >>>>> > >>>>> Problem is as follows: > >>>>> - serial8250_do_startup() locks the serial (console) port. > >>>>> - serial8250_do_startup() then disables interrupts if interrupts are > >>>>> shared, by calling disable_irq_nosync(). > >>>>> - disable_irq_nosync() calls __irq_get_desc_lock() to lock the interrupt > >>>>> descriptor. > >>>>> - __irq_get_desc_lock() calls lock_acquire() > >>>>> - If CONFIG_PROVE_LOCKING is enabled, validate_chain() and check_noncircular() > >>>>> are called and identify a potential locking error. > >>>>> - This locking error is reported via printk, which ultimately calls > >>>>> serial8250_console_write(). > >>>>> - serial8250_console_write() tries to lock the serial console port. > >>>>> Since it is already locked, the system hangs and ultimately reports > >>>>> a hard lockup. > >>>>> > >>>>> I understand we'll need to figure out and fix what lockdep complains about, > >>>>> and I am working on that. However, even if that is fixed, we'll need a > >>>>> solution for the recursive lock: Fixing the lockdep problem doesn't > >>>>> guarantee that a similar problem (or some other log message) won't be > >>>>> detected and reported sometime in the future while serial8250_do_startup() > >>>>> holds the console port lock. > >>>>> > >>>>> Ideas, anyone ? Everything I came up with so far seems clumsy and hackish. > >>>>> > >>>> > >>>> Turns out the situation is a bit worse than I thought. disable_irq_nosync(), > >>>> when called from serial8250_do_startup(), locks the interrupt descriptor. > >>>> The order of locking is > >>>> serial port lock > >>>> interrupt descriptor lock > >>>> > >>>> At the same time, __setup_irq() locks the interrupt descriptor as well. > >>>> With the descriptor locked, it may report an error message using pr_err(). > >>>> This in turn may call serial8250_console_write(), which will try to lock > >>>> the console serial port. The lock sequence is > >>>> interrupt descriptor lock > >>>> serial port lock > >>>> > >>>> I added the lockdep splat to the bug log at crbug.com/1114800. > >>>> > >>>> Effectively, I think, this means we can't call disable_irq_nosync() > >>>> while holding a serial port lock, or at least not while holding a > >>>> serial port lock that is associated with a console. > >>>> > >>>> The problem was introduced (or, rather, exposed) with upstream commit > >>>> 7febbcbc48fc ("serial: 8250: Check UPF_IRQ_SHARED in advance"). > >>> > >>> Adding Andy, who wrote the above commit :) > >>> > >>> Andy, any thoughts? > >> > >> So, we have here a problem and my commit is indeed revealed it since it's > >> basically did spread of what we used to have only in two drivers (and > >> originally reported problem was against third one, i.e. 8250_pnp) to all 8250. > >> Even if we revert that commit, we got the other problem appear, hence it's a > >> matter who to suffer until the clean solution will be provided. > >> > >> As per earlier discussion [1] (and I Cc'ed this to people from there) it > >> appears there is another issue with RT kernels which brought initially that > >> controversial disable_irq_nosync() call. Same here, if we drop this call > >> somebody will be unsatisfied. > >> > > > > The lock chain in [1] is > > console_owner --> &port_lock_key --> &irq_desc_lock_class > > and in my case ([2], comment 13) it is > > &irq_desc_lock_class --> console_owner --> &port_lock_key > > > > Looks like we just changed the order of locks. > > > >> The real fix possible to go to completely lockless printk(), but on the other > >> hand it probably won't prevent other locking corner cases (dead lock?) in 8250 > >> console write callback. > >> spin_lock_irqsave > >> The fix proposed in [2] perhaps not the way to go either... > >> > > > > The code in [2] (Comment 10) was just a hack to prevent the hard lockup > > from happening and to be able see the lockdep splat. It wasn't supposed > > to fix anything (and it doesn't). > > > > Can we change the order of spin_lock_irqsave / disable_irq_nosync ? > > > > - spin_lock_irqsave(&port->lock, flags); > > if (up->port.irqflags & IRQF_SHARED) > > disable_irq_nosync(port->irq); > > + spin_lock_irqsave(&port->lock, flags); > > > > [ plus of course the same for unlock ] > > > > I tried the above, and it solves the problem for me. It is less than perfect > (interrupts will be disabled for more time if the code has to wait for the > spinlock), but I _think_ it should work. > > Should I submit a patch ? Or is there a major flaw in my thinking ? That's basically what Sergey (IIRC) proposed in [1]. (You missed enable_irq() part in above) I guess we may try it. Sergey, can you submit a formal patch? > >> The idea about not allowing disabling IRQ for console port may be least > >> painful as a (temporary?) mitigation. > >> > >> [1]: https://lore.kernel.org/lkml/CAHQZ30BnfX+gxjPm1DUd5psOTqbyDh4EJE=2=VAMW_VDafctkA@xxxxxxxxxxxxxx/T/#u > >> [2]: https://bugs.chromium.org/p/chromium/issues/detail?id=1114800 -- With Best Regards, Andy Shevchenko