Re: [prink] BUG: spinlock lockup suspected on CPU#0, swapper/1

[Jan Kara <jack@suse.cz>]

On Fri 30-05-14 18:19:48, Peter Zijlstra wrote:
> On Fri, May 30, 2014 at 06:16:47PM +0200, Peter Zijlstra wrote:
> > On Fri, May 30, 2014 at 05:50:51PM +0200, Jan Kara wrote:
> > > > [    7.492350] ======================================================
> > > > [    7.492350] [ INFO: possible circular locking dependency detected ]
> > > > [    7.492350] 3.15.0-rc5-00567-gbafe980 #1 Not tainted
> > > > [    7.492350] -------------------------------------------------------
> > > > [    7.492350] swapper/1 is trying to acquire lock:
> > > > [    7.492350]  (&irq_desc_lock_class){-.-...}, at: [<8107dc8c>] __irq_get_desc_lock+0x3c/0x70
> > > > [    7.492350] 
> > > > [    7.492350] but task is already holding lock:
> > > > [    7.492350]  (&port_lock_key){......}, at: [<815f5b27>] serial8250_startup+0x337/0x720
> > > > [    7.492350] 
> > > > [    7.492350] which lock already depends on the new lock.
> > > > [    7.492350] 
> > > > [    7.492350] 
> > > > [    7.492350] the existing dependency chain (in reverse order) is:
> > > > [    7.492350] 
> > > > -> #2 (&port_lock_key){......}:
> > > > [    7.492350]        [<810750e5>] lock_acquire+0x85/0x190
> > > > [    7.492350]        [<81baed9d>] _raw_spin_lock_irqsave+0x4d/0x60
> > > > [    7.492350]        [<8106eb1c>] down_trylock+0xc/0x30
> > > > [    7.492350]        [<8107b795>] console_trylock+0x15/0xb0
> > > > [    7.492350]        [<8107be8f>] vprintk_emit+0x14f/0x4d0
> > > > [    7.492350]        [<81b969b9>] printk+0x38/0x3a
> > > > [    7.492350]        [<82137f78>] print_ICs+0x5b/0x3e7
> > > > [    7.492350]        [<8212bb41>] do_one_initcall+0x8b/0x128
> > > > [    7.492350]        [<8212bd7d>] kernel_init_freeable+0x19f/0x236
> > > > [    7.492350]        [<81b9238b>] kernel_init+0xb/0xd0
> > > > [    7.492350]        [<81bb0080>] ret_from_kernel_thread+0x20/0x30
> > >
> > >   But this looks really strange. How can we possibly get port_lock_key in
> > > down_trylock() which calls raw_spin_lock_irqsave() on console_sem->lock?
> > > That looks like some strange lockdep key aliasing issue? Peter do you have
> > > any idea?
> > 
> > No, strange that, I can't say I've ever seen a bogus stracktrace in
> > lockdep reports like this.
> > 
> > So this is through: check_prev_add()->save_trace(). And that doesn't
> > reuse entries, at worst it can truncate a trace when we run out of
> > entries, but the above looks complete since it terminates in
> > lock_acquire(), which is the right place to be.
> > 
> > But its worse than that, the above trace should link i8259A_lock to
> > port_lock_key, and I can't see where we would have taken i8259A_lock
> > either.
> 
> Oh, wait, I missed it, that would be: print_ICs()->print_PIC(), it takes
> that lock there.
  Yeah, so as much as the lockdep reported stack trace looks strange I can
now see how a locking problem lockdep reports can happen. We really do call
printk() under i8259A_lock in print_PIC() and so the locking chain lockdep
found is real. Luckily it likely cannot lead to any real problems because
printk only happens during early init.

In any case it is another example of a problem that was just uncovered by
my change which increased lockdep coverage of printk code. I'll send a fix
to x86 maintainers.

								Honza
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR