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

2012-08-07 Thread Fengguang Wu
On Tue, Aug 07, 2012 at 09:29:33AM -0400, Steven Rostedt wrote:
> On Wed, 2012-08-01 at 07:57 +0800, Fengguang Wu wrote:
> > > 
> > > 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!
> 
> I have this patch queued for 3.7. Can I add your 'Tested-by' for it.

Yes, please. Thanks!

Thanks,
Fengguang

> > [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
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2012-08-07 Thread Steven Rostedt
On Wed, 2012-08-01 at 07:57 +0800, Fengguang Wu wrote:
> > 
> > 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!

I have this patch queued for 3.7. Can I add your 'Tested-by' for it.

Thanks,

-- Steve

> 
> [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


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


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

2012-08-07 Thread Steven Rostedt
On Wed, 2012-08-01 at 07:57 +0800, Fengguang Wu wrote:
  
  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!

I have this patch queued for 3.7. Can I add your 'Tested-by' for it.

Thanks,

-- Steve

 
 [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


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


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

2012-08-07 Thread Fengguang Wu
On Tue, Aug 07, 2012 at 09:29:33AM -0400, Steven Rostedt wrote:
 On Wed, 2012-08-01 at 07:57 +0800, Fengguang Wu wrote:
   
   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!
 
 I have this patch queued for 3.7. Can I add your 'Tested-by' for it.

Yes, please. Thanks!

Thanks,
Fengguang

  [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
 
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2012-07-31 Thread Paul E. McKenney
On Tue, Jul 31, 2012 at 08:09:38PM -0400, Steven Rostedt wrote:
> On Tue, 2012-07-31 at 16:57 -0700, Paul E. McKenney wrote:
> 
> > > 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.
> > 
> > Though it needs another patch to actually use it in the right place...
> 
> Right. Something like this:

Looks good to me!

Thanx, Paul

> -- Steve
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 5638104..d915638 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -631,7 +631,12 @@ __update_max_tr(struct trace_array *tr, struct 
> task_struct *tsk, int cpu)
> 
>   memcpy(max_data->comm, tsk->comm, TASK_COMM_LEN);
>   max_data->pid = tsk->pid;
> - max_data->uid = task_uid(tsk);
> + /*
> +  * task_uid() calls rcu_read_lock, but this can be called
> +  * outside of RCU state monitoring (irq going back to idle).
> +  */ 
> + RCU_NONIDLE(max_data->uid = task_uid(tsk));
> +
>   max_data->nice = tsk->static_prio - 20 - MAX_RT_PRIO;
>   max_data->policy = tsk->policy;
>   max_data->rt_priority = tsk->rt_priority;
> 
> 

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


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

2012-07-31 Thread Steven Rostedt
On Tue, 2012-07-31 at 16:57 -0700, Paul E. McKenney wrote:

> > 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.
> 
> Though it needs another patch to actually use it in the right place...

Right. Something like this:

-- Steve

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 5638104..d915638 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -631,7 +631,12 @@ __update_max_tr(struct trace_array *tr, struct task_struct 
*tsk, int cpu)
 
memcpy(max_data->comm, tsk->comm, TASK_COMM_LEN);
max_data->pid = tsk->pid;
-   max_data->uid = task_uid(tsk);
+   /*
+* task_uid() calls rcu_read_lock, but this can be called
+* outside of RCU state monitoring (irq going back to idle).
+*/ 
+   RCU_NONIDLE(max_data->uid = task_uid(tsk));
+
max_data->nice = tsk->static_prio - 20 - MAX_RT_PRIO;
max_data->policy = tsk->policy;
max_data->rt_priority = tsk->rt_priority;


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


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

2012-07-31 Thread Fengguang Wu
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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2012-07-31 Thread Paul E. McKenney
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.

Though it needs another patch to actually use it in the right place...

Thanx, Paul

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


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

2012-07-31 Thread Steven Rostedt
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.

-- Steve


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


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

2012-07-31 Thread Fengguang Wu
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:

[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

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


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

2012-07-31 Thread Steven Rostedt
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:

-- Steve


diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c
index 1003a4d..2c00a69 100644
--- a/kernel/trace/trace_selftest.c
+++ b/kernel/trace/trace_selftest.c
@@ -1041,6 +1041,8 @@ static int trace_wakeup_test_thread(void *data)
set_current_state(TASK_INTERRUPTIBLE);
schedule();
 
+   complete(x);
+
/* we are awake, now wait to disappear */
while (!kthread_should_stop()) {
/*
@@ -1084,24 +1086,21 @@ trace_selftest_startup_wakeup(struct tracer *trace, 
struct trace_array *tr)
/* reset the max latency */
tracing_max_latency = 0;
 
-   /* sleep to let the RT thread sleep too */
-   msleep(100);
+   while (p->on_rq) {
+   /*
+* Sleep to make sure the RT thread is asleep too.
+* On virtual machines we can't rely on timings,
+* but we want to make sure this test still works.
+*/
+   msleep(100);
+   }
 
-   /*
-* Yes this is slightly racy. It is possible that for some
-* strange reason that the RT thread we created, did not
-* call schedule for 100ms after doing the completion,
-* and we do a wakeup on a task that already is awake.
-* But that is extremely unlikely, and the worst thing that
-* happens in such a case, is that we disable tracing.
-* Honestly, if this race does happen something is horrible
-* wrong with the system.
-*/
+   init_completion();
 
wake_up_process(p);
 
-   /* give a little time to let the thread wake up */
-   msleep(100);
+   /* Wait for the task to wake up */
+   wait_for_completion();
 
/* stop the tracing. */
tracing_stop();



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


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

2012-07-31 Thread Avi Kivity
On 07/31/2012 03:43 PM, Steven Rostedt wrote:
> On Tue, 2012-07-31 at 15:37 +0300, Avi Kivity wrote:
>> On 07/31/2012 03:17 PM, Fengguang Wu wrote:
>> > 
>> > It's good to quickly get to the root cause :) Can we possibly detect
>> > whether we are in a virtual machine and hence skip this particular
>> > test case?
>> 
>> cpu_has(_cpu, X86_FEATURE_HYPERVISOR)
>> 
> 
> Yeah, but then it is still broken on non-x86 code (the test lives in
> core kernel).
> 
> As it is just testing the events for wakeup, I could probably just add a
> completion and force the other thread to just wait for it. I'll write up
> a patch. But it wont make it in till 3.7.

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.


-- 
error compiling committee.c: too many arguments to function


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


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

2012-07-31 Thread Steven Rostedt
On Tue, 2012-07-31 at 15:37 +0300, Avi Kivity wrote:
> On 07/31/2012 03:17 PM, Fengguang Wu wrote:
> > 
> > It's good to quickly get to the root cause :) Can we possibly detect
> > whether we are in a virtual machine and hence skip this particular
> > test case?
> 
> cpu_has(_cpu, X86_FEATURE_HYPERVISOR)
> 

Yeah, but then it is still broken on non-x86 code (the test lives in
core kernel).

As it is just testing the events for wakeup, I could probably just add a
completion and force the other thread to just wait for it. I'll write up
a patch. But it wont make it in till 3.7.

-- Steve


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


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

2012-07-31 Thread Avi Kivity
On 07/31/2012 03:17 PM, Fengguang Wu wrote:
> 
> It's good to quickly get to the root cause :) Can we possibly detect
> whether we are in a virtual machine and hence skip this particular
> test case?

cpu_has(_cpu, X86_FEATURE_HYPERVISOR)

-- 
error compiling committee.c: too many arguments to function


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


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

2012-07-31 Thread Fengguang Wu
[CC kvm developers]

On Mon, Jul 30, 2012 at 11:45:05AM -0400, Steven Rostedt wrote:
> On Tue, 2012-07-24 at 17:07 +0800, Fengguang Wu wrote:
> > On Tue, Jul 24, 2012 at 05:03:30PM +0800, Fengguang Wu wrote:
> 
> > And this warning shows up in one of the dozens of boots, for the same
> > kconfig.
> > 
> > [2.320434] Testing tracer wakeup: PASSED
> > [2.840288] Testing tracer wakeup_rt: .. no entries found ..FAILED!
> > [3.280861] [ cut here ]
> > [3.281967] WARNING: at 
> > /c/kernel-tests/src/linux/kernel/trace/trace.c:834 
> > register_tracer+0x1b0/0x270()
> > [3.284162] Hardware name: Bochs
> > [3.284933] Modules linked in:
> > [3.285695] Pid: 1, comm: swapper/0 Not tainted 3.5.0+ #1371
> > [3.287032] Call Trace:
> > [3.287626]  [<41035c32>] warn_slowpath_common+0x72/0xa0
> > [3.288938]  [<410e7dd0>] ? register_tracer+0x1b0/0x270
> > [3.290280]  [<410e7dd0>] ? register_tracer+0x1b0/0x270
> > [3.291516]  [<41035c82>] warn_slowpath_null+0x22/0x30
> > [3.292723]  [<410e7dd0>] register_tracer+0x1b0/0x270
> > [3.293921]  [<41434c7a>] ? init_irqsoff_tracer+0x11/0x11
> > [3.295269]  [<41434c95>] init_wakeup_tracer+0x1b/0x1d
> > [3.296464]  [<41001112>] do_one_initcall+0x112/0x160
> > [3.297639]  [<4141fadd>] kernel_init+0xf7/0x18e
> > [3.298724]  [<4141f455>] ? do_early_param+0x7a/0x7a
> > [3.299879]  [<4141f9e6>] ? start_kernel+0x375/0x375
> > [3.301093]  [<412b15c2>] kernel_thread_helper+0x6/0x10
> > [3.302352] ---[ end trace 57f7151f6a5def05 ]---
> > 
> 
> The comment above this test shows:
> 
>* Yes this is slightly racy. It is possible that for some
>* strange reason that the RT thread we created, did not
>* call schedule for 100ms after doing the completion,
>* and we do a wakeup on a task that already is awake.
>* But that is extremely unlikely, and the worst thing that
>* happens in such a case, is that we disable tracing.
>* Honestly, if this race does happen something is horrible
>* wrong with the system.
> 
> I guess the question now is, why didn't the RT test wake up?
> 
> Oh wait! You did this on a virt machine. This test isn't designed for
> virt machines because the thread could have woken on another vcpu, but
> due to scheduling of the host system, it didn't get to run for 100ms,
> thus the test will fail because it never recorded the wakeup of the RT
> task.
> 
> In other-words, the test is bogus on virt boxes :-/

It's good to quickly get to the root cause :) Can we possibly detect
whether we are in a virtual machine and hence skip this particular
test case?

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


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

2012-07-31 Thread Fengguang Wu
[CC kvm developers]

On Mon, Jul 30, 2012 at 11:45:05AM -0400, Steven Rostedt wrote:
 On Tue, 2012-07-24 at 17:07 +0800, Fengguang Wu wrote:
  On Tue, Jul 24, 2012 at 05:03:30PM +0800, Fengguang Wu wrote:
 
  And this warning shows up in one of the dozens of boots, for the same
  kconfig.
  
  [2.320434] Testing tracer wakeup: PASSED
  [2.840288] Testing tracer wakeup_rt: .. no entries found ..FAILED!
  [3.280861] [ cut here ]
  [3.281967] WARNING: at 
  /c/kernel-tests/src/linux/kernel/trace/trace.c:834 
  register_tracer+0x1b0/0x270()
  [3.284162] Hardware name: Bochs
  [3.284933] Modules linked in:
  [3.285695] Pid: 1, comm: swapper/0 Not tainted 3.5.0+ #1371
  [3.287032] Call Trace:
  [3.287626]  [41035c32] warn_slowpath_common+0x72/0xa0
  [3.288938]  [410e7dd0] ? register_tracer+0x1b0/0x270
  [3.290280]  [410e7dd0] ? register_tracer+0x1b0/0x270
  [3.291516]  [41035c82] warn_slowpath_null+0x22/0x30
  [3.292723]  [410e7dd0] register_tracer+0x1b0/0x270
  [3.293921]  [41434c7a] ? init_irqsoff_tracer+0x11/0x11
  [3.295269]  [41434c95] init_wakeup_tracer+0x1b/0x1d
  [3.296464]  [41001112] do_one_initcall+0x112/0x160
  [3.297639]  [4141fadd] kernel_init+0xf7/0x18e
  [3.298724]  [4141f455] ? do_early_param+0x7a/0x7a
  [3.299879]  [4141f9e6] ? start_kernel+0x375/0x375
  [3.301093]  [412b15c2] kernel_thread_helper+0x6/0x10
  [3.302352] ---[ end trace 57f7151f6a5def05 ]---
  
 
 The comment above this test shows:
 
* Yes this is slightly racy. It is possible that for some
* strange reason that the RT thread we created, did not
* call schedule for 100ms after doing the completion,
* and we do a wakeup on a task that already is awake.
* But that is extremely unlikely, and the worst thing that
* happens in such a case, is that we disable tracing.
* Honestly, if this race does happen something is horrible
* wrong with the system.
 
 I guess the question now is, why didn't the RT test wake up?
 
 Oh wait! You did this on a virt machine. This test isn't designed for
 virt machines because the thread could have woken on another vcpu, but
 due to scheduling of the host system, it didn't get to run for 100ms,
 thus the test will fail because it never recorded the wakeup of the RT
 task.
 
 In other-words, the test is bogus on virt boxes :-/

It's good to quickly get to the root cause :) Can we possibly detect
whether we are in a virtual machine and hence skip this particular
test case?

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


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

2012-07-31 Thread Avi Kivity
On 07/31/2012 03:17 PM, Fengguang Wu wrote:
 
 It's good to quickly get to the root cause :) Can we possibly detect
 whether we are in a virtual machine and hence skip this particular
 test case?

cpu_has(boot_cpu, X86_FEATURE_HYPERVISOR)

-- 
error compiling committee.c: too many arguments to function


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


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

2012-07-31 Thread Steven Rostedt
On Tue, 2012-07-31 at 15:37 +0300, Avi Kivity wrote:
 On 07/31/2012 03:17 PM, Fengguang Wu wrote:
  
  It's good to quickly get to the root cause :) Can we possibly detect
  whether we are in a virtual machine and hence skip this particular
  test case?
 
 cpu_has(boot_cpu, X86_FEATURE_HYPERVISOR)
 

Yeah, but then it is still broken on non-x86 code (the test lives in
core kernel).

As it is just testing the events for wakeup, I could probably just add a
completion and force the other thread to just wait for it. I'll write up
a patch. But it wont make it in till 3.7.

-- Steve


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


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

2012-07-31 Thread Avi Kivity
On 07/31/2012 03:43 PM, Steven Rostedt wrote:
 On Tue, 2012-07-31 at 15:37 +0300, Avi Kivity wrote:
 On 07/31/2012 03:17 PM, Fengguang Wu wrote:
  
  It's good to quickly get to the root cause :) Can we possibly detect
  whether we are in a virtual machine and hence skip this particular
  test case?
 
 cpu_has(boot_cpu, X86_FEATURE_HYPERVISOR)
 
 
 Yeah, but then it is still broken on non-x86 code (the test lives in
 core kernel).
 
 As it is just testing the events for wakeup, I could probably just add a
 completion and force the other thread to just wait for it. I'll write up
 a patch. But it wont make it in till 3.7.

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.


-- 
error compiling committee.c: too many arguments to function


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


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

2012-07-31 Thread Steven Rostedt
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:

-- Steve


diff --git a/kernel/trace/trace_selftest.c b/kernel/trace/trace_selftest.c
index 1003a4d..2c00a69 100644
--- a/kernel/trace/trace_selftest.c
+++ b/kernel/trace/trace_selftest.c
@@ -1041,6 +1041,8 @@ static int trace_wakeup_test_thread(void *data)
set_current_state(TASK_INTERRUPTIBLE);
schedule();
 
+   complete(x);
+
/* we are awake, now wait to disappear */
while (!kthread_should_stop()) {
/*
@@ -1084,24 +1086,21 @@ trace_selftest_startup_wakeup(struct tracer *trace, 
struct trace_array *tr)
/* reset the max latency */
tracing_max_latency = 0;
 
-   /* sleep to let the RT thread sleep too */
-   msleep(100);
+   while (p-on_rq) {
+   /*
+* Sleep to make sure the RT thread is asleep too.
+* On virtual machines we can't rely on timings,
+* but we want to make sure this test still works.
+*/
+   msleep(100);
+   }
 
-   /*
-* Yes this is slightly racy. It is possible that for some
-* strange reason that the RT thread we created, did not
-* call schedule for 100ms after doing the completion,
-* and we do a wakeup on a task that already is awake.
-* But that is extremely unlikely, and the worst thing that
-* happens in such a case, is that we disable tracing.
-* Honestly, if this race does happen something is horrible
-* wrong with the system.
-*/
+   init_completion(isrt);
 
wake_up_process(p);
 
-   /* give a little time to let the thread wake up */
-   msleep(100);
+   /* Wait for the task to wake up */
+   wait_for_completion(isrt);
 
/* stop the tracing. */
tracing_stop();



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


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

2012-07-31 Thread Fengguang Wu
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:

[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

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


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

2012-07-31 Thread Steven Rostedt
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.

-- Steve


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


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

2012-07-31 Thread Paul E. McKenney
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.

Though it needs another patch to actually use it in the right place...

Thanx, Paul

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


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

2012-07-31 Thread Fengguang Wu
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
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2012-07-31 Thread Steven Rostedt
On Tue, 2012-07-31 at 16:57 -0700, Paul E. McKenney wrote:

  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.
 
 Though it needs another patch to actually use it in the right place...

Right. Something like this:

-- Steve

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 5638104..d915638 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -631,7 +631,12 @@ __update_max_tr(struct trace_array *tr, struct task_struct 
*tsk, int cpu)
 
memcpy(max_data-comm, tsk-comm, TASK_COMM_LEN);
max_data-pid = tsk-pid;
-   max_data-uid = task_uid(tsk);
+   /*
+* task_uid() calls rcu_read_lock, but this can be called
+* outside of RCU state monitoring (irq going back to idle).
+*/ 
+   RCU_NONIDLE(max_data-uid = task_uid(tsk));
+
max_data-nice = tsk-static_prio - 20 - MAX_RT_PRIO;
max_data-policy = tsk-policy;
max_data-rt_priority = tsk-rt_priority;


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


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

2012-07-31 Thread Paul E. McKenney
On Tue, Jul 31, 2012 at 08:09:38PM -0400, Steven Rostedt wrote:
 On Tue, 2012-07-31 at 16:57 -0700, Paul E. McKenney wrote:
 
   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.
  
  Though it needs another patch to actually use it in the right place...
 
 Right. Something like this:

Looks good to me!

Thanx, Paul

 -- Steve
 
 diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
 index 5638104..d915638 100644
 --- a/kernel/trace/trace.c
 +++ b/kernel/trace/trace.c
 @@ -631,7 +631,12 @@ __update_max_tr(struct trace_array *tr, struct 
 task_struct *tsk, int cpu)
 
   memcpy(max_data-comm, tsk-comm, TASK_COMM_LEN);
   max_data-pid = tsk-pid;
 - max_data-uid = task_uid(tsk);
 + /*
 +  * task_uid() calls rcu_read_lock, but this can be called
 +  * outside of RCU state monitoring (irq going back to idle).
 +  */ 
 + RCU_NONIDLE(max_data-uid = task_uid(tsk));
 +
   max_data-nice = tsk-static_prio - 20 - MAX_RT_PRIO;
   max_data-policy = tsk-policy;
   max_data-rt_priority = tsk-rt_priority;
 
 

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


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

2012-07-30 Thread Steven Rostedt
On Tue, 2012-07-24 at 17:07 +0800, Fengguang Wu wrote:
> On Tue, Jul 24, 2012 at 05:03:30PM +0800, Fengguang Wu wrote:

> And this warning shows up in one of the dozens of boots, for the same
> kconfig.
> 
> [2.320434] Testing tracer wakeup: PASSED
> [    2.840288] Testing tracer wakeup_rt: .. no entries found ..FAILED!
> [3.280861] [ cut here ]
> [3.281967] WARNING: at /c/kernel-tests/src/linux/kernel/trace/trace.c:834 
> register_tracer+0x1b0/0x270()
> [3.284162] Hardware name: Bochs
> [3.284933] Modules linked in:
> [3.285695] Pid: 1, comm: swapper/0 Not tainted 3.5.0+ #1371
> [3.287032] Call Trace:
> [3.287626]  [<41035c32>] warn_slowpath_common+0x72/0xa0
> [3.288938]  [<410e7dd0>] ? register_tracer+0x1b0/0x270
> [3.290280]  [<410e7dd0>] ? register_tracer+0x1b0/0x270
> [3.291516]  [<41035c82>] warn_slowpath_null+0x22/0x30
> [3.292723]  [<410e7dd0>] register_tracer+0x1b0/0x270
> [3.293921]  [<41434c7a>] ? init_irqsoff_tracer+0x11/0x11
> [3.295269]  [<41434c95>] init_wakeup_tracer+0x1b/0x1d
> [3.296464]  [<41001112>] do_one_initcall+0x112/0x160
> [3.297639]  [<4141fadd>] kernel_init+0xf7/0x18e
> [3.298724]  [<4141f455>] ? do_early_param+0x7a/0x7a
> [3.299879]  [<4141f9e6>] ? start_kernel+0x375/0x375
> [3.301093]  [<412b15c2>] kernel_thread_helper+0x6/0x10
> [3.302352] ---[ end trace 57f7151f6a5def05 ]---
> 

The comment above this test shows:

 * Yes this is slightly racy. It is possible that for some
 * strange reason that the RT thread we created, did not
 * call schedule for 100ms after doing the completion,
 * and we do a wakeup on a task that already is awake.
 * But that is extremely unlikely, and the worst thing that
 * happens in such a case, is that we disable tracing.
 * Honestly, if this race does happen something is horrible
 * wrong with the system.

I guess the question now is, why didn't the RT test wake up?

Oh wait! You did this on a virt machine. This test isn't designed for
virt machines because the thread could have woken on another vcpu, but
due to scheduling of the host system, it didn't get to run for 100ms,
thus the test will fail because it never recorded the wakeup of the RT
task.

In other-words, the test is bogus on virt boxes :-/

-- Steve


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


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

2012-07-30 Thread Steven Rostedt
On Tue, 2012-07-24 at 17:07 +0800, Fengguang Wu wrote:
 On Tue, Jul 24, 2012 at 05:03:30PM +0800, Fengguang Wu wrote:

 And this warning shows up in one of the dozens of boots, for the same
 kconfig.
 
 [2.320434] Testing tracer wakeup: PASSED
 [2.840288] Testing tracer wakeup_rt: .. no entries found ..FAILED!
 [3.280861] [ cut here ]
 [3.281967] WARNING: at /c/kernel-tests/src/linux/kernel/trace/trace.c:834 
 register_tracer+0x1b0/0x270()
 [3.284162] Hardware name: Bochs
 [3.284933] Modules linked in:
 [3.285695] Pid: 1, comm: swapper/0 Not tainted 3.5.0+ #1371
 [3.287032] Call Trace:
 [3.287626]  [41035c32] warn_slowpath_common+0x72/0xa0
 [3.288938]  [410e7dd0] ? register_tracer+0x1b0/0x270
 [3.290280]  [410e7dd0] ? register_tracer+0x1b0/0x270
 [3.291516]  [41035c82] warn_slowpath_null+0x22/0x30
 [3.292723]  [410e7dd0] register_tracer+0x1b0/0x270
 [3.293921]  [41434c7a] ? init_irqsoff_tracer+0x11/0x11
 [3.295269]  [41434c95] init_wakeup_tracer+0x1b/0x1d
 [3.296464]  [41001112] do_one_initcall+0x112/0x160
 [3.297639]  [4141fadd] kernel_init+0xf7/0x18e
 [3.298724]  [4141f455] ? do_early_param+0x7a/0x7a
 [3.299879]  [4141f9e6] ? start_kernel+0x375/0x375
 [3.301093]  [412b15c2] kernel_thread_helper+0x6/0x10
 [3.302352] ---[ end trace 57f7151f6a5def05 ]---
 

The comment above this test shows:

 * Yes this is slightly racy. It is possible that for some
 * strange reason that the RT thread we created, did not
 * call schedule for 100ms after doing the completion,
 * and we do a wakeup on a task that already is awake.
 * But that is extremely unlikely, and the worst thing that
 * happens in such a case, is that we disable tracing.
 * Honestly, if this race does happen something is horrible
 * wrong with the system.

I guess the question now is, why didn't the RT test wake up?

Oh wait! You did this on a virt machine. This test isn't designed for
virt machines because the thread could have woken on another vcpu, but
due to scheduling of the host system, it didn't get to run for 100ms,
thus the test will fail because it never recorded the wakeup of the RT
task.

In other-words, the test is bogus on virt boxes :-/

-- Steve


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


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

2012-07-24 Thread Fengguang Wu
On Tue, Jul 24, 2012 at 05:03:30PM +0800, Fengguang Wu wrote:
> Hi Steven,
> 
> This looks like some old bug, so I directly report to you w/o trying
> to bisect it. It only happens on the attached i386 randconfig and
> happens in about half of the kvm boots.
> 
> [1.380369] Testing tracer irqsoff: [1.524917] 
> [1.525217] ===
> [1.525868] [ INFO: suspicious RCU usage. ]
> [1.526556] 3.5.0+ #1289 Not tainted
> [1.527124] ---
> [1.527799] /c/kernel-tests/src/linux/include/linux/rcupdate.h:730 
> rcu_read_lock() used illegally while idle!
> [1.529375] 
> [1.529375] other info that might help us debug this:
> [1.529375] 
> [1.530667] 
> [1.530667] RCU used illegally from idle CPU!
> [1.530667] rcu_scheduler_active = 1, debug_locks = 1
> [1.532383] RCU used illegally from extended quiescent state!
> [1.533297] 2 locks held by swapper/0/0:
> 
> [1.533924]  #0: [1.534271]  (max_trace_lock){..}, at: 
> [<410e9d67>] check_critical_timing+0x67/0x1b0
> [1.534883]  #1:  (rcu_read_lock){.+.+..}, at: [<410e1ea0>] 
> __update_max_tr+0x0/0x200
> 
> [1.534883] stack backtrace:
> [1.534883] Pid: 0, comm: swapper/0 Not tainted 3.5.0+ #1289
> [1.534883] Call Trace:
> [1.534883]  [<41093a76>] lockdep_rcu_suspicious+0xc6/0x100
> [1.534883]  [<410e2071>] __update_max_tr+0x1d1/0x200
> [1.534883]  [<410e1ea0>] ? tracing_record_cmdline+0x130/0x130
> [1.534883]  [<410e30f5>] update_max_tr_single+0x1f5/0x240
> [1.534883]  [<410e294c>] ? __trace_stack+0x1c/0x30
> [1.534883]  [<410e9e96>] check_critical_timing+0x196/0x1b0
> [1.534883]  [<4100b858>] ? default_idle+0x468/0x4c0
> [1.534883]  [<4100b858>] ? default_idle+0x468/0x4c0
> [1.534883]  [<410ea47f>] time_hardirqs_on+0xff/0x110
> [1.534883]  [<410961eb>] ? trace_hardirqs_on+0xb/0x10
> [1.534883]  [<4100b858>] ? default_idle+0x468/0x4c0
> [1.534883]  [<41096031>] trace_hardirqs_on_caller+0x11/0x1c0
> [1.534883]  [<410961eb>] trace_hardirqs_on+0xb/0x10
> [1.534883]  [<4100b858>] default_idle+0x468/0x4c0
> [1.534883]  [<4100c4e6>] cpu_idle+0x186/0x190
> [1.534883]  [<412953c3>] rest_init+0x127/0x134
> [1.534883]  [<4129529c>] ? __read_lock_failed+0x14/0x14
> [1.534883]  [<4141b9e0>] start_kernel+0x36f/0x375
> [1.534883]  [<4141b4a6>] ? repair_env_string+0x51/0x51
> [    1.534883]  [<4141b2d4>] i386_start_kernel+0x8a/0x8f
> [1.534883] 
> [1.534883] ===

And this warning shows up in one of the dozens of boots, for the same
kconfig.

[2.320434] Testing tracer wakeup: PASSED
[2.840288] Testing tracer wakeup_rt: .. no entries found ..FAILED!
[3.280861] [ cut here ]
[3.281967] WARNING: at /c/kernel-tests/src/linux/kernel/trace/trace.c:834 
register_tracer+0x1b0/0x270()
[3.284162] Hardware name: Bochs
[3.284933] Modules linked in:
[3.285695] Pid: 1, comm: swapper/0 Not tainted 3.5.0+ #1371
[3.287032] Call Trace:
[3.287626]  [<41035c32>] warn_slowpath_common+0x72/0xa0
[3.288938]  [<410e7dd0>] ? register_tracer+0x1b0/0x270
[3.290280]  [<410e7dd0>] ? register_tracer+0x1b0/0x270
[3.291516]  [<41035c82>] warn_slowpath_null+0x22/0x30
[3.292723]  [<410e7dd0>] register_tracer+0x1b0/0x270
[3.293921]  [<41434c7a>] ? init_irqsoff_tracer+0x11/0x11
[3.295269]  [<41434c95>] init_wakeup_tracer+0x1b/0x1d
[3.296464]  [<41001112>] do_one_initcall+0x112/0x160
[3.297639]  [<4141fadd>] kernel_init+0xf7/0x18e
[3.298724]  [<4141f455>] ? do_early_param+0x7a/0x7a
[3.299879]  [<4141f9e6>] ? start_kernel+0x375/0x375
[3.301093]  [<412b15c2>] kernel_thread_helper+0x6/0x10
[3.302352] ---[ end trace 57f7151f6a5def05 ]---

Thanks,
Fengguang

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


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

2012-07-24 Thread Fengguang Wu
On Tue, Jul 24, 2012 at 05:03:30PM +0800, Fengguang Wu wrote:
 Hi Steven,
 
 This looks like some old bug, so I directly report to you w/o trying
 to bisect it. It only happens on the attached i386 randconfig and
 happens in about half of the kvm boots.
 
 [1.380369] Testing tracer irqsoff: [1.524917] 
 [1.525217] ===
 [1.525868] [ INFO: suspicious RCU usage. ]
 [1.526556] 3.5.0+ #1289 Not tainted
 [1.527124] ---
 [1.527799] /c/kernel-tests/src/linux/include/linux/rcupdate.h:730 
 rcu_read_lock() used illegally while idle!
 [1.529375] 
 [1.529375] other info that might help us debug this:
 [1.529375] 
 [1.530667] 
 [1.530667] RCU used illegally from idle CPU!
 [1.530667] rcu_scheduler_active = 1, debug_locks = 1
 [1.532383] RCU used illegally from extended quiescent state!
 [1.533297] 2 locks held by swapper/0/0:
 
 [1.533924]  #0: [1.534271]  (max_trace_lock){..}, at: 
 [410e9d67] check_critical_timing+0x67/0x1b0
 [1.534883]  #1:  (rcu_read_lock){.+.+..}, at: [410e1ea0] 
 __update_max_tr+0x0/0x200
 
 [1.534883] stack backtrace:
 [1.534883] Pid: 0, comm: swapper/0 Not tainted 3.5.0+ #1289
 [1.534883] Call Trace:
 [1.534883]  [41093a76] lockdep_rcu_suspicious+0xc6/0x100
 [1.534883]  [410e2071] __update_max_tr+0x1d1/0x200
 [1.534883]  [410e1ea0] ? tracing_record_cmdline+0x130/0x130
 [1.534883]  [410e30f5] update_max_tr_single+0x1f5/0x240
 [1.534883]  [410e294c] ? __trace_stack+0x1c/0x30
 [1.534883]  [410e9e96] check_critical_timing+0x196/0x1b0
 [1.534883]  [4100b858] ? default_idle+0x468/0x4c0
 [1.534883]  [4100b858] ? default_idle+0x468/0x4c0
 [1.534883]  [410ea47f] time_hardirqs_on+0xff/0x110
 [1.534883]  [410961eb] ? trace_hardirqs_on+0xb/0x10
 [1.534883]  [4100b858] ? default_idle+0x468/0x4c0
 [1.534883]  [41096031] trace_hardirqs_on_caller+0x11/0x1c0
 [1.534883]  [410961eb] trace_hardirqs_on+0xb/0x10
 [1.534883]  [4100b858] default_idle+0x468/0x4c0
 [1.534883]  [4100c4e6] cpu_idle+0x186/0x190
 [1.534883]  [412953c3] rest_init+0x127/0x134
 [1.534883]  [4129529c] ? __read_lock_failed+0x14/0x14
 [1.534883]  [4141b9e0] start_kernel+0x36f/0x375
 [1.534883]  [4141b4a6] ? repair_env_string+0x51/0x51
 [1.534883]  [4141b2d4] i386_start_kernel+0x8a/0x8f
 [1.534883] 
 [1.534883] ===

And this warning shows up in one of the dozens of boots, for the same
kconfig.

[2.320434] Testing tracer wakeup: PASSED
[2.840288] Testing tracer wakeup_rt: .. no entries found ..FAILED!
[3.280861] [ cut here ]
[3.281967] WARNING: at /c/kernel-tests/src/linux/kernel/trace/trace.c:834 
register_tracer+0x1b0/0x270()
[3.284162] Hardware name: Bochs
[3.284933] Modules linked in:
[3.285695] Pid: 1, comm: swapper/0 Not tainted 3.5.0+ #1371
[3.287032] Call Trace:
[3.287626]  [41035c32] warn_slowpath_common+0x72/0xa0
[3.288938]  [410e7dd0] ? register_tracer+0x1b0/0x270
[3.290280]  [410e7dd0] ? register_tracer+0x1b0/0x270
[3.291516]  [41035c82] warn_slowpath_null+0x22/0x30
[3.292723]  [410e7dd0] register_tracer+0x1b0/0x270
[3.293921]  [41434c7a] ? init_irqsoff_tracer+0x11/0x11
[3.295269]  [41434c95] init_wakeup_tracer+0x1b/0x1d
[3.296464]  [41001112] do_one_initcall+0x112/0x160
[3.297639]  [4141fadd] kernel_init+0xf7/0x18e
[3.298724]  [4141f455] ? do_early_param+0x7a/0x7a
[3.299879]  [4141f9e6] ? start_kernel+0x375/0x375
[3.301093]  [412b15c2] kernel_thread_helper+0x6/0x10
[3.302352] ---[ end trace 57f7151f6a5def05 ]---

Thanks,
Fengguang

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