Skip to contentSkip to conversation

tracing: queued up stuff waiting for k.org to come back on line

GIT PULL In review Steven Rostedt 2 participants 34 messages Sep 22, 2011 – Sep 23, 2011

Subsystems (7)
Documentation x86 Tracing Module support +3 more subsystems
lore
Share & tools
lore

Steven Rostedt

author maintainer
#0 lore raw

Ingo,

I've had lots of these patches for a while now and was holding off till kernel.org became back on line. But that is taking much longer than I expected, and the patches are starting to build up even though I've been working more on -rt lately. I may start working on mainline again soon so need to get rid of the queue I currently have.

Sorry for the big patch set, but it is really more a bunch of smaller patch sets that have accumulated.

I bit the bullet and created a github account. You can pull from that for now.

Thanks!

-- Steve

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

git://github.com/rostedt/linux.git
tip/perf/core

Head SHA1: 963616e48ea9cf58a1c3217457612cfa2be70b2c

Jiri Olsa (10):
tracing/filter: Use static allocation for filter predicates tracing/filter: Separate predicate init and filter addition tracing/filter: Remove field_name from filter_pred struct tracing/filter: Simplify tracepoint event lookup
tracing/filter: Unify predicate tree walking, change check_pred_tree function to use it tracing/filter: Change count_leafs function to use walk_pred_tree tracing/filter: Change fold_pred_tree function to use walk_pred_tree tracing/filter: Change fold_pred function to use walk_pred_tree tracing/filter: Change filter_match_preds function to use walk_pred_tree tracing/filter: Add startup tests for events filter

Kevin Winchester (1):
x86: jump_label: arch_jump_label_text_poke_early: add missing __init

Mathieu Desnoyers (1):
Tracepoint: Dissociate from module mutex

Steven Rostedt (7):
tracing: Clean up tb_fmt to not give faulty compile warning
tracing: Add preempt disable for filter self test
tracing: Add a counter clock for those that do not trust clocks
tracing: Fix preemptirqsoff tracer to not stop at preempt off
tracing: Account for preempt off in preempt_schedule()
tracing: Do not allocate buffer for trace_marker
tracing: Add optional percpu buffers for trace_printk()

Vaibhav Nagarnaik (2):
trace: Add a new readonly entry to report total buffer size
trace: Add ring buffer stats to measure rate of events

----

 Documentation/kernel-parameters.txt     |   11 +
 arch/x86/kernel/jump_label.c            |    2 +-
 include/linux/module.h                  |   12 -
 include/linux/ring_buffer.h             |    2 +
 include/linux/trace_clock.h             |    1 +
 include/linux/tracepoint.h              |   25 +-
 kernel/module.c                         |   47 --
 kernel/sched.c                          |    9 +
 kernel/trace/Makefile                   |    2 +
 kernel/trace/ring_buffer.c              |   70 +++-
 kernel/trace/trace.c                    |  183 ++++++-
 kernel/trace/trace.h                    |   15 +-
 kernel/trace/trace_clock.c              |   12 +
 kernel/trace/trace_events_filter.c      |  795 ++++++++++++++++++-------------
 kernel/trace/trace_events_filter_test.h |   50 ++
 kernel/trace/trace_irqsoff.c            |    4 +-
 kernel/trace/trace_printk.c             |   19 +-
 kernel/tracepoint.c                     |  169 ++++++-
 18 files changed, 953 insertions(+), 475 deletions(-)
author maintainer
#1 lore raw

PATCH 1/21 tracing: Clean up tb_fmt to not give faulty compile warning

From: Steven Rostedt <[email protected]>

gcc incorrectly states that the variable "fmt" is uninitialized when CC_OPITMIZE_FOR_SIZE is set.

Instead of just blindly setting fmt to NULL, the code is cleaned up a little to be a bit easier for humans to follow, as well as gcc to know the variables are initialized.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_printk.c |   19 ++++++++++---------
 1 files changed, 10 insertions(+), 9 deletions(-)
kernel/trace/trace_printk.c +10 -9
index 1f06468..6fd4ffd 100644
@@ -59,18 +59,19 @@ void hold_module_trace_bprintk_format(const char **start, const char **end)
 			continue;
 		}
 
+		fmt = NULL;
 		tb_fmt = kmalloc(sizeof(*tb_fmt), GFP_KERNEL);
-		if (tb_fmt)
+		if (tb_fmt) {
 			fmt = kmalloc(strlen(*iter) + 1, GFP_KERNEL);
-		if (tb_fmt && fmt) {
-			list_add_tail(&tb_fmt->list, &trace_bprintk_fmt_list);
-			strcpy(fmt, *iter);
-			tb_fmt->fmt = fmt;
-			*iter = tb_fmt->fmt;
-		} else {
-			kfree(tb_fmt);
-			*iter = NULL;
+			if (fmt) {
+				list_add_tail(&tb_fmt->list, &trace_bprintk_fmt_list);
+				strcpy(fmt, *iter);
+				tb_fmt->fmt = fmt;
+			} else
+				kfree(tb_fmt);
 		}
+		*iter = fmt;
+
 	}
 	mutex_unlock(&btrace_mutex);
 }
Signature · 1 line
1.7.5.4
author maintainer
#2 lore raw

PATCH 2/21 Tracepoint: Dissociate from module mutex

In reply to Steven Rostedt

From: Mathieu Desnoyers <[email protected]>

Copy the information needed from struct module into a local module list held within tracepoint.c from within the module coming/going notifier.

This vastly simplifies locking of tracepoint registration / unregistration, because we don't have to take the module mutex to register and unregister tracepoints anymore. Steven Rostedt ran into dependency problems related to modules mutex vs kprobes mutex vs ftrace mutex vs tracepoint mutex that seems to be hard to fix without removing this dependency between tracepoint and module mutex. (note: it should be investigated whether kprobes could benefit of being dissociated from the modules mutex too.)

This also fixes module handling of tracepoint list iterators, because it was expecting the list to be sorted by pointer address. Given we have control on our own list now, it's OK to sort this list which has tracepoints as its only purpose. The reason why this sorting is required is to handle the fact that seq files (and any read() operation from user-space) cannot hold the tracepoint mutex across multiple calls, so list entries may vanish between calls. With sorting, the tracepoint iterator becomes usable even if the list don't contain the exact item pointed to by the iterator anymore.

Signed-off-by Mathieu Desnoyers <[email protected]>
Acked-by Jason Baron <[email protected]>
CC Ingo Molnar <[email protected]>
CC Lai Jiangshan <[email protected]>
CC Peter Zijlstra <[email protected]>
CC Thomas Gleixner <[email protected]>
CC Masami Hiramatsu <[email protected]>
Link http://lkml.kernel.org/r/20110810191839.GC8525@Krystal open here
Signed-off-by Steven Rostedt <[email protected]>
---
 include/linux/module.h     |   12 ---
 include/linux/tracepoint.h |   25 +++----
 kernel/module.c            |   47 ------------
 kernel/tracepoint.c        |  169 ++++++++++++++++++++++++++++++++++++++------
 4 files changed, 158 insertions(+), 95 deletions(-)
include/linux/module.h +0 -12
index 1c30087..8639216 100644
@@ -580,9 +580,6 @@ int unregister_module_notifier(struct notifier_block * nb);
 
 extern void print_modules(void);
 
-extern void module_update_tracepoints(void);
-extern int module_get_iter_tracepoints(struct tracepoint_iter *iter);
-
 #else /* !CONFIG_MODULES... */
 #define EXPORT_SYMBOL(sym)
 #define EXPORT_SYMBOL_GPL(sym)

@@ -698,15 +695,6 @@ static inline int unregister_module_notifier(struct notifier_block * nb)
 static inline void print_modules(void)
 {
 }
-
-static inline void module_update_tracepoints(void)
-{
-}
-
-static inline int module_get_iter_tracepoints(struct tracepoint_iter *iter)
-{
-	return 0;
-}
 #endif /* CONFIG_MODULES */
 
 #ifdef CONFIG_SYSFS
include/linux/tracepoint.h +11 -14
index d530a44..df0a779 100644
@@ -54,8 +54,18 @@ extern int tracepoint_probe_unregister_noupdate(const char *name, void *probe,
 						void *data);
 extern void tracepoint_probe_update_all(void);
 
+#ifdef CONFIG_MODULES
+struct tp_module {
+	struct list_head list;
+	unsigned int num_tracepoints;
+	struct tracepoint * const *tracepoints_ptrs;
+};
+#endif /* CONFIG_MODULES */
+
 struct tracepoint_iter {
-	struct module *module;
+#ifdef CONFIG_MODULES
+	struct tp_module *module;
+#endif /* CONFIG_MODULES */
 	struct tracepoint * const *tracepoint;
 };
 

@@ -63,8 +73,6 @@ extern void tracepoint_iter_start(struct tracepoint_iter *iter);
 extern void tracepoint_iter_next(struct tracepoint_iter *iter);
 extern void tracepoint_iter_stop(struct tracepoint_iter *iter);
 extern void tracepoint_iter_reset(struct tracepoint_iter *iter);
