Re: Testing tracer wakeup_rt: .. no entries found ..FAILED!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
[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!
[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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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!
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/