[PATCH 0/3] [GIT PULL][3.9] tracing/perf: Various fixes

[PATCH 0/3] [GIT PULL][3.9] tracing/perf: Various fixes

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 660 bytes --]


Ingo,

Please pull the latest tip/perf/urgent tree, which can be found at:

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
tip/perf/urgent

Head SHA1: cc1e2627b179f0fccb3285fe565e893b570558b8


Jan Kiszka (1):
      ftrace: Consistently restore trace function on sysctl enabling

Steven Rostedt (Red Hat) (2):
      tracing: Fix race with update_max_tr_single and changing tracers
      ftrace: Do not call stub functions in control loop

----
 include/linux/ftrace.h |    2 ++
 kernel/trace/ftrace.c  |   13 +++++--------
 kernel/trace/trace.c   |    5 ++++-
 3 files changed, 11 insertions(+), 9 deletions(-)

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 490 bytes --]

[PATCH 1/3] tracing: Fix race with update_max_tr_single and changing tracers

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1004 bytes --]

From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>

The commit 34600f0e9 "tracing: Fix race with max_tr and changing tracers"
fixed the updating of the main buffers with the race of changing
tracers, but left out the fix to the updating of just a per cpu buffer.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace.c |    5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 4f1dade..7ba7fc7 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -744,8 +744,11 @@ update_max_tr_single(struct trace_array *tr, struct task_struct *tsk, int cpu)
 		return;
 
 	WARN_ON_ONCE(!irqs_disabled());
-	if (WARN_ON_ONCE(!current_trace->allocated_snapshot))
+	if (!current_trace->allocated_snapshot) {
+		/* Only the nop tracer should hit this when disabling */
+		WARN_ON_ONCE(current_trace != &nop_trace);
 		return;
+	}
 
 	arch_spin_lock(&ftrace_max_lock);
 
-- 
1.7.10.4



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 490 bytes --]

[PATCH 2/3] ftrace: Consistently restore trace function on sysctl enabling

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 1245 bytes --]

From: Jan Kiszka <jan.kiszka@siemens.com>

If we reenable ftrace via syctl, we currently set ftrace_trace_function
based on the previous simplistic algorithm. This is inconsistent with
what update_ftrace_function does. So better call that helper instead.

Link: http://lkml.kernel.org/r/5151D26F.1070702@siemens.com

Cc: stable@vger.kernel.org
Signed-off-by: Jan Kiszka <jan.kiszka@siemens.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c |    8 ++------
 1 file changed, 2 insertions(+), 6 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 6893d5a..cc4943c 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -4555,12 +4555,8 @@ ftrace_enable_sysctl(struct ctl_table *table, int write,
 		ftrace_startup_sysctl();
 
 		/* we are starting ftrace again */
-		if (ftrace_ops_list != &ftrace_list_end) {
-			if (ftrace_ops_list->next == &ftrace_list_end)
-				ftrace_trace_function = ftrace_ops_list->func;
-			else
-				ftrace_trace_function = ftrace_ops_list_func;
-		}
+		if (ftrace_ops_list != &ftrace_list_end)
+			update_ftrace_function();
 
 	} else {
 		/* stopping ftrace calls (just send to ftrace_stub) */
-- 
1.7.10.4



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 490 bytes --]

[PATCH 3/3] ftrace: Do not call stub functions in control loop

[Steven Rostedt]