-extern int tracepoint_get_iter_range(struct tracepoint * const **tracepoint,
-	struct tracepoint * const *begin, struct tracepoint * const *end);
 
 /*
  * tracepoint_synchronize_unregister must be called between the last tracepoint

@@ -78,17 +86,6 @@ static inline void tracepoint_synchronize_unregister(void)
 
 #define PARAMS(args...) args
 
-#ifdef CONFIG_TRACEPOINTS
-extern
-void tracepoint_update_probe_range(struct tracepoint * const *begin,
-	struct tracepoint * const *end);
-#else
-static inline
-void tracepoint_update_probe_range(struct tracepoint * const *begin,
-	struct tracepoint * const *end)
-{ }
-#endif /* CONFIG_TRACEPOINTS */
-
 #endif /* _LINUX_TRACEPOINT_H */
 
 /*
kernel/module.c +0 -47

50 lines not on this page · raw message

kernel/tracepoint.c +147 -22

279 lines not on this page · raw message

Signature · 1 line
1.7.5.4
author maintainer
#3 lore raw

PATCH 3/21 x86: jump_label: arch_jump_label_text_poke_early: add missing __init

In reply to Steven Rostedt

From: Kevin Winchester <[email protected]>

arch_jump_label_text_poke_early calls text_poke_early, which is an __init function. Thus arch_jump_label_text_poke_early should be the same.

Signed-off-by Kevin Winchester <[email protected]>
Cc [email protected]
Cc [email protected]
Cc [email protected]
Cc [email protected]
Cc [email protected]
Link http://lkml.kernel.org/r/[email protected] open here

[ Use __init_or_module instead of __init ]

Signed-off-by Steven Rostedt <[email protected]>
---
 arch/x86/kernel/jump_label.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)
arch/x86/kernel/jump_label.c +1 -1
index 3fee346..cacdd46 100644
@@ -42,7 +42,7 @@ void arch_jump_label_transform(struct jump_entry *entry,
 	put_online_cpus();
 }
 
-void arch_jump_label_text_poke_early(jump_label_t addr)
+void __init_or_module arch_jump_label_text_poke_early(jump_label_t addr)
 {
 	text_poke_early((void *)addr, ideal_nops[NOP_ATOMIC5],
 			JUMP_LABEL_NOP_SIZE);
Signature · 1 line
1.7.5.4
author maintainer
#4 lore raw

PATCH 4/21 tracing/filter: Use static allocation for filter predicates

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Don't dynamically allocate filter_pred struct, use static memory. This way we can get rid of the code managing the dynamic filter_pred struct object.

The create_pred function integrates create_logical_pred function. This way the static predicate memory is returned only from one place.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |   57 ++++++++++--------------------------
 1 files changed, 16 insertions(+), 41 deletions(-)
kernel/trace/trace_events_filter.c +16 -41
index 256764e..cb295a1 100644
@@ -630,11 +630,7 @@ find_event_field(struct ftrace_event_call *call, char *name)
 
 static void filter_free_pred(struct filter_pred *pred)
 {
-	if (!pred)
-		return;
-
 	kfree(pred->field_name);
-	kfree(pred);
 }
 
 static void filter_clear_pred(struct filter_pred *pred)

@@ -1302,39 +1298,30 @@ parse_operand:
 	return 0;
 }
 
-static struct filter_pred *create_pred(int op, char *operand1, char *operand2)
+static struct filter_pred *create_pred(struct filter_parse_state *ps,
+				       int op, char *operand1, char *operand2)
 {
-	struct filter_pred *pred;
+	static struct filter_pred pred;
 
-	pred = kzalloc(sizeof(*pred), GFP_KERNEL);
-	if (!pred)
-		return NULL;
+	memset(&pred, 0, sizeof(pred));
+	pred.op = op;
 
-	pred->field_name = kstrdup(operand1, GFP_KERNEL);
-	if (!pred->field_name) {
-		kfree(pred);
+	if (op == OP_AND || op == OP_OR)
+		return &pred;
+
+	if (!operand1 || !operand2) {
+		parse_error(ps, FILT_ERR_MISSING_FIELD, 0);
 		return NULL;
 	}
 
-	strcpy(pred->regex.pattern, operand2);
-	pred->regex.len = strlen(pred->regex.pattern);
-
-	pred->op = op;
-
-	return pred;
-}
-
-static struct filter_pred *create_logical_pred(int op)
-{
-	struct filter_pred *pred;
-
-	pred = kzalloc(sizeof(*pred), GFP_KERNEL);
-	if (!pred)
+	pred.field_name = kstrdup(operand1, GFP_KERNEL);
+	if (!pred.field_name)
 		return NULL;
 
-	pred->op = op;
+	strcpy(pred.regex.pattern, operand2);
+	pred.regex.len = strlen(pred.regex.pattern);
 
-	return pred;
+	return &pred;
 }
 
 static int check_preds(struct filter_parse_state *ps)

@@ -1643,19 +1630,7 @@ static int replace_preds(struct ftrace_event_call *call,
 			goto fail;
 		}
 
-		if (elt->op == OP_AND || elt->op == OP_OR) {
-			pred = create_logical_pred(elt->op);
-			goto add_pred;
-		}
-
-		if (!operand1 || !operand2) {
-			parse_error(ps, FILT_ERR_MISSING_FIELD, 0);
-			err = -EINVAL;
-			goto fail;
-		}
-
-		pred = create_pred(elt->op, operand1, operand2);
-add_pred:
+		pred = create_pred(ps, elt->op, operand1, operand2);
 		if (!pred) {
 			err = -ENOMEM;
 			goto fail;
Signature · 1 line
1.7.5.4
author maintainer
#5 lore raw

PATCH 5/21 tracing/filter: Separate predicate init and filter addition

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Making the code cleaner by having one function to fully prepare the predicate (create_pred), and another to add the predicate to the filter (filter_add_pred).

As a benefit, this way the dry_run flag stays only inside the replace_preds function and is not passed deeper.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |   56 +++++++++++++++---------------------
 1 files changed, 23 insertions(+), 33 deletions(-)
kernel/trace/trace_events_filter.c +23 -33
index cb295a1..61c8dec 100644
@@ -685,8 +685,7 @@ __pop_pred_stack(struct pred_stack *stack)
 static int filter_set_pred(struct event_filter *filter,
 			   int idx,
 			   struct pred_stack *stack,
-			   struct filter_pred *src,
-			   filter_pred_fn_t fn)
+			   struct filter_pred *src)
 {
 	struct filter_pred *dest = &filter->preds[idx];
 	struct filter_pred *left;

@@ -698,7 +697,6 @@ static int filter_set_pred(struct event_filter *filter,
 		if (!dest->field_name)
 			return -ENOMEM;
 	}
-	dest->fn = fn;
 	dest->index = idx;
 
 	if (dest->op == OP_OR || dest->op == OP_AND) {

@@ -836,12 +834,10 @@ static void filter_free_subsystem_filters(struct event_subsystem *system)
 	}
 }
 
-static int filter_add_pred_fn(struct filter_parse_state *ps,
-			      struct ftrace_event_call *call,
-			      struct event_filter *filter,
-			      struct filter_pred *pred,
-			      struct pred_stack *stack,
-			      filter_pred_fn_t fn)
+static int filter_add_pred(struct filter_parse_state *ps,
+			   struct event_filter *filter,
+			   struct filter_pred *pred,
+			   struct pred_stack *stack)
 {
 	int idx, err;
 

@@ -852,7 +848,7 @@ static int filter_add_pred_fn(struct filter_parse_state *ps,
 
 	idx = filter->n_preds;
 	filter_clear_pred(&filter->preds[idx]);
-	err = filter_set_pred(filter, idx, stack, pred, fn);
+	err = filter_set_pred(filter, idx, stack, pred);
 	if (err)
 		return err;
 

@@ -933,25 +929,16 @@ static filter_pred_fn_t select_comparison_fn(int op, int field_size,
 	return fn;
 }
 
-static int filter_add_pred(struct filter_parse_state *ps,
-			   struct ftrace_event_call *call,
-			   struct event_filter *filter,
-			   struct filter_pred *pred,
-			   struct pred_stack *stack,
-			   bool dry_run)
+static int init_pred(struct filter_parse_state *ps,
+		     struct ftrace_event_call *call,
+		     struct filter_pred *pred)
+
 {
 	struct ftrace_event_field *field;
-	filter_pred_fn_t fn;
+	filter_pred_fn_t fn = filter_pred_none;
 	unsigned long long val;
 	int ret;
 
-	fn = pred->fn = filter_pred_none;
-
-	if (pred->op == OP_AND)
-		goto add_pred_fn;
-	else if (pred->op == OP_OR)
-		goto add_pred_fn;
-
 	field = find_event_field(call, pred->field_name);
 	if (!field) {
 		parse_error(ps, FILT_ERR_FIELD_NOT_FOUND, 0);

@@ -997,9 +984,7 @@ static int filter_add_pred(struct filter_parse_state *ps,
 	if (pred->op == OP_NE)
 		pred->not = 1;
 
-add_pred_fn:
-	if (!dry_run)
-		return filter_add_pred_fn(ps, call, filter, pred, stack, fn);
+	pred->fn = fn;
 	return 0;
 }
 

@@ -1299,6 +1284,7 @@ parse_operand:
 }
 
 static struct filter_pred *create_pred(struct filter_parse_state *ps,
+				       struct ftrace_event_call *call,
 				       int op, char *operand1, char *operand2)
 {
 	static struct filter_pred pred;

@@ -1321,7 +1307,7 @@ static struct filter_pred *create_pred(struct filter_parse_state *ps,
 	strcpy(pred.regex.pattern, operand2);
 	pred.regex.len = strlen(pred.regex.pattern);
 
-	return &pred;
+	return init_pred(ps, call, &pred) ? NULL : &pred;
 }
 
 static int check_preds(struct filter_parse_state *ps)

@@ -1630,16 +1616,20 @@ static int replace_preds(struct ftrace_event_call *call,
 			goto fail;
 		}
 
-		pred = create_pred(ps, elt->op, operand1, operand2);
+		pred = create_pred(ps, call, elt->op, operand1, operand2);
 		if (!pred) {
 			err = -ENOMEM;
 			goto fail;
 		}
-		err = filter_add_pred(ps, call, filter, pred, &stack, dry_run);
-		filter_free_pred(pred);
-		if (err)
-			goto fail;
+		if (!dry_run) {
+			err = filter_add_pred(ps, filter, pred, &stack);
+			if (err) {
+				filter_free_pred(pred);
+				goto fail;
+			}
+		}
 
+		filter_free_pred(pred);
 		operand1 = operand2 = NULL;
 	}
Signature · 1 line
1.7.5.4
author maintainer
#6 lore raw

PATCH 6/21 tracing/filter: Remove field_name from filter_pred struct

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

The field_name was used just for finding event's fields. This way we don't need to care about field_name allocation/free.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace.h               |   11 +-------
 kernel/trace/trace_events_filter.c |   53 ++++++++---------------------------
 2 files changed, 13 insertions(+), 51 deletions(-)
kernel/trace/trace.h +1 -10
index 616846b..2eb3cf6 100644
@@ -761,16 +761,7 @@ struct filter_pred {
 	filter_pred_fn_t 	fn;
 	u64 			val;
 	struct regex		regex;
-	/*
-	 * Leaf nodes use field_name, ops is used by AND and OR
-	 * nodes. The field_name is always freed when freeing a pred.
-	 * We can overload field_name for ops and have it freed
-	 * as well.
-	 */
-	union {
-		char		*field_name;
-		unsigned short	*ops;
-	};
+	unsigned short		*ops;
 	int 			offset;
 	int 			not;
 	int 			op;
