Re: lockdep and preemptoff tracer are fighting again.

[Steven Rostedt]

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

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/