Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1470506 > unrolled thread

Re: [PATCH v2 1/3] tracing: Deference pointers without RCU checks

Started byMasami Hiramatsu <mhiramat@kernel.org>
First post2016-08-26 03:50 +0200
Last post2016-08-29 02:00 +0200
Articles 3 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH v2 1/3] tracing: Deference pointers without RCU checks Masami Hiramatsu <mhiramat@kernel.org> - 2016-08-26 03:50 +0200
    Re: [PATCH v2 1/3] tracing: Deference pointers without RCU checks Binoy Jayan <binoy.jayan@linaro.org> - 2016-08-26 07:30 +0200
      Re: [PATCH v2 1/3] tracing: Deference pointers without RCU checks Masami Hiramatsu <mhiramat@kernel.org> - 2016-08-29 02:00 +0200

#1470506 — Re: [PATCH v2 1/3] tracing: Deference pointers without RCU checks

FromMasami Hiramatsu <mhiramat@kernel.org>
Date2016-08-26 03:50 +0200
SubjectRe: [PATCH v2 1/3] tracing: Deference pointers without RCU checks
Message-ID<saero-rr-7@gated-at.bofh.it>
On Wed, 24 Aug 2016 16:47:28 +0530
Binoy Jayan <binoy.jayan@linaro.org> wrote:

