bug: ftrace & lockdep badness

bug: ftrace & lockdep badness

[Heiko Carstens]

Hi Steven,

enabling preemptirqsoff tracing gives me this on a lockdep enabled kernel:

Badness at kernel/lockdep.c:2894
Modules linked in:
CPU: 0 Not tainted 2.6.28-rc3-00031-ga75952b-dirty #72
Process sshd (pid: 2542, task: 000000003397d7a8, ksp: 0000000033abb618)
Krnl PSW : 0404c00180000000 0000000000078770 (check_flags+0x12c/0x160)
           R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
Krnl GPRS: 0000000000000000 0000000000dcda88 0000000000000000 000000000000000f
           0000000000000000 0000000000000000 0000000000000002 0000000000000000
           0000000000000000 0000000000000000 000000003fe7d428 0000000033abb170
           0000000000557fb8 000000000038b210 0000000000078758 0000000033abb170
Krnl Code: 0000000000078764: bf2f1000           icm     %r2,15,0(%r1)
           0000000000078768: a774ffa7           brc     7,786b6
           000000000007876c: a7f40001           brc     15,7876e
          >0000000000078770: a7f4ffa3           brc     15,786b6
           0000000000078774: c0e5000a53ea       brasl   %r14,1c2f48
           000000000007877a: 1222               ltr     %r2,%r2
           000000000007877c: a784000b           brc     8,78792
           0000000000078780: c010006aa984       larl    %r1,dcda88
Call Trace:
([<0000000033abb188>] 0x33abb188)
 [<000000000007e76a>] lock_acquire+0x52/0xbc
 [<000000000037618c>] _spin_lock_irqsave+0x6c/0xb0
 [<000000000009d52e>] ring_buffer_reset_cpu+0x6e/0x114
 [<00000000000a46c0>] tracing_reset+0x84/0xe8
 [<00000000000a5632>] trace_preempt_off+0x112/0x178
 [<0000000000378888>] add_preempt_count+0xa4/0x130
 [<00000000000539e0>] __local_bh_disable+0x54/0xcc
 [<0000000000053a82>] local_bh_disable+0x2a/0x38
 [<0000000000376002>] _spin_lock_bh+0x2e/0xa4
 [<00000000002a1baa>] lock_sock_nested+0x4a/0x118
 [<00000000002e9e86>] tcp_sendmsg+0x42/0xdc0
 [<000000000029cd3c>] sock_aio_write+0x130/0x180
 [<00000000000ea36c>] do_sync_write+0xdc/0x134
 [<00000000000eafe8>] vfs_write+0x154/0x15c
 [<00000000000eb106>] sys_write+0x52/0xa8
 [<000000000002a950>] sys32_write+0x2c/0x4c
 [<0000000000026f80>] sysc_noemu+0x10/0x16
 [<0000000077c5c186>] 0x77c5c186
INFO: lockdep is turned off.

Seems to be that the following happens:

__local_bh_disable() calls add_preempt_count() which adds something to
preempt_count().
After this addition softirq_count() will return something != 0.
However current->softirqs_enabled is still 1 since we haven't called
trace_softirqs_off() yet.
But we call trace_preempt_off() instead which will grab a lock in the
ringbuffer code and that will trigger this check in lockdep.c:

        if (!hardirq_count()) {
                if (softirq_count())
                        DEBUG_LOCKS_WARN_ON(current->softirqs_enabled);

I assume this is a known bug. Is there any fix available?

Re: bug: ftrace & lockdep badness

[Steven Rostedt]

On Wed, 5 Nov 2008, Heiko Carstens wrote:

> enabling preemptirqsoff tracing gives me this on a lockdep enabled kernel:
> 
> Badness at kernel/lockdep.c:2894
> Modules linked in:
> CPU: 0 Not tainted 2.6.28-rc3-00031-ga75952b-dirty #72
> Process sshd (pid: 2542, task: 000000003397d7a8, ksp: 0000000033abb618)
> Krnl PSW : 0404c00180000000 0000000000078770 (check_flags+0x12c/0x160)
>            R:0 T:1 IO:0 EX:0 Key:0 M:1 W:0 P:0 AS:3 CC:0 PM:0 EA:3
> Krnl GPRS: 0000000000000000 0000000000dcda88 0000000000000000 000000000000000f
>            0000000000000000 0000000000000000 0000000000000002 0000000000000000
>            0000000000000000 0000000000000000 000000003fe7d428 0000000033abb170
>            0000000000557fb8 000000000038b210 0000000000078758 0000000033abb170
> Krnl Code: 0000000000078764: bf2f1000           icm     %r2,15,0(%r1)
>            0000000000078768: a774ffa7           brc     7,786b6
>            000000000007876c: a7f40001           brc     15,7876e
>           >0000000000078770: a7f4ffa3           brc     15,786b6
>            0000000000078774: c0e5000a53ea       brasl   %r14,1c2f48
>            000000000007877a: 1222               ltr     %r2,%r2
>            000000000007877c: a784000b           brc     8,78792
>            0000000000078780: c010006aa984       larl    %r1,dcda88
> Call Trace:
> ([<0000000033abb188>] 0x33abb188)
>  [<000000000007e76a>] lock_acquire+0x52/0xbc
>  [<000000000037618c>] _spin_lock_irqsave+0x6c/0xb0
>  [<000000000009d52e>] ring_buffer_reset_cpu+0x6e/0x114
>  [<00000000000a46c0>] tracing_reset+0x84/0xe8
>  [<00000000000a5632>] trace_preempt_off+0x112/0x178
>  [<0000000000378888>] add_preempt_count+0xa4/0x130
>  [<00000000000539e0>] __local_bh_disable+0x54/0xcc
>  [<0000000000053a82>] local_bh_disable+0x2a/0x38
>  [<0000000000376002>] _spin_lock_bh+0x2e/0xa4
>  [<00000000002a1baa>] lock_sock_nested+0x4a/0x118
>  [<00000000002e9e86>] tcp_sendmsg+0x42/0xdc0
>  [<000000000029cd3c>] sock_aio_write+0x130/0x180
>  [<00000000000ea36c>] do_sync_write+0xdc/0x134
>  [<00000000000eafe8>] vfs_write+0x154/0x15c
>  [<00000000000eb106>] sys_write+0x52/0xa8
>  [<000000000002a950>] sys32_write+0x2c/0x4c
>  [<0000000000026f80>] sysc_noemu+0x10/0x16
>  [<0000000077c5c186>] 0x77c5c186
> INFO: lockdep is turned off.
> 
> Seems to be that the following happens:
> 
> __local_bh_disable() calls add_preempt_count() which adds something to
> preempt_count().
> After this addition softirq_count() will return something != 0.
> However current->softirqs_enabled is still 1 since we haven't called
> trace_softirqs_off() yet.
> But we call trace_preempt_off() instead which will grab a lock in the
> ringbuffer code and that will trigger this check in lockdep.c:
> 
>         if (!hardirq_count()) {
>                 if (softirq_count())
>                         DEBUG_LOCKS_WARN_ON(current->softirqs_enabled);
> 
> I assume this is a known bug. Is there any fix available?


Actually this is the first time that I've seen this. I'm off to school, 
and will look at this when I get back (around 10:30 EST).

-- Steve

Re: bug: ftrace & lockdep badness

[Steven Rostedt]

On Wed, 5 Nov 2008, Heiko Carstens wrote:

> Hi Steven,
> 
> enabling preemptirqsoff tracing gives me this on a lockdep enabled kernel:
> 
> Badness at kernel/lockdep.c:2894

[...]

> Call Trace:
> ([<0000000033abb188>] 0x33abb188)
>  [<000000000007e76a>] lock_acquire+0x52/0xbc
>  [<000000000037618c>] _spin_lock_irqsave+0x6c/0xb0
>  [<000000000009d52e>] ring_buffer_reset_cpu+0x6e/0x114
>  [<00000000000a46c0>] tracing_reset+0x84/0xe8
>  [<00000000000a5632>] trace_preempt_off+0x112/0x178
>  [<0000000000378888>] add_preempt_count+0xa4/0x130
>  [<00000000000539e0>] __local_bh_disable+0x54/0xcc
>  [<0000000000053a82>] local_bh_disable+0x2a/0x38

[...]

> Seems to be that the following happens:
> 
> __local_bh_disable() calls add_preempt_count() which adds something to
> preempt_count().
> After this addition softirq_count() will return something != 0.
> However current->softirqs_enabled is still 1 since we haven't called
> trace_softirqs_off() yet.
> But we call trace_preempt_off() instead which will grab a lock in the
> ringbuffer code and that will trigger this check in lockdep.c:
> 
>         if (!hardirq_count()) {
>                 if (softirq_count())
>                         DEBUG_LOCKS_WARN_ON(current->softirqs_enabled);
> 
> I assume this is a known bug. Is there any fix available?

Yes, this does seem to be the case.

Perhaps Peter or Ingo can come up with some ideas on how to solve this. 
Let me try to rephrase the problem.

In __local_bh_disable() we call add_preempt_count(SOFTIRQ_OFFSET)

in add_preempt_count (in sched.c)

  preempt_count() += val;
  if (preempt_count() == val)
	trace_preempt_off(...)

in trace_preempt_off we record into the ring buffer. But the ring buffer 
will call spin_lock_irqsave (it use to be raw_spin_lock, where this was 
not an issue). Note, there is development to make the ring buffer 
lockless, but until that time, we need to come up with a real solution.

Now we enter the lockdep code, but we are not in a full state transition 
and we get a WARN_ON triggered by the lockdep code (have SOFTIRQ_OFFSET 
set but we did not yet tell lockdep we are in a softirq).

This is the type of problems we deal with when we have the tracer tracing 
lockdep code at the same time the lockdep code is checking the tracer.

-- Steve

Re: bug: ftrace & lockdep badness

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> This is the type of problems we deal with when we have the tracer 
> tracing lockdep code at the same time the lockdep code is checking 
> the tracer.

ok ... you are right, i guess we need to go back to raw locks after 
all?

	Ingo

Re: bug: ftrace & lockdep badness

[Steven Rostedt]

On Wed, 5 Nov 2008, Ingo Molnar wrote:

> 
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > This is the type of problems we deal with when we have the tracer 
> > tracing lockdep code at the same time the lockdep code is checking 
> > the tracer.
> 
> ok ... you are right, i guess we need to go back to raw locks after 
> all?

I do like the fact that lockdep checks it too. But there's times that we 
can not do that.

Perhaps we can do something in between.

Make a rb_spin_lock macro inside ring_buffer.c that can be either a 
spin_lock or a raw_spin_lock.  There are some tracers that must have this 
as a raw (function trace, irqsoff and preemptoff), but the rest should be 
fine. We can make it where the rb_spin_lock is a raw lock when any of 
those three tracers are configured, and make it into a normal lock when 
they are not.

This way we can still test the integrity of the ring_buffer for other 
tracers. We just need to be careful when we are using function tracing or 
irqs/preempt off tracing. But we need to be careful with those anyway.

-- Steve

Re: bug: ftrace & lockdep badness

[Frédéric Weisbecker]

2008/11/5 Steven Rostedt <rostedt@goodmis.org>:
> I do like the fact that lockdep checks it too. But there's times that we
> can not do that.
>
> Perhaps we can do something in between.
>
> Make a rb_spin_lock macro inside ring_buffer.c that can be either a
> spin_lock or a raw_spin_lock.  There are some tracers that must have this
> as a raw (function trace, irqsoff and preemptoff), but the rest should be
> fine. We can make it where the rb_spin_lock is a raw lock when any of
> those three tracers are configured, and make it into a normal lock when
> they are not.


But this way we won't be able to have lockdep checks when only one of
those "raw-need" tracers are
configured. Wouldn't it better to set it as a function pointer? It
would dynamically reference spin_lock or
raw_spin_lock functions depending on what tracer is currently
selected. I think that wouldn't hardly impact
the performances....

Re: bug: ftrace & lockdep badness

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> On Wed, 5 Nov 2008, Ingo Molnar wrote:
> 
> > 
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > This is the type of problems we deal with when we have the tracer 
> > > tracing lockdep code at the same time the lockdep code is checking 
> > > the tracer.
> > 
> > ok ... you are right, i guess we need to go back to raw locks after 
> > all?
> 
> I do like the fact that lockdep checks it too. But there's times 
> that we can not do that.
> 
> Perhaps we can do something in between.
> 
> Make a rb_spin_lock macro inside ring_buffer.c that can be either a 
> spin_lock or a raw_spin_lock.  There are some tracers that must have 
> this as a raw (function trace, irqsoff and preemptoff), but the rest 
> should be fine. We can make it where the rb_spin_lock is a raw lock 
> when any of those three tracers are configured, and make it into a 
> normal lock when they are not.
> 
> This way we can still test the integrity of the ring_buffer for 
> other tracers. We just need to be careful when we are using function 
> tracing or irqs/preempt off tracing. But we need to be careful with 
> those anyway.

i'd rather we not complicate this anymore and just go for raw locks 
unconditionally - or no raw locks unconditionally.

	Ingo

Re: bug: ftrace & lockdep badness

[Steven Rostedt]

On Wed, 5 Nov 2008, Ingo Molnar wrote:
> > > 
> > > > This is the type of problems we deal with when we have the tracer 
> > > > tracing lockdep code at the same time the lockdep code is checking 
> > > > the tracer.
> > > 
> > > ok ... you are right, i guess we need to go back to raw locks after 
> > > all?
> > 
> > I do like the fact that lockdep checks it too. But there's times 
> > that we can not do that.
> > 
> > Perhaps we can do something in between.
> > 
> > Make a rb_spin_lock macro inside ring_buffer.c that can be either a 
> > spin_lock or a raw_spin_lock.  There are some tracers that must have 
> > this as a raw (function trace, irqsoff and preemptoff), but the rest 
> > should be fine. We can make it where the rb_spin_lock is a raw lock 
> > when any of those three tracers are configured, and make it into a 
> > normal lock when they are not.
> > 
> > This way we can still test the integrity of the ring_buffer for 
> > other tracers. We just need to be careful when we are using function 
> > tracing or irqs/preempt off tracing. But we need to be careful with 
> > those anyway.
> 
> i'd rather we not complicate this anymore and just go for raw locks 
> unconditionally - or no raw locks unconditionally.

OK, agree. We can have a debug patch that converts it back to normal 
spinlocks that we can apply when we want to test it. But for release, we 
just keep the raw_spin_locks.

-- Steve