tracing: Updates and minor fixes for 3.11.

The following patches are queued for 3.11.

Harsh Prateek Bora (1):
tracing/trivial: Consolidate error return condition

Juri Lelli (1):
ftrace: Fix stddev calculation in function profiler

Li Zefan (1):
ftrace: Remove ftrace_regex_lseek()

Namhyung Kim (1):
tracing: Do not call kmem_cache_free() on allocation failure

Steven Rostedt (2):
ftrace: Use schedule_on_each_cpu() as a heavy synchronize_sched()
tracing: Add binary '&' filter for events

Steven Rostedt (Red Hat) (4):
tracing: Add function probe to trigger a ftrace dump to console
tracing: Add function probe to trigger a ftrace dump of current CPU trace
tracing: Update documentation on tracepoint glob matching
tracing: Disable tracing on warning

Wang YanQing (1):
tracing: Fix file mode of free_buffer

zhangwei(Jovi) (1):
tracing/kprobes: Remove unnecessary checking of trace_probe_is_enabled

----

 Documentation/kernel-parameters.txt |   13 +++++
 Documentation/trace/events.txt      |   15 ++++-
 Documentation/trace/ftrace.txt      |   13 +++++
 include/linux/ftrace.h              |    9 +--
 kernel/panic.c                      |    3 +
 kernel/sysctl.c                     |    7 +++
 kernel/trace/ftrace.c               |   33 +++++++++--
 kernel/trace/trace.c                |   19 ++++++-
 kernel/trace/trace_events.c         |   12 +---
 kernel/trace/trace_events_filter.c  |    6 ++
 kernel/trace/trace_functions.c      |  103 +++++++++++++++++++++++++++++++++--
 kernel/trace/trace_kprobe.c         |    3 +-
 12 files changed, 207 insertions(+), 29 deletions(-)

From: "Steven Rostedt (Red Hat)" <[email protected]>

Add the "dump" command to have the ftrace buffer dumped to console if a function is hit. This is useful when debugging a tripple fault, where you have an idea of a function that is called just before the tripple fault occurs, and can tell ftrace to dump its content out to the console before it continues.

Format is:

<function>:dump

echo 'bad_address:dump' > /debug/tracing/set_ftrace_filter

To remove this:

echo '!bad_address:dump' > /debug/tracing/set_ftrace_filter

---
 Documentation/trace/ftrace.txt |    7 +++++
 kernel/trace/trace_functions.c |   59 ++++++++++++++++++++++++++++++++++++----
 2 files changed, 61 insertions(+), 5 deletions(-)

index bfe8c29..cc9ec57 100644
@@ -2430,6 +2430,13 @@ The following commands are supported:
    echo '!schedule:disable_event:sched:sched_switch' > \
    	 set_ftrace_filter
 
+- dump
+  When the function is hit, it will dump the contents of the ftrace
+  ring buffer to the console. This is useful if you need to debug
+  something, and want to dump the trace when a certain function
+  is hit. Perhaps its a function that is called before a tripple
+  fault happens and does not allow you to get a regular dump.
+
 trace_pipe
 ----------
 

1.7.10.4

From: "Steven Rostedt (Red Hat)" <[email protected]>

Add the "cpudump" command to have the current CPU ftrace buffer dumped to console if a function is hit. This is useful when debugging a tripple fault, where you have an idea of a function that is called just before the tripple fault occurs, and can tell ftrace to dump its content out to the console before it continues.

This differs from the "dump" command as it only dumps the content of the ring buffer for the currently executing CPU, and does not show the contents of the other CPUs.

Format is:

<function>:cpudump

echo 'bad_address:cpudump' > /debug/tracing/set_ftrace_filter

To remove this:

echo '!bad_address:cpudump' > /debug/tracing/set_ftrace_filter

---
 Documentation/trace/ftrace.txt |    6 ++++++
 kernel/trace/trace_functions.c |   44 ++++++++++++++++++++++++++++++++++++++++
 2 files changed, 50 insertions(+)