kernel/trace/trace_events_filter.c +12 -41

127 lines not on this page · raw message

Signature · 1 line
1.7.5.4
author maintainer
#7 lore raw

PATCH 7/21 tracing/filter: Simplify tracepoint event lookup

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

We dont need to perform lookup through the ftrace_events list, instead we can use the 'tp_event' field.

Each perf_event contains tracepoint event field 'tp_event', which got initialized during the tracepoint event initialization.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |    9 +++------
 1 files changed, 3 insertions(+), 6 deletions(-)
kernel/trace/trace_events_filter.c +3 -6
index 97b93f3..0948905 100644
@@ -1894,17 +1894,14 @@ int ftrace_profile_set_filter(struct perf_event *event, int event_id,
 	int err;
 	struct event_filter *filter;
 	struct filter_parse_state *ps;
-	struct ftrace_event_call *call = NULL;
+	struct ftrace_event_call *call;
 
 	mutex_lock(&event_mutex);
 
-	list_for_each_entry(call, &ftrace_events, list) {
-		if (call->event.type == event_id)
-			break;
-	}
+	call = event->tp_event;
 
 	err = -EINVAL;
-	if (&call->list == &ftrace_events)
+	if (!call)
 		goto out_unlock;
 
 	err = -EEXIST;
Signature · 1 line
1.7.5.4
author maintainer
#8 lore raw

PATCH 8/21 tracing/filter: Unify predicate tree walking, change check_pred_tree

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Adding walk_pred_tree function to be used for walking throught the filter predicates.

For each predicate the callback function is called, allowing users to add their own functionality or customize their way through the filter predicates.

Changing check_pred_tree function to use walk_pred_tree.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |  137 ++++++++++++++++++++++-------------
 1 files changed, 86 insertions(+), 51 deletions(-)
kernel/trace/trace_events_filter.c +86 -51
index 0948905..5b889d4 100644
@@ -381,6 +381,63 @@ get_pred_parent(struct filter_pred *pred, struct filter_pred *preds,
 	return pred;
 }
 
+enum walk_return {
+	WALK_PRED_ABORT,
+	WALK_PRED_PARENT,
+	WALK_PRED_DEFAULT,
+};
+
+typedef int (*filter_pred_walkcb_t) (enum move_type move,
+				     struct filter_pred *pred,
+				     int *err, void *data);
+
+static int walk_pred_tree(struct filter_pred *preds,
+			  struct filter_pred *root,
+			  filter_pred_walkcb_t cb, void *data)
+{
+	struct filter_pred *pred = root;
+	enum move_type move = MOVE_DOWN;
+	int done = 0;
+
+	if  (!preds)
+		return -EINVAL;
+
+	do {
+		int err = 0, ret;
+
+		ret = cb(move, pred, &err, data);
+		if (ret == WALK_PRED_ABORT)
+			return err;
+		if (ret == WALK_PRED_PARENT)
+			goto get_parent;
+
+		switch (move) {
+		case MOVE_DOWN:
+			if (pred->left != FILTER_PRED_INVALID) {
+				pred = &preds[pred->left];
+				continue;
+			}
+			goto get_parent;
+		case MOVE_UP_FROM_LEFT:
+			pred = &preds[pred->right];
+			move = MOVE_DOWN;
+			continue;
+		case MOVE_UP_FROM_RIGHT:
+ get_parent:
+			if (pred == root)
+				break;
+			pred = get_pred_parent(pred, preds,
+					       pred->parent,
+					       &move);
+			continue;
+		}
+		done = 1;
+	} while (!done);
+
+	/* We are fine. */
+	return 0;
+}
+
 /*
  * A series of AND or ORs where found together. Instead of
  * climbing up and down the tree branches, an array of the

@@ -1321,6 +1378,23 @@ static int count_preds(struct filter_parse_state *ps)
 	return n_preds;
 }
 
+struct check_pred_data {
+	int count;
+	int max;
+};
+
+static int check_pred_tree_cb(enum move_type move, struct filter_pred *pred,
+			      int *err, void *data)
+{
+	struct check_pred_data *d = data;
+
+	if (WARN_ON(d->count++ > d->max)) {
+		*err = -EINVAL;
+		return WALK_PRED_ABORT;
+	}
+	return WALK_PRED_DEFAULT;
+}
+
 /*
  * The tree is walked at filtering of an event. If the tree is not correctly
  * built, it may cause an infinite loop. Check here that the tree does

@@ -1329,58 +1403,19 @@ static int count_preds(struct filter_parse_state *ps)
 static int check_pred_tree(struct event_filter *filter,
 			   struct filter_pred *root)
 {
-	struct filter_pred *preds;
-	struct filter_pred *pred;
-	enum move_type move = MOVE_DOWN;
-	int count = 0;
-	int done = 0;
-	int max;
-
-	/*
-	 * The max that we can hit a node is three times.
-	 * Once going down, once coming up from left, and
-	 * once coming up from right. This is more than enough
-	 * since leafs are only hit a single time.
-	 */
-	max = 3 * filter->n_preds;
-
-	preds = filter->preds;
-	if  (!preds)
-		return -EINVAL;
-	pred = root;
-
-	do {
-		if (WARN_ON(count++ > max))
-			return -EINVAL;
-
-		switch (move) {
-		case MOVE_DOWN:
-			if (pred->left != FILTER_PRED_INVALID) {
-				pred = &preds[pred->left];
-				continue;
-			}
-			/* A leaf at the root is just a leaf in the tree */
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		case MOVE_UP_FROM_LEFT:
-			pred = &preds[pred->right];
-			move = MOVE_DOWN;
-			continue;
-		case MOVE_UP_FROM_RIGHT:
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		}
-		done = 1;
-	} while (!done);
+	struct check_pred_data data = {
+		/*
+		 * The max that we can hit a node is three times.
+		 * Once going down, once coming up from left, and
+		 * once coming up from right. This is more than enough
+		 * since leafs are only hit a single time.
+		 */
+		.max   = 3 * filter->n_preds,
+		.count = 0,
+	};
 
-	/* We are fine. */
-	return 0;
+	return walk_pred_tree(filter->preds, root,
+			      check_pred_tree_cb, &data);
 }
 
 static int count_leafs(struct filter_pred *preds, struct filter_pred *root)
Signature · 1 line
1.7.5.4
author maintainer
#9 lore raw

PATCH 9/21 tracing/filter: Change count_leafs function to use walk_pred_tree

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Changing count_leafs function to use unified predicates tree processing.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |   47 ++++++++++-------------------------
 1 files changed, 14 insertions(+), 33 deletions(-)
kernel/trace/trace_events_filter.c +14 -33
index 5b889d4..ebbb261 100644
@@ -1418,43 +1418,24 @@ static int check_pred_tree(struct event_filter *filter,
 			      check_pred_tree_cb, &data);
 }
 
-static int count_leafs(struct filter_pred *preds, struct filter_pred *root)
+static int count_leafs_cb(enum move_type move, struct filter_pred *pred,
+			  int *err, void *data)
 {
-	struct filter_pred *pred;
-	enum move_type move = MOVE_DOWN;
-	int count = 0;
-	int done = 0;
+	int *count = data;
 
-	pred = root;
+	if ((move == MOVE_DOWN) &&
+	    (pred->left == FILTER_PRED_INVALID))
+		(*count)++;
 
-	do {
-		switch (move) {
-		case MOVE_DOWN:
-			if (pred->left != FILTER_PRED_INVALID) {
-				pred = &preds[pred->left];
-				continue;
-			}
-			/* A leaf at the root is just a leaf in the tree */
-			if (pred == root)
-				return 1;
-			count++;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		case MOVE_UP_FROM_LEFT:
-			pred = &preds[pred->right];
-			move = MOVE_DOWN;
-			continue;
-		case MOVE_UP_FROM_RIGHT:
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		}
-		done = 1;
-	} while (!done);
+	return WALK_PRED_DEFAULT;
+}
+
+static int count_leafs(struct filter_pred *preds, struct filter_pred *root)
+{
+	int count = 0, ret;
 
+	ret = walk_pred_tree(preds, root, count_leafs_cb, &count);
+	WARN_ON(ret);
 	return count;
 }
Signature · 1 line
1.7.5.4
author maintainer
#10 lore raw

PATCH 10/21 tracing/filter: Change fold_pred_tree function to use walk_pred_tree

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Changing fold_pred_tree function to use unified predicates tree processing.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |   65 +++++++++++-------------------------
 1 files changed, 20 insertions(+), 45 deletions(-)
kernel/trace/trace_events_filter.c +20 -45
index ebbb261..d8aa100 100644
@@ -1496,6 +1496,24 @@ static int fold_pred(struct filter_pred *preds, struct filter_pred *root)
 	return 0;
 }
 
