Re: lockdep and preemptoff tracer are fighting again.

Steven Rostedt
2009-01-22T22:28:06Z

On Thu, 22 Jan 2009, Peter Zijlstra wrote:

> On Thu, 2009-01-22 at 15:40 -0500, Steven Rostedt wrote:
> >
> > Hey guys, I can consistently hit this bug when running the preempt tracer:
> >

[ shortened ]

> > ------------[ cut here ]------------
> > WARNING: at kernel/lockdep.c:2899 check_flags+0x154/0x18b()
> > Call Trace:
> > [<ffffffff802699bf>] check_flags+0x154/0x18b
> > [<ffffffff8026de66>] lock_acquire+0x41/0xa9
> > [<ffffffff80543e27>] _spin_lock_irqsave+0x46/0x59
> > [<ffffffff8029519c>] ring_buffer_reset_cpu+0x31/0x6b
> > [<ffffffff80299ec6>] tracing_reset+0x46/0x9b
> > [<ffffffff8029e33f>] trace_preempt_off+0x100/0x14d
> > [<ffffffff80546df1>] add_preempt_count+0x12d/0x132
> > [<ffffffff8024b44f>] __local_bh_disable+0xc0/0xf0
> > [<ffffffff8024b491>] local_bh_disable+0x12/0x14
> > [<ffffffff80543b95>] _spin_lock_bh+0x16/0x4c
> > [<ffffffff804ab49a>] lock_sock_nested+0x28/0xe5
> > [<ffffffff804eff87>] tcp_sendmsg+0x27/0xac2
> > [<ffffffff804a82b0>] sock_aio_write+0x109/0x11d
> > [<ffffffff802d8881>] do_sync_write+0xf0/0x137
> > [<ffffffff802d921c>] vfs_write+0x103/0x17d
> > [<ffffffff802d978f>] sys_write+0x4e/0x8c
> > [<ffffffff8020c64b>] system_call_fastpath+0x16/0x1b
> > ---[ end trace 713cc9df66b54d6e ]---
> >
> >
> > The cause is simple. The following happens:
> >

> > lock_acquire calls check_flags which performs this check:
> >
> > if (!hardirq_count()) {
> > if (softirq_count())
> > DEBUG_LOCKS_WARN_ON(current->softirqs_enabled);
> > else
> > DEBUG_LOCKS_WARN_ON(!current->softirqs_enabled);
> > }
> >

>
> __local_bh_disable()
> {
> unsigned long flags;
>
> raw_local_irq_save(flags);
>
> /*
> * comment explaining why add_preempt_count() doesn't work
> */
> preempt_count() += SOFTIRQ_OFFSET;
> if (softirq_count() == SOFTIRQ_OFFSET)
> trace_softirqs_off(ip);
> if (preempt_count() == SOFTIRQ_OFFSET)
> trace_preempt_off(CALLER_ADDR0, ...);
> raw_local_irq_restore(flags);
> }

Almost ;-)

With the above I get:

------------[ cut here ]------------
WARNING: at kernel/lockdep.c:2887 check_flags+0xba/0x18b()
Call Trace:
[<ffffffff80245ee7>] warn_slowpath+0xd8/0xf7
[<ffffffff802699a1>] check_flags+0xba/0x18b
[<ffffffff8026dee2>] lock_acquire+0x41/0xa9
[<ffffffff80543c3f>] _spin_lock_bh+0x40/0x4c
[<ffffffff804ab51a>] lock_sock_nested+0x28/0xe5
[<ffffffff804f0007>] tcp_sendmsg+0x27/0xac2
[<ffffffff804a8330>] sock_aio_write+0x109/0x11d
[<ffffffff802d88fd>] do_sync_write+0xf0/0x137
[<ffffffff802d9298>] vfs_write+0x103/0x17d
[<ffffffff802d980b>] sys_write+0x4e/0x8c
[<ffffffff8020c64b>] system_call_fastpath+0x16/0x1b
---[ end trace 5057c94a6be2ce17 ]---

Which is hitting:

if (irqs_disabled_flags(flags)) {
if (DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled)) {
printk("possible reason: unannotated irqs-off.\n");
}
} else {

Which is caused by the "raw_local_irq_save(flags) in the local_bh_disable
;-)

The solution is to move the "if (preempt_count() == SOFTIRQ_OFFSET)"
outside the raw_local_irq_restore(flags). There should be nothing wrong
with doing this outside the irqs disabled. The check in add_preempt_count
does not disable interrupts either.

Patch soon on its way, Thanks!

-- Steve