index cc9ec57..b937c6e 100644
@@ -2437,6 +2437,12 @@ The following commands are supported:
   is hit. Perhaps its a function that is called before a tripple
   fault happens and does not allow you to get a regular dump.
 
+- cpudump
+  When the function is hit, it will dump the contents of the ftrace
+  ring buffer for the current CPU to the console. Unlike the "dump"
+  command, it only prints out the contents of the ring buffer for the
+  CPU that executed the function that triggered the dump.
+
 trace_pipe
 ----------
 

1.7.10.4

From: Harsh Prateek Bora <[email protected]>

Consolidate the checks for !enabled and !param to return -EINVAL in event_enable_func().

---
 kernel/trace/trace_events.c |    5 +----
 1 file changed, 1 insertion(+), 4 deletions(-)

index 27963e2..db086f1 100644
@@ -2011,10 +2011,7 @@ event_enable_func(struct ftrace_hash *hash,
 	int ret;
 
 	/* hash funcs only work with set_ftrace_filter */
-	if (!enabled)
-		return -EINVAL;
-
-	if (!param)
+	if (!enabled || !param)
 		return -EINVAL;
 
 	system = strsep(&param, ":");

1.7.10.4

From: Wang YanQing <[email protected]>

Commit 4f271a2a60c748599b30bb4dafff30d770439b96 (tracing: Add a proc file to stop tracing and free buffer) implement a method to free up ring buffer in kernel memory in the release code path of free_buffer's fd.

Then we don't need read/write support for free_buffer, indeed we just have a dummy write fop, and don't implement read fop.

So the 0200 is more reasonable file mode for free_buffer than the current file mode 0644.

---
 kernel/trace/trace.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 1a41023..5f4a09c 100644
@@ -5935,7 +5935,7 @@ init_tracer_debugfs(struct trace_array *tr, struct dentry *d_tracer)
 	trace_create_file("buffer_total_size_kb", 0444, d_tracer,
 			  tr, &tracing_total_entries_fops);
 
-	trace_create_file("free_buffer", 0644, d_tracer,
+	trace_create_file("free_buffer", 0200, d_tracer,
 			  tr, &tracing_free_buffer_fops);
 
 	trace_create_file("trace_marker", 0220, d_tracer,

1.7.10.4

From: Steven Rostedt <[email protected]>

The function tracer uses preempt_disable/enable_notrace() for synchronization between reading registered ftrace_ops and unregistering them.

Most of the ftrace_ops are global permanent structures that do not require this synchronization. That is, ops may be added and removed from the hlist but are never freed, and wont hurt if a synchronization is missed.

But this is not true for dynamically created ftrace_ops or control_ops, which are used by the perf function tracing.

The problem here is that the function tracer can be used to trace kernel/user context switches as well as going to and from idle. Basically, it can be used to trace blind spots of the RCU subsystem. This means that even though preempt_disable() is done, a synchronize_sched() will ignore CPUs that haven't made it out of user space or idle. These can include functions that are being traced just before entering or exiting the kernel sections.

To implement the RCU synchronization, instead of using synchronize_sched() the use of schedule_on_each_cpu() is performed. This means that when a dynamically allocated ftrace_ops, or a control ops is being unregistered, all CPUs must be touched and execute a ftrace_sync() stub function via the work queues. This will rip CPUs out from idle or in dynamic tick mode. This only happens when a user disables perf function tracing or other dynamically allocated function tracers, but it allows us to continue to debug RCU and context tracking with function tracing.

---
 kernel/trace/ftrace.c |   23 +++++++++++++++++++++--
 1 file changed, 21 insertions(+), 2 deletions(-)

index 6c508ff..800a8a2 100644
@@ -413,6 +413,17 @@ static int __register_ftrace_function(struct ftrace_ops *ops)
 	return 0;
 }
 
+static void ftrace_sync(struct work_struct *work)
+{
+	/*
+	 * This function is just a stub to implement a hard force
+	 * of synchronize_sched(). This requires synchronizing
+	 * tasks even in userspace and idle.
+	 *
+	 * Yes, function tracing is rude.
+	 */
+}
+
 static int __unregister_ftrace_function(struct ftrace_ops *ops)
 {
 	int ret;

@@ -440,8 +451,12 @@ static int __unregister_ftrace_function(struct ftrace_ops *ops)
 			 * so there'll be no new users. We must ensure
 			 * all current users are done before we free
 			 * the control data.
+			 * Note synchronize_sched() is not enough, as we
+			 * use preempt_disable() to do RCU, but the function
+			 * tracer can be called where RCU is not active
+			 * (before user_exit()).
 			 */
-			synchronize_sched();
+			schedule_on_each_cpu(ftrace_sync);
 			control_ops_free(ops);
 		}
 	} else

@@ -456,9 +471,13 @@ static int __unregister_ftrace_function(struct ftrace_ops *ops)
 	/*
 	 * Dynamic ops may be freed, we must make sure that all
 	 * callers are done before leaving this function.
+	 *
+	 * Again, normal synchronize_sched() is not good enough.
+	 * We need to do a hard force of sched synchronization.
 	 */
 	if (ops->flags & FTRACE_OPS_FL_DYNAMIC)
-		synchronize_sched();
+		schedule_on_each_cpu(ftrace_sync);
+
 
 	return 0;
 }