+static int fold_pred_tree_cb(enum move_type move, struct filter_pred *pred,
+			     int *err, void *data)
+{
+	struct filter_pred *preds = data;
+
+	if (move != MOVE_DOWN)
+		return WALK_PRED_DEFAULT;
+	if (!(pred->index & FILTER_PRED_FOLD))
+		return WALK_PRED_DEFAULT;
+
+	*err = fold_pred(preds, pred);
+	if (*err)
+		return WALK_PRED_ABORT;
+
+	/* eveyrhing below is folded, continue with parent */
+	return WALK_PRED_PARENT;
+}
+
 /*
  * To optimize the processing of the ops, if we have several "ors" or
  * "ands" together, we can put them in an array and process them all

@@ -1504,51 +1522,8 @@ static int fold_pred(struct filter_pred *preds, struct filter_pred *root)
 static int fold_pred_tree(struct event_filter *filter,
 			   struct filter_pred *root)
 {
-	struct filter_pred *preds;
-	struct filter_pred *pred;
-	enum move_type move = MOVE_DOWN;
-	int done = 0;
-	int err;
-
-	preds = filter->preds;
-	if  (!preds)
-		return -EINVAL;
-	pred = root;
-
-	do {
-		switch (move) {
-		case MOVE_DOWN:
-			if (pred->index & FILTER_PRED_FOLD) {
-				err = fold_pred(preds, pred);
-				if (err)
-					return err;
-				/* Folded nodes are like leafs */
-			} else if (pred->left != FILTER_PRED_INVALID) {
-				pred = &preds[pred->left];
-				continue;
-			}
-
-			/* A leaf at the root is just a leaf in the tree */
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		case MOVE_UP_FROM_LEFT:
-			pred = &preds[pred->right];
-			move = MOVE_DOWN;
-			continue;
-		case MOVE_UP_FROM_RIGHT:
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		}
-		done = 1;
-	} while (!done);
-
-	return 0;
+	return walk_pred_tree(filter->preds, root, fold_pred_tree_cb,
+			      filter->preds);
 }
 
 static int replace_preds(struct ftrace_event_call *call,
Signature · 1 line
1.7.5.4
author maintainer
#11 lore raw

PATCH 11/21 tracing/filter: Change fold_pred function to use walk_pred_tree

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Changing fold_pred_tree function to use unified predicates tree processing.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |   68 +++++++++++++++++------------------
 1 files changed, 33 insertions(+), 35 deletions(-)
kernel/trace/trace_events_filter.c +33 -35
index d8aa100..f44e68b 100644
@@ -1439,13 +1439,40 @@ static int count_leafs(struct filter_pred *preds, struct filter_pred *root)
 	return count;
 }
 