[-- Attachment #1: Type: text/plain, Size: 5967 bytes --]

From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>

The function tracing control loop used by perf spits out a warning
if the called function is not a control function. This is because
the control function references a per cpu allocated data structure
on struct ftrace_ops that is not allocated for other types of
functions.

commit 0a016409e42 "ftrace: Optimize the function tracer list loop"

Had an optimization done to all function tracing loops to optimize
for a single registered ops. Unfortunately, this allows for a slight
race when tracing starts or ends, where the stub function might be
called after the current registered ops is removed. In this case we
get the following dump:

root# perf stat -e ftrace:function sleep 1
[   74.339105] WARNING: at include/linux/ftrace.h:209 ftrace_ops_control_func+0xde/0xf0()
[   74.349522] Hardware name: PRIMERGY RX200 S6
[   74.357149] Modules linked in: sg igb iTCO_wdt ptp pps_core iTCO_vendor_support i7core_edac dca lpc_ich i2c_i801 coretemp edac_core crc32c_intel mfd_core ghash_clmulni_intel dm_multipath acpi_power_meter pcspk
r microcode vhost_net tun macvtap macvlan nfsd kvm_intel kvm auth_rpcgss nfs_acl lockd sunrpc uinput xfs libcrc32c sd_mod crc_t10dif sr_mod cdrom mgag200 i2c_algo_bit drm_kms_helper ttm qla2xxx mptsas ahci drm li
bahci scsi_transport_sas mptscsih libata scsi_transport_fc i2c_core mptbase scsi_tgt dm_mirror dm_region_hash dm_log dm_mod
[   74.446233] Pid: 1377, comm: perf Tainted: G        W    3.9.0-rc1 #1
[   74.453458] Call Trace:
[   74.456233]  [<ffffffff81062e3f>] warn_slowpath_common+0x7f/0xc0
[   74.462997]  [<ffffffff810fbc60>] ? rcu_note_context_switch+0xa0/0xa0
[   74.470272]  [<ffffffff811041a2>] ? __unregister_ftrace_function+0xa2/0x1a0
[   74.478117]  [<ffffffff81062e9a>] warn_slowpath_null+0x1a/0x20
[   74.484681]  [<ffffffff81102ede>] ftrace_ops_control_func+0xde/0xf0
[   74.491760]  [<ffffffff8162f400>] ftrace_call+0x5/0x2f
[   74.497511]  [<ffffffff8162f400>] ? ftrace_call+0x5/0x2f
[   74.503486]  [<ffffffff8162f400>] ? ftrace_call+0x5/0x2f
[   74.509500]  [<ffffffff810fbc65>] ? synchronize_sched+0x5/0x50
[   74.516088]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
[   74.522268]  [<ffffffff810fbc65>] ? synchronize_sched+0x5/0x50
[   74.528837]  [<ffffffff811041a2>] ? __unregister_ftrace_function+0xa2/0x1a0
[   74.536696]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
[   74.542878]  [<ffffffff8162402d>] ? mutex_lock+0x1d/0x50
[   74.548869]  [<ffffffff81105c67>] unregister_ftrace_function+0x27/0x50
[   74.556243]  [<ffffffff8111eadf>] perf_ftrace_event_register+0x9f/0x140
[   74.563709]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
[   74.569887]  [<ffffffff8162402d>] ? mutex_lock+0x1d/0x50
[   74.575898]  [<ffffffff8111e94e>] perf_trace_destroy+0x2e/0x50
[   74.582505]  [<ffffffff81127ba9>] tp_perf_event_destroy+0x9/0x10
[   74.589298]  [<ffffffff811295d0>] free_event+0x70/0x1a0
[   74.595208]  [<ffffffff8112a579>] perf_event_release_kernel+0x69/0xa0
[   74.602460]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
[   74.608667]  [<ffffffff8112a640>] put_event+0x90/0xc0
[   74.614373]  [<ffffffff8112a740>] perf_release+0x10/0x20
[   74.620367]  [<ffffffff811a3044>] __fput+0xf4/0x280
[   74.625894]  [<ffffffff811a31de>] ____fput+0xe/0x10
[   74.631387]  [<ffffffff81083697>] task_work_run+0xa7/0xe0
[   74.637452]  [<ffffffff81014981>] do_notify_resume+0x71/0xb0
[   74.643843]  [<ffffffff8162fa92>] int_signal+0x12/0x17

To fix this a new ftrace_ops flag is added that denotes the ftrace_list_end
ftrace_ops stub as just that, a stub. This flag is now checked in the
control loop and the function is not called if the flag is set.

Thanks to Jovi for not just reporting the bug, but also pointing out
where the bug was in the code.

Link: http://lkml.kernel.org/r/514A8855.7090402@redhat.com
Link: http://lkml.kernel.org/r/1364377499-1900-15-git-send-email-jovi.zhangwei@huawei.com

Reported-by: WANG Chao <chaowang@redhat.com>
Reported-by: zhangwei(Jovi) <jovi.zhangwei@huawei.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/ftrace.h |    2 ++
 kernel/trace/ftrace.c  |    5 +++--
 2 files changed, 5 insertions(+), 2 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index e5ca8ef..167abf9 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -89,6 +89,7 @@ typedef void (*ftrace_func_t)(unsigned long ip, unsigned long parent_ip,
  *            that the call back has its own recursion protection. If it does
  *            not set this, then the ftrace infrastructure will add recursion
  *            protection for the caller.
+ * STUB   - The ftrace_ops is just a place holder.
  */
 enum {
 	FTRACE_OPS_FL_ENABLED			= 1 << 0,
@@ -98,6 +99,7 @@ enum {
 	FTRACE_OPS_FL_SAVE_REGS			= 1 << 4,
 	FTRACE_OPS_FL_SAVE_REGS_IF_SUPPORTED	= 1 << 5,
 	FTRACE_OPS_FL_RECURSION_SAFE		= 1 << 6,
+	FTRACE_OPS_FL_STUB			= 1 << 7,
 };
 
 struct ftrace_ops {
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index cc4943c..7e89710 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -66,7 +66,7 @@
 
 static struct ftrace_ops ftrace_list_end __read_mostly = {
 	.func		= ftrace_stub,
-	.flags		= FTRACE_OPS_FL_RECURSION_SAFE,
+	.flags		= FTRACE_OPS_FL_RECURSION_SAFE | FTRACE_OPS_FL_STUB,
 };
 
 /* ftrace_enabled is a method to turn ftrace on or off */
@@ -4131,7 +4131,8 @@ ftrace_ops_control_func(unsigned long ip, unsigned long parent_ip,
 	preempt_disable_notrace();
 	trace_recursion_set(TRACE_CONTROL_BIT);
 	do_for_each_ftrace_op(op, ftrace_control_list) {
-		if (!ftrace_function_local_disabled(op) &&
+		if (!(op->flags & FTRACE_OPS_FL_STUB) &&
+		    !ftrace_function_local_disabled(op) &&
 		    ftrace_ops_test(op, ip))
 			op->func(ip, parent_ip, op, regs);
 	} while_for_each_ftrace_op(op);
-- 
1.7.10.4



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 490 bytes --]

Re: [PATCH 3/3] ftrace: Do not call stub functions in control loop

[WANG Chao]

On 03/28/2013 08:52 PM, Steven Rostedt wrote:
> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> 
> The function tracing control loop used by perf spits out a warning
> if the called function is not a control function. This is because
> the control function references a per cpu allocated data structure
> on struct ftrace_ops that is not allocated for other types of
> functions.
> 
> commit 0a016409e42 "ftrace: Optimize the function tracer list loop"
> 
> Had an optimization done to all function tracing loops to optimize
> for a single registered ops. Unfortunately, this allows for a slight
> race when tracing starts or ends, where the stub function might be
> called after the current registered ops is removed. In this case we
> get the following dump:
> 
> root# perf stat -e ftrace:function sleep 1
> [   74.339105] WARNING: at include/linux/ftrace.h:209 ftrace_ops_control_func+0xde/0xf0()
> [   74.349522] Hardware name: PRIMERGY RX200 S6
> [   74.357149] Modules linked in: sg igb iTCO_wdt ptp pps_core iTCO_vendor_support i7core_edac dca lpc_ich i2c_i801 coretemp edac_core crc32c_intel mfd_core ghash_clmulni_intel dm_multipath acpi_power_meter pcspk
> r microcode vhost_net tun macvtap macvlan nfsd kvm_intel kvm auth_rpcgss nfs_acl lockd sunrpc uinput xfs libcrc32c sd_mod crc_t10dif sr_mod cdrom mgag200 i2c_algo_bit drm_kms_helper ttm qla2xxx mptsas ahci drm li
> bahci scsi_transport_sas mptscsih libata scsi_transport_fc i2c_core mptbase scsi_tgt dm_mirror dm_region_hash dm_log dm_mod
> [   74.446233] Pid: 1377, comm: perf Tainted: G        W    3.9.0-rc1 #1
> [   74.453458] Call Trace:
> [   74.456233]  [<ffffffff81062e3f>] warn_slowpath_common+0x7f/0xc0
> [   74.462997]  [<ffffffff810fbc60>] ? rcu_note_context_switch+0xa0/0xa0
> [   74.470272]  [<ffffffff811041a2>] ? __unregister_ftrace_function+0xa2/0x1a0
> [   74.478117]  [<ffffffff81062e9a>] warn_slowpath_null+0x1a/0x20
> [   74.484681]  [<ffffffff81102ede>] ftrace_ops_control_func+0xde/0xf0
> [   74.491760]  [<ffffffff8162f400>] ftrace_call+0x5/0x2f
> [   74.497511]  [<ffffffff8162f400>] ? ftrace_call+0x5/0x2f
> [   74.503486]  [<ffffffff8162f400>] ? ftrace_call+0x5/0x2f
> [   74.509500]  [<ffffffff810fbc65>] ? synchronize_sched+0x5/0x50
> [   74.516088]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
> [   74.522268]  [<ffffffff810fbc65>] ? synchronize_sched+0x5/0x50
> [   74.528837]  [<ffffffff811041a2>] ? __unregister_ftrace_function+0xa2/0x1a0
> [   74.536696]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
> [   74.542878]  [<ffffffff8162402d>] ? mutex_lock+0x1d/0x50
> [   74.548869]  [<ffffffff81105c67>] unregister_ftrace_function+0x27/0x50
> [   74.556243]  [<ffffffff8111eadf>] perf_ftrace_event_register+0x9f/0x140
> [   74.563709]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
> [   74.569887]  [<ffffffff8162402d>] ? mutex_lock+0x1d/0x50
> [   74.575898]  [<ffffffff8111e94e>] perf_trace_destroy+0x2e/0x50
> [   74.582505]  [<ffffffff81127ba9>] tp_perf_event_destroy+0x9/0x10
> [   74.589298]  [<ffffffff811295d0>] free_event+0x70/0x1a0
> [   74.595208]  [<ffffffff8112a579>] perf_event_release_kernel+0x69/0xa0
> [   74.602460]  [<ffffffff816254d5>] ? _cond_resched+0x5/0x40
> [   74.608667]  [<ffffffff8112a640>] put_event+0x90/0xc0
> [   74.614373]  [<ffffffff8112a740>] perf_release+0x10/0x20
> [   74.620367]  [<ffffffff811a3044>] __fput+0xf4/0x280
> [   74.625894]  [<ffffffff811a31de>] ____fput+0xe/0x10
> [   74.631387]  [<ffffffff81083697>] task_work_run+0xa7/0xe0
> [   74.637452]  [<ffffffff81014981>] do_notify_resume+0x71/0xb0
> [   74.643843]  [<ffffffff8162fa92>] int_signal+0x12/0x17
> 
> To fix this a new ftrace_ops flag is added that denotes the ftrace_list_end
> ftrace_ops stub as just that, a stub. This flag is now checked in the
> control loop and the function is not called if the flag is set.
> 
> Thanks to Jovi for not just reporting the bug, but also pointing out
> where the bug was in the code.
> 
> Link: http://lkml.kernel.org/r/514A8855.7090402@redhat.com
> Link: http://lkml.kernel.org/r/1364377499-1900-15-git-send-email-jovi.zhangwei@huawei.com
> 
> Reported-by: WANG Chao <chaowang@redhat.com>
> Reported-by: zhangwei(Jovi) <jovi.zhangwei@huawei.com>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  include/linux/ftrace.h |    2 ++
>  kernel/trace/ftrace.c  |    5 +++--
>  2 files changed, 5 insertions(+), 2 deletions(-)
> 
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index e5ca8ef..167abf9 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -89,6 +89,7 @@ typedef void (*ftrace_func_t)(unsigned long ip, unsigned long parent_ip,
>   *            that the call back has its own recursion protection. If it does
>   *            not set this, then the ftrace infrastructure will add recursion
>   *            protection for the caller.
> + * STUB   - The ftrace_ops is just a place holder.
>   */
>  enum {
>  	FTRACE_OPS_FL_ENABLED			= 1 << 0,
> @@ -98,6 +99,7 @@ enum {
>  	FTRACE_OPS_FL_SAVE_REGS			= 1 << 4,
>  	FTRACE_OPS_FL_SAVE_REGS_IF_SUPPORTED	= 1 << 5,
>  	FTRACE_OPS_FL_RECURSION_SAFE		= 1 << 6,
> +	FTRACE_OPS_FL_STUB			= 1 << 7,
>  };
>  
>  struct ftrace_ops {
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index cc4943c..7e89710 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -66,7 +66,7 @@
>  
>  static struct ftrace_ops ftrace_list_end __read_mostly = {
>  	.func		= ftrace_stub,
> -	.flags		= FTRACE_OPS_FL_RECURSION_SAFE,
> +	.flags		= FTRACE_OPS_FL_RECURSION_SAFE | FTRACE_OPS_FL_STUB,
>  };
>  
>  /* ftrace_enabled is a method to turn ftrace on or off */
> @@ -4131,7 +4131,8 @@ ftrace_ops_control_func(unsigned long ip, unsigned long parent_ip,
>  	preempt_disable_notrace();
>  	trace_recursion_set(TRACE_CONTROL_BIT);
>  	do_for_each_ftrace_op(op, ftrace_control_list) {
> -		if (!ftrace_function_local_disabled(op) &&
> +		if (!(op->flags & FTRACE_OPS_FL_STUB) &&
> +		    !ftrace_function_local_disabled(op) &&
>  		    ftrace_ops_test(op, ip))
>  			op->func(ip, parent_ip, op, regs);
>  	} while_for_each_ftrace_op(op);
> 

Tested this patch on top of 3.9-rc4 and didn't see this issue any more.

Tested by WANG Chao <chaowang@redhat.com>

Thanks for the fix.
WANG Chao