1.7.10.4

From: Li Zefan <[email protected]>

This is a leftover after ftrace_regex_lseek() was renamed to ftrace_filter_lseek() and then ftrace_filter_lseek() was moved out side of CONFIG_DYNAMIC_FTRACE.

---
 include/linux/ftrace.h |    4 ----
 1 file changed, 4 deletions(-)

index 99d0fbc..e48ed1d 100644
@@ -566,10 +566,6 @@ static inline ssize_t ftrace_filter_write(struct file *file, const char __user *
 			    size_t cnt, loff_t *ppos) { return -ENODEV; }
 static inline ssize_t ftrace_notrace_write(struct file *file, const char __user *ubuf,
 			     size_t cnt, loff_t *ppos) { return -ENODEV; }
-static inline loff_t ftrace_regex_lseek(struct file *file, loff_t offset, int whence)
-{
-	return -ENODEV;
-}
 static inline int
 ftrace_regex_release(struct inode *inode, struct file *file) { return -ENODEV; }
 #endif /* CONFIG_DYNAMIC_FTRACE */

1.7.10.4

From: Namhyung Kim <[email protected]>

There's no point calling it when _alloc() failed.

---
 kernel/trace/trace_events.c |    7 +------
 1 file changed, 1 insertion(+), 6 deletions(-)