+struct fold_pred_data {
+	struct filter_pred *root;
+	int count;
+	int children;
+};
+
+static int fold_pred_cb(enum move_type move, struct filter_pred *pred,
+			int *err, void *data)
+{
+	struct fold_pred_data *d = data;
+	struct filter_pred *root = d->root;
+
+	if (move != MOVE_DOWN)
+		return WALK_PRED_DEFAULT;
+	if (pred->left != FILTER_PRED_INVALID)
+		return WALK_PRED_DEFAULT;
+
+	if (WARN_ON(d->count == d->children)) {
+		*err = -EINVAL;
+		return WALK_PRED_ABORT;
+	}
+
+	pred->index &= ~FILTER_PRED_FOLD;
+	root->ops[d->count++] = pred->index;
+	return WALK_PRED_DEFAULT;
+}
+
 static int fold_pred(struct filter_pred *preds, struct filter_pred *root)
 {
-	struct filter_pred *pred;
-	enum move_type move = MOVE_DOWN;
-	int count = 0;
+	struct fold_pred_data data = {
+		.root  = root,
+		.count = 0,
+	};
 	int children;
-	int done = 0;
 
 	/* No need to keep the fold flag */
 	root->index &= ~FILTER_PRED_FOLD;

@@ -1463,37 +1490,8 @@ static int fold_pred(struct filter_pred *preds, struct filter_pred *root)
 		return -ENOMEM;
 
 	root->val = children;
-
-	pred = root;
-	do {
-		switch (move) {
-		case MOVE_DOWN:
-			if (pred->left != FILTER_PRED_INVALID) {
-				pred = &preds[pred->left];
-				continue;
-			}
-			if (WARN_ON(count == children))
-				return -EINVAL;
-			pred->index &= ~FILTER_PRED_FOLD;
-			root->ops[count++] = pred->index;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		case MOVE_UP_FROM_LEFT:
-			pred = &preds[pred->right];
-			move = MOVE_DOWN;
-			continue;
-		case MOVE_UP_FROM_RIGHT:
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		}
-		done = 1;
-	} while (!done);
-
-	return 0;
+	data.children = children;
+	return walk_pred_tree(preds, root, fold_pred_cb, &data);
 }
 
 static int fold_pred_tree_cb(enum move_type move, struct filter_pred *pred,
Signature · 1 line
1.7.5.4
author maintainer
#12 lore raw

PATCH 12/21 tracing/filter: Change filter_match_preds function to use

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Changing filter_match_preds function to use unified predicates tree processing.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |  124 +++++++++++++++++-------------------
 1 files changed, 58 insertions(+), 66 deletions(-)
kernel/trace/trace_events_filter.c +58 -66
index f44e68b..319c3ca 100644
@@ -467,99 +467,91 @@ static int process_ops(struct filter_pred *preds,
 
 	for (i = 0; i < op->val; i++) {
 		pred = &preds[op->ops[i]];
-		match = pred->fn(pred, rec);
+		if (!WARN_ON_ONCE(!pred->fn))
+			match = pred->fn(pred, rec);
 		if (!!match == type)
 			return match;
 	}
 	return match;
 }
 
+struct filter_match_preds_data {
+	struct filter_pred *preds;
+	int match;
+	void *rec;
+};
+
+static int filter_match_preds_cb(enum move_type move, struct filter_pred *pred,
+				 int *err, void *data)
+{
+	struct filter_match_preds_data *d = data;
+
+	*err = 0;
+	switch (move) {
+	case MOVE_DOWN:
+		/* only AND and OR have children */
+		if (pred->left != FILTER_PRED_INVALID) {
+			/* If ops is set, then it was folded. */
+			if (!pred->ops)
+				return WALK_PRED_DEFAULT;
+			/* We can treat folded ops as a leaf node */
+			d->match = process_ops(d->preds, pred, d->rec);
+		} else {
+			if (!WARN_ON_ONCE(!pred->fn))
+				d->match = pred->fn(pred, d->rec);
+		}
+
+		return WALK_PRED_PARENT;
+	case MOVE_UP_FROM_LEFT:
+		/*
+		 * Check for short circuits.
+		 *
+		 * Optimization: !!match == (pred->op == OP_OR)
+		 *   is the same as:
+		 * if ((match && pred->op == OP_OR) ||
+		 *     (!match && pred->op == OP_AND))
+		 */
+		if (!!d->match == (pred->op == OP_OR))
+			return WALK_PRED_PARENT;
+		break;
+	case MOVE_UP_FROM_RIGHT:
+		break;
+	}
+
+	return WALK_PRED_DEFAULT;
+}
+
 /* return 1 if event matches, 0 otherwise (discard) */
 int filter_match_preds(struct event_filter *filter, void *rec)
 {
-	int match = -1;
-	enum move_type move = MOVE_DOWN;
 	struct filter_pred *preds;
-	struct filter_pred *pred;
 	struct filter_pred *root;
-	int n_preds;
-	int done = 0;
+	struct filter_match_preds_data data = {
+		/* match is currently meaningless */
+		.match = -1,
+		.rec   = rec,
+	};
+	int n_preds, ret;
 
 	/* no filter is considered a match */
 	if (!filter)
 		return 1;
 
 	n_preds = filter->n_preds;
-
 	if (!n_preds)
 		return 1;
 
 	/*
 	 * n_preds, root and filter->preds are protect with preemption disabled.
 	 */
-	preds = rcu_dereference_sched(filter->preds);
 	root = rcu_dereference_sched(filter->root);
 	if (!root)
 		return 1;
 
-	pred = root;
-
-	/* match is currently meaningless */
-	match = -1;
-
-	do {
-		switch (move) {
-		case MOVE_DOWN:
-			/* only AND and OR have children */
-			if (pred->left != FILTER_PRED_INVALID) {
-				/* If ops is set, then it was folded. */
-				if (!pred->ops) {
-					/* keep going to down the left side */
-					pred = &preds[pred->left];
-					continue;
-				}
-				/* We can treat folded ops as a leaf node */
-				match = process_ops(preds, pred, rec);
-			} else
-				match = pred->fn(pred, rec);
-			/* If this pred is the only pred */
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		case MOVE_UP_FROM_LEFT:
-			/*
-			 * Check for short circuits.
-			 *
-			 * Optimization: !!match == (pred->op == OP_OR)
-			 *   is the same as:
-			 * if ((match && pred->op == OP_OR) ||
-			 *     (!match && pred->op == OP_AND))
-			 */
-			if (!!match == (pred->op == OP_OR)) {
-				if (pred == root)
-					break;
-				pred = get_pred_parent(pred, preds,
-						       pred->parent, &move);
-				continue;
-			}
-			/* now go down the right side of the tree. */
-			pred = &preds[pred->right];
-			move = MOVE_DOWN;
-			continue;
-		case MOVE_UP_FROM_RIGHT:
-			/* We finished this equation. */
-			if (pred == root)
-				break;
-			pred = get_pred_parent(pred, preds,
-					       pred->parent, &move);
-			continue;
-		}
-		done = 1;
-	} while (!done);
-
-	return match;
+	data.preds = preds = rcu_dereference_sched(filter->preds);
+	ret = walk_pred_tree(preds, root, filter_match_preds_cb, &data);
+	WARN_ON(ret);
+	return data.match;
 }
 EXPORT_SYMBOL_GPL(filter_match_preds);
Signature · 1 line
1.7.5.4
author maintainer
#13 lore raw

PATCH 13/21 tracing/filter: Add startup tests for events filter

In reply to Steven Rostedt

From: Jiri Olsa <[email protected]>

Adding automated tests running as late_initcall. Tests are compiled in with CONFIG_FTRACE_STARTUP_TEST option.

Adding test event "ftrace_test_filter" used to simulate filter processing during event occurance.

String filters are compiled and tested against several test events with different values.

Also testing that evaluation of explicit predicates is ommited due to the lazy filter evaluation.

Signed-off-by Jiri Olsa <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/Makefile                   |    2 +
 kernel/trace/trace.h                    |    3 +
 kernel/trace/trace_events_filter.c      |  209 +++++++++++++++++++++++++++++++
 kernel/trace/trace_events_filter_test.h |   50 ++++++++
 4 files changed, 264 insertions(+), 0 deletions(-)
 create mode 100644 kernel/trace/trace_events_filter_test.h
kernel/trace/Makefile +2 -0
index 761c510..b384ed5 100644
@@ -15,6 +15,8 @@ ifdef CONFIG_TRACING_BRANCHES
 KBUILD_CFLAGS += -DDISABLE_BRANCH_PROFILING
 endif
 
+CFLAGS_trace_events_filter.o := -I$(src)
+
 #
 # Make the trace clocks available generally: it's infrastructure
 # relied on by ptrace for example:
kernel/trace/trace.h +3 -0
index 2eb3cf6..4c7540a 100644
@@ -762,6 +762,9 @@ struct filter_pred {
 	u64 			val;
 	struct regex		regex;
 	unsigned short		*ops;
+#ifdef CONFIG_FTRACE_STARTUP_TEST
+	struct ftrace_event_field *field;
+#endif
 	int 			offset;
 	int 			not;
 	int 			op;
kernel/trace/trace_events_filter.c +209 -0

218 lines not on this page · raw message

kernel/trace/trace_events_filter_test.h new file +50 -0

50 lines not on this page · raw message

Signature · 1 line
1.7.5.4
author maintainer
#14 lore raw

PATCH 14/21 tracing: Add preempt disable for filter self test

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

The self testing for event filters does not really need preemption disabled as there are no races at the time of testing, but the functions it calls uses rcu_dereference_sched() which will complain if preemption is not disabled.

Cc Jiri Olsa <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_filter.c |    6 ++++++
 1 files changed, 6 insertions(+), 0 deletions(-)
kernel/trace/trace_events_filter.c +6 -0
index 6a642e2..816d3d0 100644
@@ -2101,6 +2101,11 @@ static __init int ftrace_test_event_filter(void)
 			break;
 		}
 
+		/*
+		 * The preemption disabling is not really needed for self
+		 * tests, but the rcu dereference will complain without it.
+		 */
+		preempt_disable();
 		if (*d->not_visited)
 			walk_pred_tree(filter->preds, filter->root,
 				       test_walk_pred_cb,

@@ -2108,6 +2113,7 @@ static __init int ftrace_test_event_filter(void)
 
 		test_pred_visited = 0;
 		err = filter_match_preds(filter, &d->rec);
+		preempt_enable();
 
 		__free_filter(filter);
Signature · 1 line
1.7.5.4
author maintainer
#15 lore raw

PATCH 15/21 trace: Add a new readonly entry to report total buffer size

In reply to Steven Rostedt

From: Vaibhav Nagarnaik <[email protected]>

The current file "buffer_size_kb" reports the size of per-cpu buffer and not the overall memory allocated which could be misleading. A new file "buffer_total_size_kb" adds up all the enabled CPU buffer sizes and reports it. This is only a readonly entry.

Signed-off-by Vaibhav Nagarnaik <[email protected]>
Cc Michael Rubin <[email protected]>
Cc David Sharp <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace.c |   33 +++++++++++++++++++++++++++++++++
 1 files changed, 33 insertions(+), 0 deletions(-)
kernel/trace/trace.c +33 -0
index e5df02c..0117678 100644
@@ -3569,6 +3569,30 @@ tracing_entries_write(struct file *filp, const char __user *ubuf,
 }
 
 static ssize_t
+tracing_total_entries_read(struct file *filp, char __user *ubuf,
+				size_t cnt, loff_t *ppos)
+{
+	struct trace_array *tr = filp->private_data;
+	char buf[64];
+	int r, cpu;
+	unsigned long size = 0, expanded_size = 0;
+
+	mutex_lock(&trace_types_lock);
+	for_each_tracing_cpu(cpu) {
+		size += tr->entries >> 10;
+		if (!ring_buffer_expanded)
+			expanded_size += trace_buf_size >> 10;
+	}
+	if (ring_buffer_expanded)
+		r = sprintf(buf, "%lu\n", size);
+	else
+		r = sprintf(buf, "%lu (expanded: %lu)\n", size, expanded_size);
+	mutex_unlock(&trace_types_lock);
+
+	return simple_read_from_buffer(ubuf, cnt, ppos, buf, r);
+}
+
+static ssize_t
 tracing_free_buffer_write(struct file *filp, const char __user *ubuf,
 			  size_t cnt, loff_t *ppos)
 {

@@ -3739,6 +3763,12 @@ static const struct file_operations tracing_entries_fops = {
 	.llseek		= generic_file_llseek,
 };
 
+static const struct file_operations tracing_total_entries_fops = {
+	.open		= tracing_open_generic,
+	.read		= tracing_total_entries_read,
+	.llseek		= generic_file_llseek,
+};
+
 static const struct file_operations tracing_free_buffer_fops = {
 	.write		= tracing_free_buffer_write,
 	.release	= tracing_free_buffer_release,

@@ -4450,6 +4480,9 @@ static __init int tracer_init_debugfs(void)
 	trace_create_file("buffer_size_kb", 0644, d_tracer,
 			&global_trace, &tracing_entries_fops);
 
+	trace_create_file("buffer_total_size_kb", 0444, d_tracer,
+			&global_trace, &tracing_total_entries_fops);
+
 	trace_create_file("free_buffer", 0644, d_tracer,
 			&global_trace, &tracing_free_buffer_fops);
Signature · 1 line
1.7.5.4
author maintainer
#16 lore raw

PATCH 16/21 trace: Add ring buffer stats to measure rate of events

In reply to Steven Rostedt

From: Vaibhav Nagarnaik <[email protected]>

The stats file under per_cpu folder provides the number of entries, overruns and other statistics about the CPU ring buffer. However, the numbers do not provide any indication of how full the ring buffer is in bytes compared to the overall size in bytes. Also, it is helpful to know the rate at which the cpu buffer is filling up.

This patch adds an entry "bytes: " in printed stats for per_cpu ring buffer which provides the actual bytes consumed in the ring buffer. This field includes the number of bytes used by recorded events and the padding bytes added when moving the tail pointer to next page.

It also adds the following time stamps:
"oldest event ts:" - the oldest timestamp in the ring buffer "now ts:" - the timestamp at the time of reading

The field "now ts" provides a consistent time snapshot to the userspace when being read. This is read from the same trace clock used by tracing event timestamps.

Together, these values provide the rate at which the buffer is filling up, from the formula:
bytes / (now_ts - oldest_event_ts)

Signed-off-by Vaibhav Nagarnaik <[email protected]>
Cc Michael Rubin <[email protected]>
Cc David Sharp <[email protected]>
Link http://lkml.kernel.org/r/[email protected] open here
Signed-off-by Steven Rostedt <[email protected]>
---
 include/linux/ring_buffer.h |    2 +
 kernel/trace/ring_buffer.c  |   70 ++++++++++++++++++++++++++++++++++++++++++-
 kernel/trace/trace.c        |   13 ++++++++
 3 files changed, 84 insertions(+), 1 deletions(-)
include/linux/ring_buffer.h +2 -0
index b891de9..67be037 100644
@@ -154,6 +154,8 @@ void ring_buffer_record_enable(struct ring_buffer *buffer);
 void ring_buffer_record_disable_cpu(struct ring_buffer *buffer, int cpu);
 void ring_buffer_record_enable_cpu(struct ring_buffer *buffer, int cpu);
 
+unsigned long ring_buffer_oldest_event_ts(struct ring_buffer *buffer, int cpu);
+unsigned long ring_buffer_bytes_cpu(struct ring_buffer *buffer, int cpu);
 unsigned long ring_buffer_entries(struct ring_buffer *buffer);
 unsigned long ring_buffer_overruns(struct ring_buffer *buffer);
 unsigned long ring_buffer_entries_cpu(struct ring_buffer *buffer, int cpu);
kernel/trace/ring_buffer.c +69 -1

136 lines not on this page · raw message

kernel/trace/trace.c +13 -0
index 0117678..b419070 100644
@@ -4056,6 +4056,8 @@ tracing_stats_read(struct file *filp, char __user *ubuf,
 	struct trace_array *tr = &global_trace;
 	struct trace_seq *s;
 	unsigned long cnt;
+	unsigned long long t;
+	unsigned long usec_rem;
 
 	s = kmalloc(sizeof(*s), GFP_KERNEL);
 	if (!s)

@@ -4072,6 +4074,17 @@ tracing_stats_read(struct file *filp, char __user *ubuf,
 	cnt = ring_buffer_commit_overrun_cpu(tr->buffer, cpu);
 	trace_seq_printf(s, "commit overrun: %ld\n", cnt);
 
+	cnt = ring_buffer_bytes_cpu(tr->buffer, cpu);
+	trace_seq_printf(s, "bytes: %ld\n", cnt);
+
+	t = ns2usecs(ring_buffer_oldest_event_ts(tr->buffer, cpu));
+	usec_rem = do_div(t, USEC_PER_SEC);
+	trace_seq_printf(s, "oldest event ts: %5llu.%06lu\n", t, usec_rem);
+
+	t = ns2usecs(ring_buffer_time_stamp(tr->buffer, cpu));
+	usec_rem = do_div(t, USEC_PER_SEC);
+	trace_seq_printf(s, "now ts: %5llu.%06lu\n", t, usec_rem);
+
 	count = simple_read_from_buffer(ubuf, count, ppos, s->buffer, s->len);
 
 	kfree(s);
Signature · 1 line
1.7.5.4
author maintainer
#17 lore raw

PATCH 17/21 tracing: Add a counter clock for those that do not trust clocks

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

When debugging tight race conditions, it can be helpful to have a synchronized tracing method. Although in most cases the global clock provides this functionality, if timings is not the issue, it is more comforting to know that the order of events really happened in a precise order.

Instead of using a clock, add a "counter" that is simply an incrementing atomic 64bit counter that orders the events as they are perceived to happen.

The trace_clock_counter() is added from the attempt by Peter Zijlstra trying to convert the trace_clock_global() to it. I took Peter's counter code and made trace_clock_counter() instead, and added it to the choice of clocks. Just echo counter > /debug/tracing/trace_clock to activate it.

Requested-by Thomas Gleixner <[email protected]>
Requested-by Peter Zijlstra <[email protected]>
Reviewed-by Valdis Kletnieks <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 include/linux/trace_clock.h |    1 +
 kernel/trace/trace.c        |    1 +
 kernel/trace/trace_clock.c  |   12 ++++++++++++
 3 files changed, 14 insertions(+), 0 deletions(-)
include/linux/trace_clock.h +1 -0
index 7a81303..4eb4902 100644
@@ -15,5 +15,6 @@
 extern u64 notrace trace_clock_local(void);
 extern u64 notrace trace_clock(void);
 extern u64 notrace trace_clock_global(void);
+extern u64 notrace trace_clock_counter(void);
 
 #endif /* _LINUX_TRACE_CLOCK_H */
kernel/trace/trace.c +1 -0
index b419070..4b8df0d 100644
@@ -435,6 +435,7 @@ static struct {
 } trace_clocks[] = {
 	{ trace_clock_local,	"local" },
 	{ trace_clock_global,	"global" },
+	{ trace_clock_counter,	"counter" },
 };
 
 int trace_clock_id;
kernel/trace/trace_clock.c +12 -0
index 6302747..3947835 100644
@@ -113,3 +113,15 @@ u64 notrace trace_clock_global(void)
 
 	return now;
 }
+
+static atomic64_t trace_counter;
+
+/*
+ * trace_clock_counter(): simply an atomic counter.
+ * Use the trace_counter "counter" for cases where you do not care
+ * about timings, but are interested in strict ordering.
+ */
+u64 notrace trace_clock_counter(void)
+{
+	return atomic64_add_return(1, &trace_counter);
+}
Signature · 1 line
1.7.5.4
author maintainer
#18 lore raw

PATCH 18/21 tracing: Fix preemptirqsoff tracer to not stop at preempt off

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

If irqs are disabled when preemption count reaches zero, the preemptirqsoff tracer should not flag that as the end.

When interrupts are enabled and preemption count is not zero the preemptirqsoff correctly continues its tracing.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_irqsoff.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)
kernel/trace/trace_irqsoff.c +2 -2
index 667aa8c..a1a3359 100644
@@ -505,13 +505,13 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller);
 #ifdef CONFIG_PREEMPT_TRACER
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
-	if (preempt_trace())
+	if (preempt_trace() && !irq_trace())
 		stop_critical_timing(a0, a1);
 }
 
 void trace_preempt_off(unsigned long a0, unsigned long a1)
 {
-	if (preempt_trace())
+	if (preempt_trace() && !irq_trace())
 		start_critical_timing(a0, a1);
 }
 #endif /* CONFIG_PREEMPT_TRACER */
Signature · 1 line
1.7.5.4
author maintainer
#19 lore raw

PATCH 19/21 tracing: Account for preempt off in preempt_schedule()

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

The preempt_schedule() uses the preempt_disable_notrace() version because it can cause infinite recursion by the function tracer as the function tracer uses preempt_enable_notrace() which may call back into the preempt_schedule() code as the NEED_RESCHED is still set and the PREEMPT_ACTIVE has not been set yet.

See commit: d1f74e20b5b064a130cd0743a256c2d3cfe84010 that made this change.

The preemptoff and preemptirqsoff latency tracers require the first and last preempt count modifiers to enable tracing. But this skips the checks. Since we can not convert them back to the non notrace version, we can use the idle() hooks for the latency tracers here. That is, the start/stop_critical_timings() works well to manually start and stop the latency tracer for preempt off timings.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/sched.c |    9 +++++++++
 1 files changed, 9 insertions(+), 0 deletions(-)
kernel/sched.c +9 -0
index ccacdbd..4b096cc 100644
@@ -4435,7 +4435,16 @@ asmlinkage void __sched notrace preempt_schedule(void)
 
 	do {
 		add_preempt_count_notrace(PREEMPT_ACTIVE);
+		/*
+		 * The add/subtract must not be traced by the function
+		 * tracer. But we still want to account for the
+		 * preempt off latency tracer. Since the _notrace versions
+		 * of add/subtract skip the accounting for latency tracer
+		 * we must force it manually.
+		 */
+		start_critical_timings();
 		schedule();
+		stop_critical_timings();
 		sub_preempt_count_notrace(PREEMPT_ACTIVE);
 
 		/*
Signature · 1 line
1.7.5.4
maintainer
#20 lore raw

Re: [PATCH 19/21] tracing: Account for preempt off in preempt_schedule()

Quoted 36 lines · Steven Rostedt

plain text document attachment (0019-tracing-Account-for-preempt-off-in-preempt_schedule.patch)
From: Steven Rostedt <[email protected]>

The preempt_schedule() uses the preempt_disable_notrace() version because it can cause infinite recursion by the function tracer as the function tracer uses preempt_enable_notrace() which may call back into the preempt_schedule() code as the NEED_RESCHED is still set and the PREEMPT_ACTIVE has not been set yet.

See commit: d1f74e20b5b064a130cd0743a256c2d3cfe84010 that made this change.

The preemptoff and preemptirqsoff latency tracers require the first and last preempt count modifiers to enable tracing. But this skips the checks. Since we can not convert them back to the non notrace version, we can use the idle() hooks for the latency tracers here. That is, the start/stop_critical_timings() works well to manually start and stop the latency tracer for preempt off timings.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/sched.c |    9 +++++++++
 1 files changed, 9 insertions(+), 0 deletions(-)
kernel/sched.c +3 -0
index ccacdbd..4b096cc 100644
@@ -4435,7 +4435,16 @@ asmlinkage void __sched notrace preempt_schedule(void)
 
 	do {
 		add_preempt_count_notrace(PREEMPT_ACTIVE);
+		/*
+		 * The add/subtract must not be traced by the function
+		 * tracer. But we still want to account for the

kernel/sched.c asmlinkage void __sched notrace preempt_schedule(void) · line 4450

Quoted 10 lines
kernel/sched.c +6 -0
+		 * preempt off latency tracer. Since the _notrace versions
+		 * of add/subtract skip the accounting for latency tracer
+		 * we must force it manually.
+		 */
+		start_critical_timings();
 		schedule();
+		stop_critical_timings();
 		sub_preempt_count_notrace(PREEMPT_ACTIVE);
 
 		/*

This won't apply, you're patching ancient code.

Anyway, this all stinks, and reading the changelog of d1f74e20b5b064a130cd0743a256c2d3cfe84010 and the above just makes me confused.

author maintainer
#21 lore raw

Re: [PATCH 19/21] tracing: Account for preempt off in preempt_schedule()

Quoted 26 lines · Peter Zijlstra
Quoted 26 lines
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/sched.c |    9 +++++++++
 1 files changed, 9 insertions(+), 0 deletions(-)
kernel/sched.c +9 -0
index ccacdbd..4b096cc 100644
@@ -4435,7 +4435,16 @@ asmlinkage void __sched notrace preempt_schedule(void)
 
 	do {
 		add_preempt_count_notrace(PREEMPT_ACTIVE);
+		/*
+		 * The add/subtract must not be traced by the function
+		 * tracer. But we still want to account for the
+		 * preempt off latency tracer. Since the _notrace versions
+		 * of add/subtract skip the accounting for latency tracer
+		 * we must force it manually.
+		 */
+		start_critical_timings();
 		schedule();
+		stop_critical_timings();
 		sub_preempt_count_notrace(PREEMPT_ACTIVE);
Quoted 3 lines

kernel/sched.c asmlinkage void __sched notrace preempt_schedule(void) · line 4450

Quoted 1 line
kernel/sched.c +0 -0
 		/*

This won't apply, you're patching ancient code.

Yes, that's the way git usually works. I could start a new branch for this. But since we are not doing many pulls while kernel.org is down, my kernel base has become a bit out of date. I thought that's the way Linus wants it. I'm sure this would apply with a trivial merge fixup.

But if you want to take this patch, then I could rebase my tree and take it out.

Quoted 5 lines

Anyway, this all stinks, and reading the changelog of d1f74e20b5b064a130cd0743a256c2d3cfe84010 and the above just makes me confused.

What would you suggest? Just ignore the latencies that schedule produces, even though its been one of the top causes of latencies?

-- Steve

maintainer
#22 lore raw

Re: [PATCH 19/21] tracing: Account for preempt off in preempt_schedule()

Quoted 2 lines · Steven Rostedt

What would you suggest? Just ignore the latencies that schedule produces, even though its been one of the top causes of latencies?

I would like to actually understand the issue first.. so far all I've got is confusion.

author maintainer
#23 lore raw

Re: [PATCH 19/21] tracing: Account for preempt off in preempt_schedule()

Quoted 7 lines · Peter Zijlstra
Quoted 2 lines · Steven Rostedt

What would you suggest? Just ignore the latencies that schedule produces, even though its been one of the top causes of latencies?

I would like to actually understand the issue first.. so far all I've got is confusion.

Simple. The preemptoff and even preemptirqsoff latency tracers record every time preemption is disabled and enabled. For preemptoff, this only includes modification of the preempt count. For preemptirqsoff, it includes both preempt count increment and interrupts being disabled/enabled.

Currently, the preempt check is done in add/sub_preempt_count(). But in preempt_schedule() we call add/sub_preempt_count_notrace() which updates the preempt_count directly without any of the preempt off/on checks.

The changelog I referenced talked about why we use the notrace versions. Some function tracing hooks use the preempt_enable/disable_notrace(). Function tracer is not the only user of the function tracing facility. With the original preempt_diable(), when we have preempt tracing enabled, the add/sub_preempt_count()s become traced by the function tracer (which is also a good thing as I've used that info). The issue is in preempt_schedule() which is called by preempt_enable() if NEED_RESCHED is set and PREEMPT_ACTIVE is not set. One of the first things that preempt_schedule() does is call add_preempt_count(PREEMPT_ACTIVE), to add the PREEMPT_ACTIVE to preempt count and not come back into preempt_schedule() when interrupted again.

But! If add_preempt_count(PREEPMT_ACTIVE) is traced, we call into the function tracing mechanism *before* it adds PREEMPT_ACTIVE, and when the function hook calls preempt_enable_notrace() it will notice the NEED_RESCHED set and PREEMPT_ACTIVE not set and recurse back into the preempt_schedule() and boom!

By making preempt_schedule() use notrace we avoid this issue with the function tracing hooks, but in the mean time, we just lost the check that preemption was disabled. Since we know that preemption and interrupts were both enabled before calling into preempt_schedule() (otherwise it is a bug), we can just tell the latency tracers that preemption is being disabled manually with the start/stop_critical_timings(). Note, these function names comes from the original latency_tracer that was in -rt.

There's another location in the kernel that we need to manually call into the latency tracer and that's in idle. The cpu_idle() calls disables preemption then disables interrupts and may call some assembly instruction that puts the system into idle but wakes up on interrupts. Then on return, interrupts are enabled and preemption is again enabled.

Since we don't know about this wakeup on interrupts, the latency tracers would count this idle wait as a latency, which obviously is not what we want. Which is where the start/stop_critical_timings() was created for. The preempt_schedule() case is similar in an opposite way. Instead of not wanting to trace, we want to trace, and the code works for this location too.

-- Steve

maintainer
#24 lore raw

Re: [PATCH 19/21] tracing: Account for preempt off in preempt_schedule()

Quoted 6 lines · Steven Rostedt
Quoted 5 lines · Peter Zijlstra
Quoted 2 lines · Steven Rostedt

What would you suggest? Just ignore the latencies that schedule produces, even though its been one of the top causes of latencies?

Quoted 8 lines
Quoted 2 lines

I would like to actually understand the issue first.. so far all I've got is confusion.

Simple. The preemptoff and even preemptirqsoff latency tracers record every time preemption is disabled and enabled. For preemptoff, this only includes modification of the preempt count. For preemptirqsoff, it includes both preempt count increment and interrupts being disabled/enabled.

Simple, except for this blob below..

Quoted 5 lines

Currently, the preempt check is done in add/sub_preempt_count(). But in preempt_schedule() we call add/sub_preempt_count_notrace() which updates the preempt_count directly without any of the preempt off/on checks.

The changelog I referenced talked about why we use the notrace versions.

Which is the important bit, because that's icky and obviously buggy (otherwise you wouldn't need to fix it), so one cannot judge the fix without understanding the initial problem.

Quoted 1 line

Some function tracing hooks use the preempt_enable/disable_notrace().

That's pretty much a non-statement in that it doesn't explain anything.

Quoted 1 line

Function tracer is not the only user of the function tracing facility.

So what?!

Quoted 3 lines

With the original preempt_diable(), when we have preempt tracing enabled, the add/sub_preempt_count()s become traced by the function tracer (which is also a good thing as I've used that info).

Why and how? It would seem to me marking those notrace would cure some of the issues.

Quoted 6 lines

The issue is
in preempt_schedule() which is called by preempt_enable() if NEED_RESCHED is set and PREEMPT_ACTIVE is not set. One of the first things that preempt_schedule() does is call add_preempt_count(PREEMPT_ACTIVE), to add the PREEMPT_ACTIVE to preempt count and not come back into preempt_schedule() when interrupted again.

That sentence doesn't really parse for me, but I think you mean to say that PREEMPT_ACTIVE guards against recursive preemption?

Quoted 5 lines

But! If add_preempt_count(PREEPMT_ACTIVE) is traced, we call into the function tracing mechanism *before* it adds PREEMPT_ACTIVE, and when the function hook calls preempt_enable_notrace() it will notice the NEED_RESCHED set and PREEMPT_ACTIVE not set and recurse back into the preempt_schedule() and boom!

Right, so you've got the mess that there's two different notrace options for the {add,sub}_preempt_count(). One is not doing the trace_preempt_{off,on} thing, and one is marking the function notrace.

The normal {add,sub}_preempt_count() muck does everything, the _notrace() one doesn't do either, and here you need one that does one but not the other.

So you then open code things, but instead of using trace_preempt_{off,on} you use {start,stop}_critical_timings(), which is a totally different beast, confusing matters more.

What's worse, there's not a single comment near preempt_schedule() explaining any of this mess.

Quoted 3 lines

By making preempt_schedule() use notrace we avoid this issue with the function tracing hooks, but in the mean time, we just lost the check that preemption was disabled.

Uhm, no, by marking preempt_schedule() notrace you don't call into the function tracer for this call. The preemption check was lost by using the _notrace() preempt_count fiddling.

Hiding preempt_schedule() from the function tracer isn't exactly nice though. Although I think we can reconstruct it was called by seeing schedule() called and seeing N set (except of course that the default function tracer output doesn't show that (one more reason the the default output format is broken).

Quoted 6 lines

Since we know that preemption and
interrupts were both enabled before calling into preempt_schedule() (otherwise it is a bug), we can just tell the latency tracers that preemption is being disabled manually with the start/stop_critical_timings(). Note, these function names comes from the original latency_tracer that was in -rt.

Doesn't matter where they come from, they're still confusing for anybody trying to make sense of the {add,sub}_preempt_count vs &_notrace functions.

Quoted 6 lines

There's another location in the kernel that we need to manually call into the latency tracer and that's in idle. The cpu_idle() calls disables preemption then disables interrupts and may call some assembly instruction that puts the system into idle but wakes up on interrupts. Then on return, interrupts are enabled and preemption is again enabled.

Quoted 6 lines

Since we don't know about this wakeup on interrupts, the latency tracers would count this idle wait as a latency, which obviously is not what we want. Which is where the start/stop_critical_timings() was created for. The preempt_schedule() case is similar in an opposite way. Instead of not wanting to trace, we want to trace, and the code works for this location too.

Wouldn't it be much more sensible to mark all that preempt/irq fiddling in the idle path with _notrace instead? And stick a comment near.

Having two things to do the same thing just doesn't make sense.

maintainer
#25 lore raw

Re: [PATCH 19/21] tracing: Account for preempt off in preempt_schedule()

In reply to Steven Rostedt
Quoted 5 lines · Peter Zijlstra

Wouldn't it be much more sensible to mark all that preempt/irq fiddling in the idle path with _notrace instead? And stick a comment near.

Having two things to do the same thing just doesn't make sense.

That is, it seems to me avoiding the idle path is seen as a non-preempt region is cleaner than (mostly) fixing it up.

maintainer
#26 lore raw

Re: [PATCH 19/21] tracing: Account for preempt off in preempt_schedule()

In reply to Steven Rostedt
Quoted 1 line · Steven Rostedt

Yes, that's the way git usually works

Its also one of the reasons I hate git. In this case the fixup will live in some merge commit and be totally lost to the normal way of things.

I absolutely detest non empty merge commits.

author maintainer
#27 lore raw

PATCH 20/21 tracing: Do not allocate buffer for trace_marker

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

When doing intense tracing, the kmalloc inside trace_marker can introduce side effects to what is being traced. It is best to simply use a static buffer and grab a mutex to write to it. This keeps the impact of using the trace_marker() to a minimum.

Suggested-by Thomas Gleixner <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace.c |   33 +++++++++++++++++----------------
 1 files changed, 17 insertions(+), 16 deletions(-)
kernel/trace/trace.c +17 -16
index 4b8df0d..e463125 100644
@@ -1442,15 +1442,19 @@ static void __trace_userstack(struct trace_array *tr, unsigned long flags)
 
 #endif /* CONFIG_STACKTRACE */
 
+static char trace_buf[TRACE_BUF_SIZE];
+static char trace_ubuf[TRACE_BUF_SIZE];
+
+static arch_spinlock_t trace_buf_lock =
+	(arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
+static DEFINE_MUTEX(trace_ubuf_mutex);
+
 /**
  * trace_vbprintk - write binary msg to tracing buffer
  *
  */
 int trace_vbprintk(unsigned long ip, const char *fmt, va_list args)
 {
-	static arch_spinlock_t trace_buf_lock =
-		(arch_spinlock_t)__ARCH_SPIN_LOCK_UNLOCKED;
-	static u32 trace_buf[TRACE_BUF_SIZE];
 
 	struct ftrace_event_call *call = &event_bprint;
 	struct ring_buffer_event *event;

@@ -1480,7 +1484,7 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args)
 	/* Lockdep uses trace_printk for lock tracing */
 	local_irq_save(flags);
 	arch_spin_lock(&trace_buf_lock);
-	len = vbin_printf(trace_buf, TRACE_BUF_SIZE, fmt, args);
+	len = vbin_printf((u32 *)trace_buf, TRACE_BUF_SIZE/sizeof(int), fmt, args);
 
 	if (len > TRACE_BUF_SIZE || len < 0)
 		goto out_unlock;

@@ -1532,9 +1536,6 @@ int trace_array_printk(struct trace_array *tr,
 int trace_array_vprintk(struct trace_array *tr,
 			unsigned long ip, const char *fmt, va_list args)
 {
-	static arch_spinlock_t trace_buf_lock = __ARCH_SPIN_LOCK_UNLOCKED;
-	static char trace_buf[TRACE_BUF_SIZE];
-
 	struct ftrace_event_call *call = &event_print;
 	struct ring_buffer_event *event;
 	struct ring_buffer *buffer;

@@ -3633,23 +3634,22 @@ static ssize_t
 tracing_mark_write(struct file *filp, const char __user *ubuf,
 					size_t cnt, loff_t *fpos)
 {
-	char *buf;
 	size_t written;
+	char *buf = trace_ubuf;
 
 	if (tracing_disabled)
 		return -EINVAL;
 
-	if (cnt > TRACE_BUF_SIZE)
-		cnt = TRACE_BUF_SIZE;
+	if (cnt >= TRACE_BUF_SIZE)
+		cnt = TRACE_BUF_SIZE - 2; /* \n\0 */
 
-	buf = kmalloc(cnt + 2, GFP_KERNEL);
-	if (buf == NULL)
-		return -ENOMEM;
+	mutex_lock(&trace_ubuf_mutex);
 
 	if (copy_from_user(buf, ubuf, cnt)) {
-		kfree(buf);
-		return -EFAULT;
+		written = -EFAULT;
+		goto out;
 	}
+
 	if (buf[cnt-1] != '\n') {
 		buf[cnt] = '\n';
 		buf[cnt+1] = '\0';

@@ -3657,12 +3657,13 @@ tracing_mark_write(struct file *filp, const char __user *ubuf,
 		buf[cnt] = '\0';
 
 	written = mark_printk("%s", buf);
-	kfree(buf);
 	*fpos += written;
 
 	/* don't tell userspace we wrote more - it might confuse them */
 	if (written > cnt)
 		written = cnt;
+ out:
+	mutex_unlock(&trace_ubuf_mutex);
 
 	return written;
 }
Signature · 1 line
1.7.5.4
author maintainer
#28 lore raw

PATCH 21/21 tracing: Add optional percpu buffers for trace_printk()

In reply to Steven Rostedt

From: Steven Rostedt <[email protected]>

Currently, trace_printk() uses a single buffer to write into to calculate the size and format needed to save the trace. To do this safely in an SMP environment, a spin_lock() is taken to only allow one writer at a time to the buffer. But this could also affect what is being traced, and add synchronization that would not be there otherwise.

Ideally, using percpu buffers would be useful, but since trace_printk() is only used in development, having per cpu buffers for something never used is a waste of space. We could make this a compile option but trace_print() may also be used for developing modules, on a distro kernel.

The approach taken here is to dynamically allocate percpu buffers with a new tracing/options switch "trace_printk_percpu". It can be allocated and freed at runtime, or "trace_printk_percpu" may also be specified on the command line and it will be allocated at boot up.

This allows a developer to create percpu buffers for trace_printk() on a running system, and also free them when not in used.

Signed-off-by Steven Rostedt <[email protected]>
---
 Documentation/kernel-parameters.txt |   11 ++++
 kernel/trace/trace.c                |  105 ++++++++++++++++++++++++++++++++---
 kernel/trace/trace.h                |    1 +
 3 files changed, 108 insertions(+), 9 deletions(-)
Documentation/kernel-parameters.txt +11 -0
index e279b72..8fc3e58 100644
@@ -2521,6 +2521,17 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
 			to facilitate early boot debugging.
 			See also Documentation/trace/events.txt
 
+	trace_printk_percpu
+			[FTRACE] When using trace_printk(), by default the
+			temporary buffer is a single instance with a spinlock
+			to protect it. By adding this switch or enabling it at
+			runtime with:
+			echo 1 > /sys/kernel/debug/tracing/options/trace_printk_percpu
+			Per CPU buffers are allocated and trace_printk() will write
+			to them without taking any locks. Echo 0 into the above
+			file, and the percpu buffers will safely be freed.
+			Even if they were allocated with this kernel command line.
+
 	tsc=		Disable clocksource stability checks for TSC.
 			Format: <string>
 			[x86] reliable: mark tsc clocksource as reliable, this
kernel/trace/trace.c +96 -9

196 lines not on this page · raw message

kernel/trace/trace.h +1 -0
index 4c7540a..ca4df2b 100644
@@ -652,6 +652,7 @@ enum trace_iterator_flags {
 	TRACE_ITER_RECORD_CMD		= 0x100000,
 	TRACE_ITER_OVERWRITE		= 0x200000,
 	TRACE_ITER_STOP_ON_FREE		= 0x400000,
+	TRACE_ITER_PRINTK_PERCPU	= 0x800000,
 };
 
 /*
Signature · 1 line
1.7.5.4
maintainer
#29 lore raw

Re: [PATCH 21/21] tracing: Add optional percpu buffers for trace_printk()

Quoted 7 lines · Steven Rostedt

Currently, trace_printk() uses a single buffer to write into to calculate the size and format needed to save the trace. To do this safely in an SMP environment, a spin_lock() is taken to only allow one writer at a time to the buffer. But this could also affect what is being traced, and add synchronization that would not be there otherwise.

so trace_printk() isn't NMI safe? #$%@^%@@$%@

maintainer
#30 lore raw

Re: [PATCH 21/21] tracing: Add optional percpu buffers for trace_printk()

In reply to Steven Rostedt
Quoted 10 lines · Peter Zijlstra
Quoted 7 lines · Steven Rostedt

Currently, trace_printk() uses a single buffer to write into to calculate the size and format needed to save the trace. To do this safely in an SMP environment, a spin_lock() is taken to only allow one writer at a time to the buffer. But this could also affect what is being traced, and add synchronization that would not be there otherwise.

so trace_printk() isn't NMI safe? #$%@^%@@$%@

better to make all of trace_printk() depend on that extra config, there is absolutely 0 point in having a broken and fully serialized trace 'fail^wfeature'.

author maintainer
#31 lore raw

Re: [PATCH 21/21] tracing: Add optional percpu buffers for trace_printk()

Quoted 11 lines · Peter Zijlstra
Quoted 10 lines · Peter Zijlstra
Quoted 7 lines · Steven Rostedt

Currently, trace_printk() uses a single buffer to write into to calculate the size and format needed to save the trace. To do this safely in an SMP environment, a spin_lock() is taken to only allow one writer at a time to the buffer. But this could also affect what is being traced, and add synchronization that would not be there otherwise.

so trace_printk() isn't NMI safe? #$%@^%@@$%@

It is NMI safe, always was (I use it there too). It has a percpu recursion detection (always has), thus if an NMI interrupts a current trace_printk(), the NMI trace_printk() will not print. I could add an NMI buffer to allow NMIs to print, but so far, we don't usually have issues with trace_printk(). Heck, I'm not sure printk() wont cause issues in NMIs. I think trace_printk() is still safer than printk.

Quoted 4 lines

better to make all of trace_printk() depend on that extra config, there is absolutely 0 point in having a broken and fully serialized trace 'fail^wfeature'.

Not, having per cpu buffers still doesn't allow NMIs to interrupt trace_printk(). Otherwise the NMI would just corrupt the current percpu buffer.

-- Steve

maintainer
#32 lore raw

Re: [PATCH 21/21] tracing: Add optional percpu buffers for trace_printk()

Quoted 11 lines · Steven Rostedt
Quoted 10 lines · Peter Zijlstra
Quoted 9 lines · Peter Zijlstra
Quoted 7 lines · Steven Rostedt

Currently, trace_printk() uses a single buffer to write into to calculate the size and format needed to save the trace. To do this safely in an SMP environment, a spin_lock() is taken to only allow one writer at a time to the buffer. But this could also affect what is being traced, and add synchronization that would not be there otherwise.

Quoted 8 lines
Quoted 1 line
Quoted 1 line

so trace_printk() isn't NMI safe? #$%@^%@@$%@

It is NMI safe, always was (I use it there too). It has a percpu recursion detection (always has), thus if an NMI interrupts a current trace_printk(), the NMI trace_printk() will not print. I could add an NMI buffer to allow NMIs to print, but so far, we don't usually have issues with trace_printk(). Heck, I'm not sure printk() wont cause issues in NMIs. I think trace_printk() is still safer than printk.

Of course, printk() is most useless, its too slow, and its definitely not NMI-safe.

If you've only got a single buffer, I don't see why you would need per-cpu recursion detection, just spin_try_lock() the thing and if you fail, bail. But that's not what the changelog said, or at least implied.

The possibility of dropping trace output like that is most worrying though. I can imagine myself tearing my hair out trying to make sense of a trace, and then wanting to kick you after finding out it lost the crucial bit.

Quoted 7 lines
Quoted 3 lines

better to make all of trace_printk() depend on that extra config, there is absolutely 0 point in having a broken and fully serialized trace 'fail^wfeature'.

Not, having per cpu buffers still doesn't allow NMIs to interrupt trace_printk(). Otherwise the NMI would just corrupt the current percpu buffer.

Multiple buffers sounds about right, not sure if you disable interrupts over the normal trace path, but ISTR you don't, so you need task/softirq/irq/nmi buffers per cpu.

Really loosing trace output is not an option, ever (aside from stuff falling of the end of the buffer). Reliability first, performance second.

author maintainer
#33 lore raw

Re: [PATCH 21/21] tracing: Add optional percpu buffers for trace_printk()

Quoted 6 lines · Peter Zijlstra

Of course, printk() is most useless, its too slow, and its definitely not NMI-safe.

If you've only got a single buffer, I don't see why you would need per-cpu recursion detection, just spin_try_lock() the thing and if you fail, bail. But that's not what the changelog said, or at least implied.

Not sure if the raw_spin_locks() had a try lock back when this was written. The recursion detection was there from day one, and has nothing to do with this patch. Which is why the changelog said nothing about it. This patch only is about not having the trace_printk() cause extra synchronization. This bit me once as trace_printk() cause a race to disappear.

Quoted 5 lines

The possibility of dropping trace output like that is most worrying though. I can imagine myself tearing my hair out trying to make sense of a trace, and then wanting to kick you after finding out it lost the crucial bit.

Understood, but NMIs are always something to be worried about causing strange issues.

Quoted 5 lines
Quoted 5 lines
Quoted 4 lines

better to make all of trace_printk() depend on that extra config, there is absolutely 0 point in having a broken and fully serialized trace 'fail^wfeature'.

Quoted 7 lines
Quoted 3 lines

Not, having per cpu buffers still doesn't allow NMIs to interrupt trace_printk(). Otherwise the NMI would just corrupt the current percpu buffer.

Multiple buffers sounds about right, not sure if you disable interrupts over the normal trace path, but ISTR you don't, so you need task/softirq/irq/nmi buffers per cpu.

trace_printk() does disable interrupts, so it is only an NMI issue.

Quoted 5 lines

Really loosing trace output is not an option, ever (aside from stuff falling of the end of the buffer). Reliability first, performance second.

Fine, then I'll add (on top of this patch) a CONFIG_TRACE_PRINTK_FULL or some such name that will create the per cpu NMI and normal buffers, which will not miss any interrupts. I just want to limit the unused memory for 99.99999% of users.

I could make the TRACE_PRINTK_FULL not even disable interrupts and have the normal/softirq/irq/nmi per cpu buffers. This will be something that would *not* be enabled in production.

-- Steve