diff mbox

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

Message ID 1343779778.27983.73.camel@gandalf.stny.rr.com (mailing list archive)
State New, archived
Headers show

Commit Message

Steven Rostedt Aug. 1, 2012, 12:09 a.m. UTC 
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



--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Comments

Paul E. McKenney Aug. 1, 2012, 12:18 a.m. UTC | #1 
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 kvm" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Fengguang Wu Aug. 1, 2012, 12:43 a.m. UTC | #2 
On Tue, Jul 31, 2012 at 05:18:11PM -0700, Paul E. McKenney wrote:
> 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!
 
With all 3 patches applied, the warning on __update_max_tr finally
goes away. Thanks!

However, this unrelated warning still reliably remains (the same config).
I think it's pci_get_subsys() triggered this assert:

        /*
         * Oi! Can't be having __GFP_FS allocations with IRQs disabled.
         */
        if (DEBUG_LOCKS_WARN_ON(irqs_disabled_flags(flags)))
                return;

[   91.282131] machine restart
[   91.283895] ------------[ cut here ]------------
[   91.284731] WARNING: at /c/wfg/linux/kernel/lockdep.c:2739 lockdep_trace_alloc+0x1fb/0x210()
[   91.286132] Modules linked in:
[   91.286703] Pid: 697, comm: reboot Not tainted 3.5.0-00024-g01ff5db-dirty #4
[   91.287859] Call Trace:
[   91.288289]  [<81050148>] warn_slowpath_common+0xb8/0x100
[   91.289338]  [<8110acdb>] ? lockdep_trace_alloc+0x1fb/0x210
[   91.290264]  [<8110acdb>] ? lockdep_trace_alloc+0x1fb/0x210
[   91.291161]  [<810501ce>] warn_slowpath_null+0x3e/0x50
[   91.292042]  [<8110acdb>] lockdep_trace_alloc+0x1fb/0x210
[   91.292934]  [<81228e25>] kmem_cache_alloc_trace+0x55/0x600
[   91.292934]  [<813025ca>] ? kobject_put+0x9a/0x160
[   91.292934]  [<814e95e0>] ? klist_iter_exit+0x30/0x50
[   91.292934]  [<81405881>] ? bus_find_device+0xf1/0x120
[   91.292934]  [<81361a3c>] ? pci_get_subsys+0x11c/0x1b0
[   91.292934]  [<81361a3c>] pci_get_subsys+0x11c/0x1b0
[   91.292934]  [<81361afe>] pci_get_device+0x2e/0x40
[   91.292934]  [<81033e25>] mach_reboot_fixups+0xa5/0xd0
[   91.292934]  [<81027611>] native_machine_emergency_restart+0x1f1/0x590
[   91.292934]  [<814f2e00>] ? printk+0x4b/0x5b
[   91.292934]  [<810269ef>] native_machine_restart+0x6f/0x80
[   91.292934]  [<810271cc>] machine_restart+0x1c/0x30
[   91.292934]  [<810886e0>] kernel_restart+0x70/0xc0
[   91.292934]  [<81088a85>] sys_reboot+0x325/0x380
[   91.292934]  [<811f796c>] ? handle_pte_fault+0xdc/0x1740
[   91.292934]  [<811f93e7>] ? handle_mm_fault+0x417/0x4a0
[   91.292934]  [<8103e07b>] ? do_page_fault+0x7fb/0xb30
[   91.292934]  [<810b33e7>] ? up_read+0x37/0x70
[   91.292934]  [<8103e07b>] ? do_page_fault+0x7fb/0xb30
[   91.292934]  [<8123c063>] ? do_sys_open+0x3a3/0x3f0
[   91.292934]  [<8123c063>] ? do_sys_open+0x3a3/0x3f0
[   91.292934]  [<810b0270>] ? update_rmtp+0xe0/0xe0
[   91.292934]  [<8150376e>] ? restore_all+0xf/0xf
[   91.292934]  [<8103d880>] ? vmalloc_sync_all+0x320/0x320
[   91.292934]  [<81109fca>] ? trace_hardirqs_on_caller+0x28a/0x380
[   91.292934]  [<81311594>] ? trace_hardirqs_on_thunk+0xc/0x10
[   91.292934]  [<81503735>] syscall_call+0x7/0xb

Thanks,
Fengguang
--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Fengguang Wu Aug. 22, 2012, 2:50 a.m. UTC | #3 
Feng,