index db086f1..f57b015 100644
@@ -97,7 +97,7 @@ static int __trace_define_field(struct list_head *head, const char *type,
 
 	field = kmem_cache_alloc(field_cachep, GFP_TRACE);
 	if (!field)
-		goto err;
+		return -ENOMEM;
 
 	field->name = name;
 	field->type = type;

@@ -114,11 +114,6 @@ static int __trace_define_field(struct list_head *head, const char *type,
 	list_add(&field->link, head);
 
 	return 0;
-
-err:
-	kmem_cache_free(field_cachep, field);
-
-	return -ENOMEM;
 }
 
 int trace_define_field(struct ftrace_event_call *call, const char *type,

1.7.10.4

From: Steven Rostedt <[email protected]>

There are some cases when filtering on a set flag of a field of a tracepoint is useful. But currently the only filtering commands for numbered fields is ==, !=, <, <=, >, >=. This does not help when you just want to trace if a specific flag is set. For example:

When trying to trace brcmf_dbg when level has its 1 << 18 bit set, the filter fails to perform.

By allowing a binary '&' operation, this gives the user the ability to test a bit.

Note, a binary '|' is not added, as it doesn't make sense as fields must be compared to constants (for now), and ORing a constant will always return true.

---
 Documentation/trace/events.txt     |    2 +-
 kernel/trace/trace_events_filter.c |    6 ++++++
 2 files changed, 7 insertions(+), 1 deletion(-)

index bb24c2a..4191124 100644
@@ -183,7 +183,7 @@ The relational-operators depend on the type of the field being tested:
 
 The operators available for numeric fields are:
 
-==, !=, <, <=, >, >=
+==, !=, <, <=, >, >=, &
 
 And for string fields they are:
 

index e1b653f..0d883dc 100644
@@ -44,6 +44,7 @@ enum filter_op_ids
 	OP_LE,
 	OP_GT,
 	OP_GE,
+	OP_BAND,
 	OP_NONE,
 	OP_OPEN_PAREN,
 };

@@ -54,6 +55,7 @@ struct filter_op {
 	int precedence;
 };
 
+/* Order must be the same as enum filter_op_ids above */
 static struct filter_op filter_ops[] = {
 	{ OP_OR,	"||",		1 },
 	{ OP_AND,	"&&",		2 },

@@ -64,6 +66,7 @@ static struct filter_op filter_ops[] = {
 	{ OP_LE,	"<=",		5 },
 	{ OP_GT,	">",		5 },
 	{ OP_GE,	">=",		5 },
+	{ OP_BAND,	"&",		6 },
 	{ OP_NONE,	"OP_NONE",	0 },
 	{ OP_OPEN_PAREN, "(",		0 },
 };

@@ -156,6 +159,9 @@ static int filter_pred_##type(struct filter_pred *pred, void *event)	\
 	case OP_GE:							\
 		match = (*addr >= val);					\
 		break;							\
+	case OP_BAND:							\
+		match = (*addr & val);					\
+		break;							\
 	default:							\
 		break;							\
 	}								\

1.7.10.4

Actually, my attempt was triggered by the trace-cmd manual page:

"-f filter
Specify a filter for the previous event. This must come after a -e. This will filter what events get recorded based on the content of the event. Filtering is passed to the kernel directly so what filtering is allowed may depend on what version of the kernel you have. Basically, it will let you use C notation to check if an event should be processed or not.

==, >=, <=, >, <, &, |, && and ||

The above are usually safe to use to compare fields."

Regards,
Arend

Ah thanks. That needs to be updated. Not sure why I wrote all of them. Perhaps because the report side handles them and I just assumed the kernel did too.

-- Steve

Reading the whole text with your remark in mind, I guess it does indicate there are no guarantees depending on the kernel and the list of operators are what trace-cmd supports. I overlooked/ignored the text seeing the operators.

Regards,
Arend

Exactly, which means that if you over looked the text, so has others. The text
should be changed to make it more comprehensible.

I also have a lot of other trace-cmd changes that I have not yet pushed to my git repo. I'm just not comfortable with the changes quite yet. And it's blocking some changes that I have no issue with. Hmm, I should just rebase and push, but I'm using this as motivation to get those changes tested enough ;-)

Thanks,

-- Steve

Would this change have helped you catch this?

index b95e1b4..9ef1e2a 100644
@@ -79,10 +79,12 @@ OPTIONS
     let you use C notation to check if an event should be processed or not.
 
 ----------------------------------------
-    ==, >=, <=, >, <, &, |, && and ||
+    ==, >=, <=, >, <, &, ~, && and ||
 ----------------------------------------
 
-    The above are usually safe to use to compare fields.
+    Note, not all of the above operators may work with all kernels.
+    The filter is passed directly to the kernel and is dependent on the
+    kernel supporting the operators.
 
 *-v*::
     This will cause all events specified after it on the command line to not

-- Steve

Always difficult to say in retrospect, but it certainly is more clear.

Regards,
Arend

From: "Steven Rostedt (Red Hat)" <[email protected]>

b0f1a59a "tracing/filters: Use a different op for glob match" added glob matching to tracepoint filter strings. It uses the ftrace function tracing glob matching facility that allows for the wild card character (*) to be used at the start and/or end of the matching string.

But the documentation still states that the filtering only allows for exact string matches.

---
 Documentation/trace/events.txt |   13 +++++++++++--
 1 file changed, 11 insertions(+), 2 deletions(-)

index 4191124..37732a2 100644
@@ -187,9 +187,18 @@ The operators available for numeric fields are:
 
 And for string fields they are:
 
-==, !=
+==, !=, ~
 
-Currently, only exact string matches are supported.
+The glob (~) only accepts a wild card character (*) at the start and or
+end of the string. For example:
+
+  prev_comm ~ "*sh"
+  prev_comm ~ "sh*"
+  prev_comm ~ "*sh*"
+
+But does not allow for it to be within the string:
+
+  prev_comm ~ "ba*sh"   <-- is invalid
 
 5.2 Setting filters
 -------------------

1.7.10.4

From: "Steven Rostedt (Red Hat)" <[email protected]>

Add a traceoff_on_warning option in both the kernel command line as well as a sysctl option. When set, any WARN*() function that is hit will cause the tracing_on variable to be cleared, which disables writing to the ring buffer.

This is useful especially when tracing a bug with function tracing. When a warning is hit, the print caused by the warning can flood the trace with the functions that producing the output for the warning. This can make the resulting trace useless by either hiding where the bug happened, or worse, by overflowing the buffer and losing the trace of the bug totally.

---
 Documentation/kernel-parameters.txt |   13 +++++++++++++
 include/linux/ftrace.h              |    5 +++++
 kernel/panic.c                      |    3 +++
 kernel/sysctl.c                     |    7 +++++++
 kernel/trace/trace.c                |   17 +++++++++++++++++
 5 files changed, 45 insertions(+)

index 6e3b18a..729d0b9 100644
@@ -3069,6 +3069,19 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
 			See also Documentation/trace/ftrace.txt "trace options"
 			section.
 
+	traceoff_on_warning
+			[FTRACE] enable this option to disable tracing when a
+			warning is hit. This turns off "tracing_on". Tracing can
+			be enabled again by echoing '1' into the "tracing_on"
+			file located in /sys/kernel/debug/tracing/
+
+			This option is useful, as it disables the trace before
+			the WARNING dump is called, which prevents the trace to
+			be filled with content caused by the warning output.
+
+			This option can also be set at run time via the sysctl
+			option:  kernel/traceoff_on_warning
+
 	transparent_hugepage=
 			[KNL]
 			Format: [always|madvise|never]

index e48ed1d..9f15c00 100644
@@ -824,10 +824,15 @@ enum ftrace_dump_mode;
 
 extern enum ftrace_dump_mode ftrace_dump_on_oops;
 
+extern void disable_trace_on_warning(void);
+extern int __disable_trace_on_warning;
+
 #ifdef CONFIG_PREEMPT
 #define INIT_TRACE_RECURSION		.trace_recursion = 0,
 #endif
 
+#else /* CONFIG_TRACING */
+static inline void  disable_trace_on_warning(void) { }
 #endif /* CONFIG_TRACING */
 
 #ifndef INIT_TRACE_RECURSION

index 167ec09..4cea6cc 100644
@@ -15,6 +15,7 @@
 #include <linux/notifier.h>
 #include <linux/module.h>
 #include <linux/random.h>
+#include <linux/ftrace.h>
 #include <linux/reboot.h>
 #include <linux/delay.h>
 #include <linux/kexec.h>

@@ -399,6 +400,8 @@ struct slowpath_args {
 static void warn_slowpath_common(const char *file, int line, void *caller,
 				 unsigned taint, struct slowpath_args *args)
 {
+	disable_trace_on_warning();
+
 	printk(KERN_WARNING "------------[ cut here ]------------\n");
 	printk(KERN_WARNING "WARNING: at %s:%d %pS()\n", file, line, caller);
 

index 9edcf45..5b0f18c 100644
@@ -600,6 +600,13 @@ static struct ctl_table kern_table[] = {
 		.mode		= 0644,
 		.proc_handler	= proc_dointvec,
 	},
+	{
+		.procname	= "traceoff_on_warning",
+		.data		= &__disable_trace_on_warning,
+		.maxlen		= sizeof(__disable_trace_on_warning),
+		.mode		= 0644,
+		.proc_handler	= proc_dointvec,
+	},
 #endif
 #ifdef CONFIG_MODULES
 	{

index 5f4a09c..c4c9296 100644
@@ -115,6 +115,9 @@ cpumask_var_t __read_mostly	tracing_buffer_mask;
 
 enum ftrace_dump_mode ftrace_dump_on_oops;
 
+/* When set, tracing will stop when a WARN*() is hit */
+int __disable_trace_on_warning;
+
 static int tracing_set_tracer(const char *buf);
 
 #define MAX_TRACER_SIZE		100

@@ -149,6 +152,13 @@ static int __init set_ftrace_dump_on_oops(char *str)
 }
 __setup("ftrace_dump_on_oops", set_ftrace_dump_on_oops);
 
+static int __init stop_trace_on_warning(char *str)
+{
+	__disable_trace_on_warning = 1;
+	return 1;
+}
+__setup("traceoff_on_warning=", stop_trace_on_warning);
+
 static int __init boot_alloc_snapshot(char *str)
 {
 	allocate_snapshot = true;

@@ -170,6 +180,7 @@ static int __init set_trace_boot_options(char *str)
 }
 __setup("trace_options=", set_trace_boot_options);
 
+
 unsigned long long ns2usecs(cycle_t nsec)
 {
 	nsec += 500;

@@ -562,6 +573,12 @@ void tracing_off(void)
 }
 EXPORT_SYMBOL_GPL(tracing_off);
 
+void disable_trace_on_warning(void)
+{
+	if (__disable_trace_on_warning)
+		tracing_off();
+}
+
 /**
  * tracing_is_on - show state of ring buffers enabled
  */

1.7.10.4

From: "zhangwei(Jovi)" <[email protected]>

Since tp->flags assignment was moved into function enable_trace_probe(), there is no need to use trace_probe_is_enabled to check flags in the same function.

Remove the unnecessary checking.

---
 kernel/trace/trace_kprobe.c |    3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

index 9f46e98..f237417 100644
@@ -240,8 +240,7 @@ enable_trace_probe(struct trace_probe *tp, struct ftrace_event_file *file)
 	} else
 		tp->flags |= TP_FLAG_PROFILE;
 
-	if (trace_probe_is_enabled(tp) && trace_probe_is_registered(tp) &&
-	    !trace_probe_has_gone(tp)) {
+	if (trace_probe_is_registered(tp) && !trace_probe_has_gone(tp)) {
 		if (trace_probe_is_return(tp))
 			ret = enable_kretprobe(&tp->rp);
 		else

1.7.10.4

From: Juri Lelli <[email protected]>

When FUNCTION_GRAPH_TRACER is enabled, ftrace can profile kernel functions and print basic statistics about them. Unfortunately, running stddev calculation is wrong. This patch corrects it implementing Welford’s method:

        s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2) .

---
 kernel/trace/ftrace.c |   10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

index 800a8a2..26e1910 100644
@@ -641,12 +641,18 @@ static int function_stat_show(struct seq_file *m, void *v)
 	if (rec->counter <= 1)
 		stddev = 0;
 	else {
-		stddev = rec->time_squared - rec->counter * avg * avg;
+		/*
+		 * Apply Welford's method:
+		 * s^2 = 1 / (n * (n-1)) * (n * \Sum (x_i)^2 - (\Sum x_i)^2)
+		 */
+		stddev = rec->counter * rec->time_squared -
+			 rec->time * rec->time;
+
 		/*
 		 * Divide only 1000 for ns^2 -> us^2 conversion.
 		 * trace_print_graph_duration will divide 1000 again.
 		 */
-		do_div(stddev, (rec->counter - 1) * 1000);
+		do_div(stddev, rec->counter * (rec->counter - 1) * 1000);
 	}
 
 	trace_seq_init(&s);

1.7.10.4