> From: Daniel Wagner <daniel.wagner@bmw-carit.de>
> 
> The tracepoint can't be used in code section where we are in the
> middle of a state transition.
> 
> For example if we place a tracepoint inside start/stop_critical_section(),
> lockdep complains with
> 
> [    0.035589] WARNING: CPU: 0 PID: 3 at kernel/locking/lockdep.c:3560 \
> check_flags.part.36+0x1bc/0x210() [    0.036000] \
> DEBUG_LOCKS_WARN_ON(current->softirqs_enabled) [    0.036000] Kernel panic - not \
> syncing: panic_on_warn set ... [    0.036000]
> [    0.036000] CPU: 0 PID: 3 Comm: ksoftirqd/0 Not tainted 4.0.0-rc7+ #460
> [    0.036000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS \
> 1.7.5-20140709_153950- 04/01/2014 [    0.036000]  ffffffff81f2463a ffff88007c93bb98 \
> ffffffff81afb317 0000000000000001 [    0.036000]  ffffffff81f212b3 ffff88007c93bc18 \
> ffffffff81af7bc2 ffff88007c93bbb8 [    0.036000]  ffffffff00000008 ffff88007c93bc28 \
> ffff88007c93bbc8 000000000093bbd8 [    0.036000] Call Trace:
> [    0.036000]  [<ffffffff81afb317>] dump_stack+0x4f/0x7b
> [    0.036000]  [<ffffffff81af7bc2>] panic+0xc0/0x1e9
> [    0.036000]  [<ffffffff81b07188>] ? _raw_spin_unlock_irqrestore+0x38/0x80
> [    0.036000]  [<ffffffff81052a60>] warn_slowpath_common+0xc0/0xc0
> [    0.036000]  [<ffffffff81057116>] ? __local_bh_enable+0x36/0x70
> [    0.036000]  [<ffffffff81052aa6>] warn_slowpath_fmt+0x46/0x50
> [    0.036000]  [<ffffffff810a468c>] check_flags.part.36+0x1bc/0x210
> [    0.036000]  [<ffffffff810a5168>] lock_is_held+0x78/0x90
> [    0.036000]  [<ffffffff81057116>] ? __local_bh_enable+0x36/0x70
> [    0.036000]  [<ffffffff810588ab>] ? __do_softirq+0x3db/0x500
> [    0.036000]  [<ffffffff81134495>] trace_preempt_on+0x255/0x260
> [    0.036000]  [<ffffffff81081c0b>] preempt_count_sub+0xab/0xf0
> [    0.036000]  [<ffffffff81057116>] __local_bh_enable+0x36/0x70
> [    0.036000]  [<ffffffff810588ab>] __do_softirq+0x3db/0x500
> [    0.036000]  [<ffffffff810589ef>] run_ksoftirqd+0x1f/0x60
> [    0.036000]  [<ffffffff81079653>] smpboot_thread_fn+0x193/0x2a0
> [    0.036000]  [<ffffffff810794c0>] ? SyS_setgroups+0x150/0x150
> [    0.036000]  [<ffffffff81075312>] kthread+0xf2/0x110
> [    0.036000]  [<ffffffff81b026b3>] ? wait_for_completion+0xc3/0x120
> [    0.036000]  [<ffffffff81081c0b>] ? preempt_count_sub+0xab/0xf0
> [    0.036000]  [<ffffffff81075220>] ? kthread_create_on_node+0x240/0x240
> [    0.036000]  [<ffffffff81b07cc8>] ret_from_fork+0x58/0x90
> [    0.036000]  [<ffffffff81075220>] ? kthread_create_on_node+0x240/0x240
> [    0.036000] ---[ end Kernel panic - not syncing: panic_on_warn set ...
> 
> PeterZ was so kind to explain it to me what is happening:
> 
> "__local_bh_enable() tests if this is the last SOFTIRQ_OFFSET, if so it
> tells lockdep softirqs are enabled with trace_softirqs_on() after that
> we go an actually modify the preempt_count with preempt_count_sub().
> Then in preempt_count_sub() you call into trace_preempt_on() if this
> was the last preempt_count increment but you do that _before_ you
> actually change the preempt_count with __preempt_count_sub() at this
> point lockdep and preempt_count think the world differs and *boom*"
> 
> So the simplest way to avoid this is by disabling the consistency
> checks.
> 
> We also need to take care of the iterating in trace_events_trigger.c
> to avoid a splatter in conjunction with the hist trigger.

Special care for lockdep inside tracepoint handler is reasonable.

Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>

Steven, since this seems a bugfix, could you pick this from the series?

Thank you,

> 
> Signed-off-by: Daniel Wagner <daniel.wagner@bmw-carit.de>
> ---
>  include/linux/rculist.h             | 36 ++++++++++++++++++++++++++++++++++++
>  include/linux/tracepoint.h          |  4 ++--
>  kernel/trace/trace_events_trigger.c |  6 +++---
>  3 files changed, 41 insertions(+), 5 deletions(-)
> 
> diff --git a/include/linux/rculist.h b/include/linux/rculist.h
> index 8beb98d..bee836b 100644
> --- a/include/linux/rculist.h
> +++ b/include/linux/rculist.h
> @@ -279,6 +279,24 @@ static inline void list_splice_tail_init_rcu(struct list_head *list,
>  	container_of(lockless_dereference(ptr), type, member)
>  
>  /**
> + * list_entry_rcu_notrace - get the struct for this entry (for tracing)
> + * @ptr:        the &struct list_head pointer.
> + * @type:       the type of the struct this is embedded in.
> + * @member:     the name of the list_head within the struct.
> + *
> + * This primitive may safely run concurrently with the _rcu list-mutation
> + * primitives such as list_add_rcu() as long as it's guarded by rcu_read_lock().
> + *
> + * This is the same as list_entry_rcu() except that it does
> + * not do any RCU debugging or tracing.
> + */
> +#define list_entry_rcu_notrace(ptr, type, member) \
> +({ \
> +	typeof(*ptr) __rcu *__ptr = (typeof(*ptr) __rcu __force *)ptr; \
> +	container_of((typeof(ptr))rcu_dereference_raw_notrace(__ptr), type, member); \
> +})
> +
> +/**
>   * Where are list_empty_rcu() and list_first_entry_rcu()?
>   *
>   * Implementing those functions following their counterparts list_empty() and
> @@ -391,6 +409,24 @@ static inline void list_splice_tail_init_rcu(struct list_head *list,
>  	     pos = list_entry_lockless(pos->member.next, typeof(*pos), member))
>  
>  /**
> + * list_for_each_entry_rcu_notrace	-	iterate over rcu list of given type (for tracing)
> + * @pos:	the type * to use as a loop cursor.
> + * @head:	the head for your list.
> + * @member:	the name of the list_head within the struct.
> + *
> + * This list-traversal primitive may safely run concurrently with
> + * the _rcu list-mutation primitives such as list_add_rcu()
> + * as long as the traversal is guarded by rcu_read_lock().
> + *
> + * This is the same as list_for_each_entry_rcu() except that it does
> + * not do any RCU debugging or tracing.
> + */
> +#define list_for_each_entry_rcu_notrace(pos, head, member) \
> +	for (pos = list_entry_rcu_notrace((head)->next, typeof(*pos), member); \
> +		&pos->member != (head); \
> +		pos = list_entry_rcu_notrace(pos->member.next, typeof(*pos), member))
> +
> +/**
>   * list_for_each_entry_continue_rcu - continue iteration over list of given type
>   * @pos:	the type * to use as a loop cursor.
>   * @head:	the head for your list.
> diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
> index be586c6..d0e2a82 100644
> --- a/include/linux/tracepoint.h
> +++ b/include/linux/tracepoint.h
> @@ -138,7 +138,7 @@ extern void syscall_unregfunc(void);
>  			return;						\
>  		prercu;							\
>  		rcu_read_lock_sched_notrace();				\
> -		it_func_ptr = rcu_dereference_sched((tp)->funcs);	\
> +		it_func_ptr = rcu_dereference_raw_notrace((tp)->funcs);	\
>  		if (it_func_ptr) {					\
>  			do {						\
>  				it_func = (it_func_ptr)->func;		\
> @@ -189,7 +189,7 @@ extern void syscall_unregfunc(void);
>  				TP_CONDITION(cond),,);			\
>  		if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) {		\
>  			rcu_read_lock_sched_notrace();			\
> -			rcu_dereference_sched(__tracepoint_##name.funcs);\
> +			rcu_dereference_raw_notrace(__tracepoint_##name.funcs);\
>  			rcu_read_unlock_sched_notrace();		\
>  		}							\
>  	}								\
> diff --git a/kernel/trace/trace_events_trigger.c b/kernel/trace/trace_events_trigger.c
> index a975571..4489fb4 100644
> --- a/kernel/trace/trace_events_trigger.c
> +++ b/kernel/trace/trace_events_trigger.c
> @@ -71,14 +71,14 @@ event_triggers_call(struct trace_event_file *file, void *rec)
>  	if (list_empty(&file->triggers))
>  		return tt;
>  
> -	list_for_each_entry_rcu(data, &file->triggers, list) {
> +	list_for_each_entry_rcu_notrace(data, &file->triggers, list) {
>  		if (data->paused)
>  			continue;
>  		if (!rec) {
>  			data->ops->func(data, rec);
>  			continue;
>  		}
> -		filter = rcu_dereference_sched(data->filter);
> +		filter = rcu_dereference_raw_notrace(data->filter);
>  		if (filter && !filter_match_preds(filter, rec))
>  			continue;
>  		if (event_command_post_trigger(data->cmd_ops)) {
> @@ -111,7 +111,7 @@ event_triggers_post_call(struct trace_event_file *file,
>  {
>  	struct event_trigger_data *data;
>  
> -	list_for_each_entry_rcu(data, &file->triggers, list) {
> +	list_for_each_entry_rcu_notrace(data, &file->triggers, list) {
>  		if (data->paused)
>  			continue;
>  		if (data->cmd_ops->trigger_type & tt)
> -- 
> The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
> a Linux Foundation Collaborative Project
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

[toc] | [next] | [standalone]

#1470550

FromBinoy Jayan <binoy.jayan@linaro.org>
Date2016-08-26 07:30 +0200
Message-ID<sahSh-2Or-3@gated-at.bofh.it>
In reply to#1470506
On 26 August 2016 at 07:19, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> On Wed, 24 Aug 2016 16:47:28 +0530
>> "__local_bh_enable() tests if this is the last SOFTIRQ_OFFSET, if so it
>> tells lockdep softirqs are enabled with trace_softirqs_on() after that
>> we go an actually modify the preempt_count with preempt_count_sub().
>> Then in preempt_count_sub() you call into trace_preempt_on() if this
>> was the last preempt_count increment but you do that _before_ you
>> actually change the preempt_count with __preempt_count_sub() at this
>> point lockdep and preempt_count think the world differs and *boom*"
>>
>> So the simplest way to avoid this is by disabling the consistency
>> checks.
>>
>> We also need to take care of the iterating in trace_events_trigger.c
>> to avoid a splatter in conjunction with the hist trigger.
>
> Special care for lockdep inside tracepoint handler is reasonable.
>
> Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>
>
> Steven, since this seems a bugfix, could you pick this from the series?
>
> Thank you,
>
> --
> Masami Hiramatsu <mhiramat@kernel.org>


Hi Daniel/Masami,

I ran into a similar rcu error while using same tracepoint for all
three latency types
and using a filter like below to trigger only events falling under a
specific type.

echo 'hist:key=ltype,cpu:val=latency:sort=ltype,cpu if ltype==0' > \
   /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger

The error occurs only when I use the predicate 'if ltype==0' as filter.

It occurs in 'filter_match_preds' during a call to 'rcu_dereference_sched'.
kernel/trace/trace_events_filter.c +611 : filter_match_preds()

Surprisingly, this happens only the first time the echo command is used on
the trigger file after each boot.

Do you think it is similar to the bug you have fixed? May be i'll try using
"rcu_dereference_raw_notrace" instead of 'rcu_dereference_sched'.

 Binoy


[ 1029.324257] ===============================
[ 1029.324785] [ INFO: suspicious RCU usage. ]
[ 1029.328698] 4.7.0+ #49 Not tainted
[ 1029.332858] -------------------------------
[ 1029.336334] /local/mnt/workspace/src/korg/linux/kernel/trace/trace_events_filter.c:611
suspicious rcu_dereference_check() usage!
[ 1029.340423]
[ 1029.340423] other info that might help us debug this:
[ 1029.340423]
[ 1029.352226]
[ 1029.352226] RCU used illegally from idle CPU!
[ 1029.352226] rcu_scheduler_active = 1, debug_locks = 0
[ 1029.359953] RCU used illegally from extended quiescent state!
[ 1029.371057] no locks held by swapper/0/0.
[ 1029.376696]
[ 1029.376696] stack backtrace:
[ 1029.380693] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.7.0+ #49
[ 1029.385033] Hardware name: Qualcomm Technologies, Inc. APQ 8016 SBC (DT)
[ 1029.391111] Call trace:
[ 1029.397798] [<ffff000008089ecc>] dump_backtrace+0x0/0x1e0
[ 1029.399967] [<ffff00000808a0d0>] show_stack+0x24/0x2c
[ 1029.405523] [<ffff000008431554>] dump_stack+0xb0/0xf0
[ 1029.410557] [<ffff000008115dd0>] lockdep_rcu_suspicious+0xe8/0x120
[ 1029.415595] [<ffff0000081a5d40>] filter_match_preds+0x108/0x118
[ 1029.421669] [<ffff0000081a8308>] event_triggers_call+0x5c/0xc0
[ 1029.427485] [<ffff0000081a2184>] trace_event_buffer_commit+0x11c/0x244
[ 1029.433390] [<ffff00000819a4c0>]
trace_event_raw_event_latency_template+0x58/0xa4
[ 1029.439902] [<ffff00000819b5ec>] time_hardirqs_on+0x264/0x290
[ 1029.447450] [<ffff0000081170d0>] trace_hardirqs_on_caller+0x20/0x180
[ 1029.453179] [<ffff000008117240>] trace_hardirqs_on+0x10/0x18
[ 1029.459604] [<ffff000008789290>] cpuidle_enter_state+0xc8/0x2e0
[ 1029.465246] [<ffff00000878951c>] cpuidle_enter+0x34/0x40
[ 1029.470888] [<ffff000008111188>] call_cpuidle+0x3c/0x5c
[ 1029.476442] [<ffff0000081114e8>] cpu_startup_entry+0x1c0/0x360
[ 1029.481392] [<ffff000008955bc8>] rest_init+0x150/0x160
[ 1029.487293] [<ffff000008d30b98>] start_kernel+0x3a4/0x3b8
[ 1029.492415] [<ffff000008d301bc>] __primary_switched+0x30/0x74

Binoy

[toc] | [prev] | [next] | [standalone]

#1471494

FromMasami Hiramatsu <mhiramat@kernel.org>
Date2016-08-29 02:00 +0200
Message-ID<sbi9z-8ga-1@gated-at.bofh.it>
In reply to#1470550
Hi Binoy,

On Fri, 26 Aug 2016 10:56:12 +0530
Binoy Jayan <binoy.jayan@linaro.org> wrote:

> On 26 August 2016 at 07:19, Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > On Wed, 24 Aug 2016 16:47:28 +0530
> >> "__local_bh_enable() tests if this is the last SOFTIRQ_OFFSET, if so it
> >> tells lockdep softirqs are enabled with trace_softirqs_on() after that
> >> we go an actually modify the preempt_count with preempt_count_sub().
> >> Then in preempt_count_sub() you call into trace_preempt_on() if this
> >> was the last preempt_count increment but you do that _before_ you
> >> actually change the preempt_count with __preempt_count_sub() at this
> >> point lockdep and preempt_count think the world differs and *boom*"
> >>
> >> So the simplest way to avoid this is by disabling the consistency
> >> checks.
> >>
> >> We also need to take care of the iterating in trace_events_trigger.c
> >> to avoid a splatter in conjunction with the hist trigger.
> >
> > Special care for lockdep inside tracepoint handler is reasonable.
> >
> > Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>
> >
> > Steven, since this seems a bugfix, could you pick this from the series?
> >
> > Thank you,
> >
> > --
> > Masami Hiramatsu <mhiramat@kernel.org>
> 
> 
> Hi Daniel/Masami,
> 
> I ran into a similar rcu error while using same tracepoint for all
> three latency types
> and using a filter like below to trigger only events falling under a
> specific type.
> 
> echo 'hist:key=ltype,cpu:val=latency:sort=ltype,cpu if ltype==0' > \
>    /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
> 
> The error occurs only when I use the predicate 'if ltype==0' as filter.
> 
> It occurs in 'filter_match_preds' during a call to 'rcu_dereference_sched'.
> kernel/trace/trace_events_filter.c +611 : filter_match_preds()
> 
> Surprisingly, this happens only the first time the echo command is used on
> the trigger file after each boot.
> 
> Do you think it is similar to the bug you have fixed? May be i'll try using
> "rcu_dereference_raw_notrace" instead of 'rcu_dereference_sched'.

Yes, I think we should fix that too. No rcu_derefaernce_sched used in
trace callees. (except for kprobe events, since it is out of context)

Thank you,


> 
>  Binoy
> 
> 
> [ 1029.324257] ===============================
> [ 1029.324785] [ INFO: suspicious RCU usage. ]
> [ 1029.328698] 4.7.0+ #49 Not tainted
> [ 1029.332858] -------------------------------
> [ 1029.336334] /local/mnt/workspace/src/korg/linux/kernel/trace/trace_events_filter.c:611
> suspicious rcu_dereference_check() usage!
> [ 1029.340423]
> [ 1029.340423] other info that might help us debug this:
> [ 1029.340423]
> [ 1029.352226]
> [ 1029.352226] RCU used illegally from idle CPU!
> [ 1029.352226] rcu_scheduler_active = 1, debug_locks = 0
> [ 1029.359953] RCU used illegally from extended quiescent state!
> [ 1029.371057] no locks held by swapper/0/0.
> [ 1029.376696]
> [ 1029.376696] stack backtrace:
> [ 1029.380693] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.7.0+ #49
> [ 1029.385033] Hardware name: Qualcomm Technologies, Inc. APQ 8016 SBC (DT)
> [ 1029.391111] Call trace:
> [ 1029.397798] [<ffff000008089ecc>] dump_backtrace+0x0/0x1e0
> [ 1029.399967] [<ffff00000808a0d0>] show_stack+0x24/0x2c
> [ 1029.405523] [<ffff000008431554>] dump_stack+0xb0/0xf0
> [ 1029.410557] [<ffff000008115dd0>] lockdep_rcu_suspicious+0xe8/0x120
> [ 1029.415595] [<ffff0000081a5d40>] filter_match_preds+0x108/0x118
> [ 1029.421669] [<ffff0000081a8308>] event_triggers_call+0x5c/0xc0
> [ 1029.427485] [<ffff0000081a2184>] trace_event_buffer_commit+0x11c/0x244
> [ 1029.433390] [<ffff00000819a4c0>]
> trace_event_raw_event_latency_template+0x58/0xa4
> [ 1029.439902] [<ffff00000819b5ec>] time_hardirqs_on+0x264/0x290
> [ 1029.447450] [<ffff0000081170d0>] trace_hardirqs_on_caller+0x20/0x180
> [ 1029.453179] [<ffff000008117240>] trace_hardirqs_on+0x10/0x18
> [ 1029.459604] [<ffff000008789290>] cpuidle_enter_state+0xc8/0x2e0
> [ 1029.465246] [<ffff00000878951c>] cpuidle_enter+0x34/0x40
> [ 1029.470888] [<ffff000008111188>] call_cpuidle+0x3c/0x5c
> [ 1029.476442] [<ffff0000081114e8>] cpu_startup_entry+0x1c0/0x360
> [ 1029.481392] [<ffff000008955bc8>] rest_init+0x150/0x160
> [ 1029.487293] [<ffff000008d30b98>] start_kernel+0x3a4/0x3b8
> [ 1029.492415] [<ffff000008d301bc>] __primary_switched+0x30/0x74
> 
> Binoy


-- 
Masami Hiramatsu <mhiramat@kernel.org>

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web