> I think it's pci_get_subsys() triggered this assert:
> 
>         /*
>          * Oi! Can't be having __GFP_FS allocations with IRQs disabled.
>          */
>         if (DEBUG_LOCKS_WARN_ON(irqs_disabled_flags(flags)))
>                 return;

It's bisected down to this commit:

commit 55c844a4dd16a4d1fdc0cf2a283ec631a02ec448
Author:     Feng Tang <feng.tang@intel.com>
AuthorDate: Wed May 30 23:15:41 2012 +0800
Commit:     Ingo Molnar <mingo@kernel.org>
CommitDate: Wed Jun 6 12:03:23 2012 +0200

    x86/reboot: Fix a warning message triggered by stop_other_cpus()

Thanks,
Fengguang

> [   91.282131] machine restart
> [   91.283895] ------------[ cut here ]------------
> [   91.284731] WARNING: at /c/wfg/linux/kernel/lockdep.c:2739 lockdep_trace_alloc+0x1fb/0x210()
> [   91.286132] Modules linked in:
> [   91.286703] Pid: 697, comm: reboot Not tainted 3.5.0-00024-g01ff5db-dirty #4
> [   91.287859] Call Trace:
> [   91.288289]  [<81050148>] warn_slowpath_common+0xb8/0x100
> [   91.289338]  [<8110acdb>] ? lockdep_trace_alloc+0x1fb/0x210
> [   91.290264]  [<8110acdb>] ? lockdep_trace_alloc+0x1fb/0x210
> [   91.291161]  [<810501ce>] warn_slowpath_null+0x3e/0x50
> [   91.292042]  [<8110acdb>] lockdep_trace_alloc+0x1fb/0x210
> [   91.292934]  [<81228e25>] kmem_cache_alloc_trace+0x55/0x600
> [   91.292934]  [<813025ca>] ? kobject_put+0x9a/0x160
> [   91.292934]  [<814e95e0>] ? klist_iter_exit+0x30/0x50
> [   91.292934]  [<81405881>] ? bus_find_device+0xf1/0x120
> [   91.292934]  [<81361a3c>] ? pci_get_subsys+0x11c/0x1b0
> [   91.292934]  [<81361a3c>] pci_get_subsys+0x11c/0x1b0
> [   91.292934]  [<81361afe>] pci_get_device+0x2e/0x40
> [   91.292934]  [<81033e25>] mach_reboot_fixups+0xa5/0xd0
> [   91.292934]  [<81027611>] native_machine_emergency_restart+0x1f1/0x590
> [   91.292934]  [<814f2e00>] ? printk+0x4b/0x5b
> [   91.292934]  [<810269ef>] native_machine_restart+0x6f/0x80
> [   91.292934]  [<810271cc>] machine_restart+0x1c/0x30
> [   91.292934]  [<810886e0>] kernel_restart+0x70/0xc0
> [   91.292934]  [<81088a85>] sys_reboot+0x325/0x380
> [   91.292934]  [<811f796c>] ? handle_pte_fault+0xdc/0x1740
> [   91.292934]  [<811f93e7>] ? handle_mm_fault+0x417/0x4a0
> [   91.292934]  [<8103e07b>] ? do_page_fault+0x7fb/0xb30
> [   91.292934]  [<810b33e7>] ? up_read+0x37/0x70
> [   91.292934]  [<8103e07b>] ? do_page_fault+0x7fb/0xb30
> [   91.292934]  [<8123c063>] ? do_sys_open+0x3a3/0x3f0
> [   91.292934]  [<8123c063>] ? do_sys_open+0x3a3/0x3f0
> [   91.292934]  [<810b0270>] ? update_rmtp+0xe0/0xe0
> [   91.292934]  [<8150376e>] ? restore_all+0xf/0xf
> [   91.292934]  [<8103d880>] ? vmalloc_sync_all+0x320/0x320
> [   91.292934]  [<81109fca>] ? trace_hardirqs_on_caller+0x28a/0x380
> [   91.292934]  [<81311594>] ? trace_hardirqs_on_thunk+0xc/0x10
> [   91.292934]  [<81503735>] syscall_call+0x7/0xb
> 
> Thanks,
> Fengguang
--
To unsubscribe from this list: send the line "unsubscribe kvm" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
diff mbox

Patch

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;