From: Steven Rostedt <rostedt@goodmis.org>
To: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Fengguang Wu <fengguang.wu@intel.com>,
Thomas Gleixner <tglx@linutronix.de>,
john stultz <johnstul@us.ibm.com>, Ingo Molnar <mingo@elte.hu>,
LKML <linux-kernel@vger.kernel.org>
Subject: Re: lockdep WARNING for run_timer_softirq()
Date: Wed, 05 Sep 2012 10:20:36 -0400 [thread overview]
Message-ID: <1346854836.27919.51.camel@gandalf.local.home> (raw)
In-Reply-To: <1346845644.2461.27.camel@laptop>
On Wed, 2012-09-05 at 13:47 +0200, Peter Zijlstra wrote:
> On Fri, 2012-08-31 at 00:21 -0700, Fengguang Wu wrote:
> > [ 3.267585] Testing tracer function: [ 4.282931] tsc: Refined TSC clocksource calibration: 2833.332 MHz
> > PASSED
> > [ 13.392541] Testing tracer irqsoff: PASSED
> > [ 13.428537] Testing tracer branch: [ 20.093074] ------------[ cut here ]------------
Woo hoo! tracer branch! This is a fun tracer, as it is even more
intrusive than function tracing :-)
> > [ 20.093861] WARNING: at /c/kernel-tests/src/stable/kernel/lockdep.c:3493 check_flags+0x166/0x386()
> > [ 20.093861] Pid: 0, comm: swapper/0 Not tainted 3.6.0-rc1-00102-ga184d4e #7
> > [ 20.093861] Call Trace:
> >
> > [ 20.093861] [<41064af3>] warn_slowpath_common+0x8e/0xcd
> > [ 20.093861] [<410f1372>] ? check_flags+0x166/0x386
> > [ 20.093861] [<41064c6b>] warn_slowpath_null+0x30/0x45
> > [ 20.093861] [<410f1372>] check_flags+0x166/0x386
> > [ 20.093861] [<410f7cc5>] lock_acquire+0x5b/0x24a
> > [ 20.093861] [<4107f7d8>] run_timer_softirq+0x2a6/0x77d
> > [ 20.093861] [<4107f72f>] ? run_timer_softirq+0x1fd/0x77d
> > [ 20.093861] [<4107f449>] ? spin_unlock_irqrestore+0x26/0x26
> > [ 20.093861] [<41075293>] __do_softirq+0x234/0x5d6
> > [ 20.093861] [<4107505f>] ? local_bh_enable_ip+0x2b/0x2b
> > [ 20.093861] <IRQ> [<41075adf>] ? irq_exit+0x9d/0x14b
> > [ 20.093861] [<4103b1b7>] ? smp_apic_timer_interrupt+0xe1/0xfd
> > [ 20.093861] [<41a75bc7>] ? apic_timer_interrupt+0x2f/0x34
> > [ 20.093861] [<41151975>] ? ftrace_likely_update+0x3bb/0x446
> > [ 20.093861] [<41102e17>] ? arch_local_irq_enable+0x6b/0x80
> > [ 20.093861] [<41a74287>] ? _raw_spin_unlock_irq+0x80/0xc5
> > [ 20.093861] [<410babf0>] ? finish_task_switch+0x109/0x1df
> > [ 20.093861] [<410bab8a>] ? finish_task_switch+0xa3/0x1df
> > [ 20.093861] [<41a7222b>] ? __schedule+0xb89/0xd51
> > [ 20.093861] [<4112efbe>] ? rcu_idle_exit+0x1d0/0x26c
> > [ 20.093861] [<4112efd3>] ? rcu_idle_exit+0x1e5/0x26c
> > [ 20.093861] [<41a7252f>] ? schedule+0x13c/0x14c
> > [ 20.093861] [<41014615>] ? cpu_idle+0x1d5/0x1fd
> > [ 20.093861] [<41a01c3d>] ? rest_init+0x319/0x32c
> > [ 20.093861] [<4216637a>] ? start_kernel+0x84c/0x85f
> > [ 20.093861] [<42165322>] ? i386_start_kernel+0xf8/0x10b
> > [ 20.093861] ---[ end trace 39036f94f86e3090 ]---
> > [ 20.093861] possible reason: unannotated irqs-on.
> > [ 20.093861] irq event stamp: 36791
> > [ 20.093861] hardirqs last enabled at (36790): [<41a74274>] _raw_spin_unlock_irq+0x6d/0xc5
> > [ 20.093861] hardirqs last disabled at (36791): [<41151700>] ftrace_likely_update+0x146/0x446
> > [ 20.093861] softirqs last enabled at (34274): [<41074fe8>] _local_bh_enable+0x20/0x30
> > [ 20.093861] softirqs last disabled at (34275): [<41007553>] call_on_stack+0x20/0x34
>
> I suspect its because of a 'fun' combination of paravirt and
> trace_branch, although I can't seem to make it stick.. the trace
> includes the best of both worlds although its rather uncertain of
> itself :/
>
> _raw_spin_unlock_irq()
> __raw_spin_unlock_irq()
> spin_release() <-- tell lockdep you release the lock
> do_raw_spin_unlock() <-- actually release the lock
> local_irq_enable()
> trace_hardirqs_on() <-- tell lockdep IRQs are on
> raw_local_irq_enable()
> arch_local_irq_enable()
> PVOP_VCALLEE0(pv_irq_ops.irq_enable);
> *magic*
> ftrace_likely_update()
> local_irq_save() <-- as per the hardirq last disable
>
> * note that hardirq last enable doesn't appear to be the _restore() ?! *
>
> <IRQ> <-- which would be impossible give the above state ?
> __irqexit
> __do_softirq()
> run_timer_softirq()
> lock_acquire() <-- assuming its spin_lock_irq(&base->lock) in __run_timers
>
> *confused*
>
> Anybody got clue?
Well, the branch tracer was active. That means all 'if()'s were being
traced. It comes down to how you define 'if' ;-)
-- Steve
next prev parent reply other threads:[~2012-09-05 14:20 UTC|newest]
Thread overview: 8+ messages / expand[flat|nested] mbox.gz Atom feed top
2012-08-31 7:21 lockdep WARNING for run_timer_softirq() Fengguang Wu
2012-08-31 7:32 ` Fengguang Wu
2012-09-05 11:47 ` Peter Zijlstra
2012-09-05 14:20 ` Steven Rostedt [this message]
2012-09-05 17:09 ` Peter Zijlstra
2012-09-05 17:14 ` Steven Rostedt
2012-09-05 17:19 ` Peter Zijlstra
2012-09-05 19:23 ` Steven Rostedt
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=1346854836.27919.51.camel@gandalf.local.home \
--to=rostedt@goodmis.org \
--cc=a.p.zijlstra@chello.nl \
--cc=fengguang.wu@intel.com \
--cc=johnstul@us.ibm.com \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@elte.hu \
--cc=tglx@linutronix.de \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).