Re: Testing tracer wakeup_rt: .. no entries found ..FAILED!

[Fengguang Wu <fengguang.wu@intel.com>]

On Tue, Jul 31, 2012 at 07:51:39PM -0400, Steven Rostedt wrote:
> On Wed, 2012-08-01 at 07:43 +0800, Fengguang Wu wrote:
> > On Tue, Jul 31, 2012 at 09:13:39AM -0400, Steven Rostedt wrote:
> > > On Tue, 2012-07-31 at 15:50 +0300, Avi Kivity wrote:
> > > > On 07/31/2012 03:43 PM, Steven Rostedt wrote:
> > > 
> > > > That would be better.  A hypervisor might be real-time capable (with
> > > > some effort kvm can do this), so we don't want to turn off real time
> > > > features just based on that.
> > > 
> > > It would only turn off if you enable selftests and the timing falied. If
> > > the kvm had real time features, this most likely would fail anyway. But
> > > that said, here's a patch that should solve this:
> > 
> > No luck.. it still fails:
> 
> I bet you it didn't ;-)
> 
> > 
> > [    2.360068] Testing tracer irqsoff: [    2.854529] 
> > [    2.854828] ===============================
> > [    2.855560] [ INFO: suspicious RCU usage. ]
> > [    2.856266] 3.5.0-00024-g01ff5db-dirty #3 Not tainted
> > [    2.857182] -------------------------------
> > [    2.857933] /c/wfg/linux/include/linux/rcupdate.h:730 rcu_read_lock() used illegally while idle!
> > [    2.859450] 
> > [    2.859450] other info that might help us debug this:
> > [    2.859450] 
> > [    2.860874] 
> > [    2.860874] RCU used illegally from idle CPU!
> > [    2.860874] rcu_scheduler_active = 1, debug_locks = 0
> > [    2.862754] RCU used illegally from extended quiescent state!
> > [    2.863741] 2 locks held by swapper/0/0:
> > 
> > [    2.864377]  #0: [    2.864423]  (max_trace_lock){......}, at: [<814f6bfe>] check_critical_timing+0xd7/0x286
> > [    2.864423]  #1:  (rcu_read_lock){.+.+..}, at: [<8116f930>] __update_max_tr+0x0/0x430
> > 
> > [    2.864423] stack backtrace:
> > [    2.864423] Pid: 0, comm: swapper/0 Not tainted 3.5.0-00024-g01ff5db-dirty #3
> > [    2.864423] Call Trace:
> > [    2.864423]  [<81103a06>] lockdep_rcu_suspicious+0x1c6/0x210
> > [    2.864423]  [<8116fc9a>] __update_max_tr+0x36a/0x430
> > [    2.864423]  [<8116f930>] ? tracing_record_cmdline+0x200/0x200
> > [    2.864423]  [<8117186e>] update_max_tr_single+0x14e/0x2c0
> > [    2.864423]  [<81170baa>] ? __trace_stack+0x2a/0x40
> > [    2.864423]  [<814f6d22>] check_critical_timing+0x1fb/0x286
> > [    2.864423]  [<81013313>] ? default_idle+0x593/0xc30
> > [    2.864423]  [<81013313>] ? default_idle+0x593/0xc30
> > [    2.864423]  [<8110a0e7>] ? trace_hardirqs_on+0x27/0x40
> > [    2.864423]  [<8117ea5e>] time_hardirqs_on+0x1de/0x220
> > [    2.864423]  [<81013313>] ? default_idle+0x593/0xc30
> > [    2.864423]  [<81109d6d>] trace_hardirqs_on_caller+0x2d/0x380
> > [    2.864423]  [<8110a0e7>] trace_hardirqs_on+0x27/0x40
> > [    2.864423]  [<81013313>] default_idle+0x593/0xc30
> > [    2.864423]  [<8101692d>] cpu_idle+0x2dd/0x390
> > [    2.864423]  [<814eb841>] rest_init+0x2f5/0x314
> > [    2.864423]  [<814eb54c>] ? __read_lock_failed+0x14/0x14
> > [    2.864423]  [<817a43b4>] start_kernel+0x866/0x87a
> 
> What was the next lines? I bet you it was "PASSED". Which means it did
> not fail. This is the second bug you found that has to do with RCU being
> called in 'idle'. The one that Paul posted a patch for.

Yeah, PASSED!

[    2.898070]  [<8117ea5e>] time_hardirqs_on+0x1de/0x220
[    2.898070]  [<81013313>] ? default_idle+0x593/0xc30
[    2.898070]  [<81109d6d>] trace_hardirqs_on_caller+0x2d/0x380
[    2.898070]  [<8110a0e7>] trace_hardirqs_on+0x27/0x40
[    2.898070]  [<81013313>] default_idle+0x593/0xc30
[    2.898070]  [<8101692d>] cpu_idle+0x2dd/0x390
[    2.898070]  [<817fbe97>] start_secondary+0x44b/0x460
[    3.150115] PASSED
[    3.390079] Testing tracer function_graph: PASSED

I'll test Paul's patch on top of yours right away.

Thanks,
Fengguang