Skip to contentSkip to conversation

tracing: Updates for 3.19

PATCH New Steven Rostedt 1 participant 6 messages Dec 3, 2014

Subsystems (3)
lore
Share & tools
lore

Steven Rostedt

author maintainer
#0 lore raw

cover tracing: Updates for 3.19

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next

Head SHA1: 3558a5ac50dbb2419cc649d5e154af161d661037

Byungchul Park (1):
tracing: Add additional marks to signal very large time deltas

Dan Carpenter (1):
tracing: Truncated output is better than nothing

Joonsoo Kim (1):
Documentation: describe trace_buf_size parameter more accurately

Steven Rostedt (Red Hat) (2):
tracing: Add NOT to filtering logic
tracing: Allow NOT to filter AND and OR clauses

----

 Documentation/kernel-parameters.txt  |  2 +-
 Documentation/trace/ftrace.txt       | 10 +++++++---
 kernel/trace/trace.c                 |  7 ++-----
 kernel/trace/trace.h                 |  2 ++
 kernel/trace/trace_events_filter.c   | 29 +++++++++++++++++++++++------
 kernel/trace/trace_functions_graph.c | 23 +++--------------------
 kernel/trace/trace_output.c          | 34 +++++++++++++++++++++++++++++-----
 7 files changed, 67 insertions(+), 40 deletions(-)
author maintainer
#1 lore raw

PATCH 1/5 tracing: Add NOT to filtering logic

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

Ted noticed that he could not filter on an event for a bit being cleared. That's because the filtering logic only tests event fields with a limited number of comparisons which, for bit logic, only include "&", which can test if a bit is set, but there's no good way to see if a bit is clear.

This adds a way to do: !(field & 2048)

Which returns true if the bit is not set, and false otherwise.

Note, currently !(field1 == 10 && field2 == 15) is not supported. That is, the 'not' only works for direct comparisons, not for the AND and OR logic.

---
 kernel/trace/trace_events_filter.c | 20 ++++++++++++++++++--
 1 file changed, 18 insertions(+), 2 deletions(-)
kernel/trace/trace_events_filter.c +18 -2
index 7a8c1528e141..e6a33db83856 100644
@@ -45,6 +45,7 @@ enum filter_op_ids
 	OP_GT,
 	OP_GE,
 	OP_BAND,
+	OP_NOT,
 	OP_NONE,
 	OP_OPEN_PAREN,
 };
@@ -67,6 +68,7 @@ static struct filter_op filter_ops[] = {
 	{ OP_GT,	">",		5 },
 	{ OP_GE,	">=",		5 },
 	{ OP_BAND,	"&",		6 },
+	{ OP_NOT,	"!",		6 },
 	{ OP_NONE,	"OP_NONE",	0 },
 	{ OP_OPEN_PAREN, "(",		0 },
 };
@@ -85,6 +87,7 @@ enum {
 	FILT_ERR_MISSING_FIELD,
 	FILT_ERR_INVALID_FILTER,
 	FILT_ERR_IP_FIELD_ONLY,
+	FILT_ERR_ILLEGAL_NOT_OP,
 };
 
 static char *err_text[] = {
@@ -101,6 +104,7 @@ static char *err_text[] = {
 	"Missing field name and/or value",
 	"Meaningless filter expression",
 	"Only 'ip' field is supported for function trace",
+	"Illegal use of '!'",
 };
 
 struct opstack_op {
@@ -139,6 +143,7 @@ struct pred_stack {
 	int			index;
 };
 
+/* If not of not match is equal to not of not, then it is a match */
 #define DEFINE_COMPARISON_PRED(type)					\
 static int filter_pred_##type(struct filter_pred *pred, void *event)	\
 {									\
@@ -166,7 +171,7 @@ static int filter_pred_##type(struct filter_pred *pred, void *event)	\
 		break;							\
 	}								\
 									\
-	return match;							\
+	return !!match == !pred->not;					\
 }
 
 #define DEFINE_EQUALITY_PRED(size)					\
@@ -1028,7 +1033,7 @@ static int init_pred(struct filter_parse_state *ps,
 	}
 
 	if (pred->op == OP_NE)
-		pred->not = 1;
+		pred->not ^= 1;
 
 	pred->fn = fn;
 	return 0;
@@ -1590,6 +1595,17 @@ static int replace_preds(struct ftrace_event_call *call,
 			continue;
 		}
 
+		if (elt->op == OP_NOT) {
+			if (!n_preds || operand1 || operand2) {
+				parse_error(ps, FILT_ERR_ILLEGAL_NOT_OP, 0);
+				err = -EINVAL;
+				goto fail;
+			}
+			if (!dry_run)
+				filter->preds[n_preds - 1].not ^= 1;
+			continue;
+		}
+
 		if (WARN_ON(n_preds++ == MAX_FILTER_PRED)) {
 			parse_error(ps, FILT_ERR_TOO_MANY_PREDS, 0);
 			err = -ENOSPC;
Signature · 1 line
2.1.3
author maintainer
#2 lore raw

PATCH 2/5 tracing: Allow NOT to filter AND and OR clauses

In reply to Steven Rostedt

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

Add support to allow not "!" for and (&&) and (||). That is:

!(field1 == X && field2 == Y)

Where the value of the full clause will be notted.

---
 kernel/trace/trace_events_filter.c | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)
kernel/trace/trace_events_filter.c +5 -4
index e6a33db83856..ced69da0ff55 100644
@@ -489,9 +489,10 @@ static int process_ops(struct filter_pred *preds,
 		if (!WARN_ON_ONCE(!pred->fn))
 			match = pred->fn(pred, rec);
 		if (!!match == type)
-			return match;
+			break;
 	}
-	return match;
+	/* If not of not match is equal to not of not, then it is a match */
+	return !!match == !op->not;
 }
 
 struct filter_match_preds_data {
@@ -740,10 +741,10 @@ static int filter_set_pred(struct event_filter *filter,
 		 * then this op can be folded.
 		 */
 		if (left->index & FILTER_PRED_FOLD &&
-		    (left->op == dest->op ||
+		    ((left->op == dest->op && !left->not) ||
 		     left->left == FILTER_PRED_INVALID) &&
 		    right->index & FILTER_PRED_FOLD &&
-		    (right->op == dest->op ||
+		    ((right->op == dest->op && !right->not) ||
 		     right->left == FILTER_PRED_INVALID))
 			dest->index |= FILTER_PRED_FOLD;
 
Signature · 1 line
2.1.3
author maintainer
#3 lore raw

PATCH 3/5 Documentation: describe trace_buf_size parameter more accurately

In reply to Steven Rostedt

From: Joonsoo Kim <[email protected]>

I'm stuck into panic that too litte free memory is left when I boot with trace_buf_size parameter. After digging into the problem, I found that trace_buf_size is the size of trace buffer on each cpu rather than total size of trace buffer. To prevent victim like me, change description of trace_buf_size parameter more accurately.

---
 Documentation/kernel-parameters.txt | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
Documentation/kernel-parameters.txt +1 -1
index 7dbe5ec9d9cd..1d09eb37c562 100644
@@ -3477,7 +3477,7 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
 			are saved.
 
 	trace_buf_size=nn[KMG]
-			[FTRACE] will set tracing buffer size.
+			[FTRACE] will set tracing buffer size on each cpu.
 
 	trace_event=[event-list]
 			[FTRACE] Set and start specified trace events in order
Signature · 1 line
2.1.3
author maintainer
#4 lore raw

PATCH 4/5 tracing: Add additional marks to signal very large time deltas

In reply to Steven Rostedt

From: Byungchul Park <[email protected]>

Currently, function graph tracer prints "!" or "+" just before function execution time to signal a function overhead, depending on the time. And some tracers tracing latency also print "!" or "+" just after time to signal overhead, depending on the interval between events. Even it is usually enough to do that, we sometimes need to signal for bigger execution time than 100 micro seconds.

For example, I used function graph tracer to detect if there is any case that exit_mm() takes too much time. I did following steps in /sys/kernel/debug/tracing. It was easier to detect very large excution time with patched kernel than with original kernel.

$ echo exit_mm > set_graph_function
$ echo function_graph > current_tracer
$ echo > trace
$ cat trace_pipe > $LOGFILE
 ... (do something and terminate logging)
$ grep "\\$" $LOGFILE
 3) $ 22082032 us |                      } /* kernel_map_pages */
 3) $ 22082040 us |                    } /* free_pages_prepare */
 3) $ 22082113 us |                  } /* free_hot_cold_page */
 3) $ 22083455 us |                } /* free_hot_cold_page_list */
 3) $ 22083895 us |              } /* release_pages */
 3) $ 22177873 us |            } /* free_pages_and_swap_cache */
 3) $ 22178929 us |          } /* unmap_single_vma */
 3) $ 22198885 us |        } /* unmap_vmas */
 3) $ 22206949 us |      } /* exit_mmap */
 3) $ 22207659 us |    } /* mmput */
 3) $ 22207793 us |  } /* exit_mm */

And then, it was easy to find out that a schedule-out occured by sub_preempt_count() within kernel_map_pages().

To detect very large function exection time caused by either problematic function implementation or scheduling issues, this patch can be useful.

---
 Documentation/trace/ftrace.txt       | 10 +++++++---
 kernel/trace/trace.h                 |  2 ++
 kernel/trace/trace_functions_graph.c | 23 +++--------------------
 kernel/trace/trace_output.c          | 34 +++++++++++++++++++++++++++++-----
 4 files changed, 41 insertions(+), 28 deletions(-)
Documentation/trace/ftrace.txt +7 -3
index f10f5f5d260d..8408e040f06f 100644
@@ -685,9 +685,11 @@ The above is mostly meaningful for kernel developers.
 	 needs to be fixed to be only relative to the same CPU.
 	 The marks are determined by the difference between this
 	 current trace and the next trace.
-	  '!' - greater than preempt_mark_thresh (default 100)
-	  '+' - greater than 1 microsecond
-	  ' ' - less than or equal to 1 microsecond.
+	  '$' - greater than 1 second
+	  '#' - greater than 1000 microsecond
+	  '!' - greater than 100 microsecond
+	  '+' - greater than 10 microsecond
+	  ' ' - less than or equal to 10 microsecond.
 
   The rest is the same as the 'trace' file.
 
@@ -1956,6 +1958,8 @@ want, depending on your needs.
 
   + means that the function exceeded 10 usecs.
   ! means that the function exceeded 100 usecs.
+  # means that the function exceeded 1000 usecs.
+  $ means that the function exceeded 1 sec.
 
 
 - The task/pid field displays the thread cmdline and pid which
kernel/trace/trace.h +2 -0
index c3a37e55ec8b..3255dfb054a0 100644
@@ -708,6 +708,8 @@ enum print_line_t print_trace_line(struct trace_iterator *iter);
 
 extern unsigned long trace_flags;
 
+extern char trace_find_mark(unsigned long long duration);
+
 /* Standard output formatting function used for function return traces */
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 
kernel/trace/trace_functions_graph.c +3 -20
index 100288d10e1f..6c2ab955018c 100644
@@ -730,8 +730,6 @@ static void
 print_graph_duration(unsigned long long duration, struct trace_seq *s,
 		     u32 flags)
 {
-	bool duration_printed = false;
-
 	if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
 	    !(trace_flags & TRACE_ITER_CONTEXT_INFO))
 		return;
@@ -750,24 +748,9 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,
 	}
 
 	/* Signal a overhead of time execution to the output */
-	if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
-		/* Duration exceeded 100 usecs */
-		if (duration > 100000ULL) {
-			trace_seq_puts(s, "! ");
-			duration_printed = true;
-
-		/* Duration exceeded 10 usecs */
-		} else if (duration > 10000ULL) {
-			trace_seq_puts(s, "+ ");
-			duration_printed = true;
-		}
-	}
-
-	/*
-	 * If we did not exceed the duration tresholds or we dont want
-	 * to print out the overhead. Either way we need to fill out the space.
-	 */
-	if (!duration_printed)
+	if (flags & TRACE_GRAPH_PRINT_OVERHEAD)
+		trace_seq_printf(s, "%c ", trace_find_mark(duration));
+	else
 		trace_seq_puts(s, "  ");
 
 	trace_print_graph_duration(duration, s);
kernel/trace/trace_output.c +29 -5
index 723818bc83b4..b77b9a697619 100644
@@ -115,7 +115,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 
 	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%lx", val);
-		
+
 	trace_seq_putc(p, 0);
 
 	return ret;
@@ -443,7 +443,32 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu)
 	return trace_print_lat_fmt(s, entry);
 }
 
-static unsigned long preempt_mark_thresh_us = 100;
+#undef MARK
+#define MARK(v, s) {.val = v, .sym = s}
+/* trace overhead mark */
+static const struct trace_mark {
+	unsigned long long	val; /* unit: nsec */
+	char			sym;
+} mark[] = {
+	MARK(1000000000ULL	, '$'), /* 1 sec */
+	MARK(1000000ULL		, '#'), /* 1000 usecs */
+	MARK(100000ULL		, '!'), /* 100 usecs */
+	MARK(10000ULL		, '+'), /* 10 usecs */
+};
+#undef MARK
+
+char trace_find_mark(unsigned long long d)
+{
+	int i;
+	int size = ARRAY_SIZE(mark);
+
+	for (i = 0; i < size; i++) {
+		if (d >= mark[i].val)
+			break;
+	}
+
+	return (i == size) ? ' ' : mark[i].sym;
+}
 
 static int
 lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
@@ -480,8 +505,7 @@ lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
 		trace_seq_printf(
 			s, " %4lldus%c: ",
 			abs_ts,
-			rel_ts > preempt_mark_thresh_us ? '!' :
-			rel_ts > 1 ? '+' : ' ');
+			trace_find_mark(rel_ts * NSEC_PER_USEC));
 
 	} else { /* !verbose && !in_ns */
 		trace_seq_printf(s, " %4lld: ", abs_ts);
@@ -663,7 +687,7 @@ int register_ftrace_event(struct trace_event *event)
 				goto out;
 
 		} else {
-			
+
 			event->type = next_event_type++;
 			list = &ftrace_event_list;
 		}
Signature · 1 line
2.1.3
author maintainer
#5 lore raw

PATCH 5/5 tracing: Truncated output is better than nothing

In reply to Steven Rostedt

From: Dan Carpenter <[email protected]>

The initial reason for this patch is that I noticed that:

if (len > TRACE_BUF_SIZE)

is off by one. In this code, if len == TRACE_BUF_SIZE, then it means we have truncated the last character off the output string. If we truncate two or more characters then we exit without printing.

After some discussion, we decided that printing truncated data is better than not printing at all so we should just use vscnprintf() and remove the test entirely. Also I have updated memcpy() to copy the NUL char instead of setting the NUL in a separate step.

---
 kernel/trace/trace.c | 7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)
kernel/trace/trace.c +2 -5
index 3ce3c4ccfc94..4ceb2546c7ef 100644
@@ -2158,9 +2158,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 		goto out;
 	}
 
-	len = vsnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
-	if (len > TRACE_BUF_SIZE)
-		goto out;
+	len = vscnprintf(tbuffer, TRACE_BUF_SIZE, fmt, args);
 
 	local_save_flags(flags);
 	size = sizeof(*entry) + len + 1;
@@ -2171,8 +2169,7 @@ __trace_array_vprintk(struct ring_buffer *buffer,
 	entry = ring_buffer_event_data(event);
 	entry->ip = ip;
 
-	memcpy(&entry->buf, tbuffer, len);
-	entry->buf[len] = '\0';
+	memcpy(&entry->buf, tbuffer, len + 1);
 	if (!call_filter_check_discard(call, entry, buffer, event)) {
 		__buffer_unlock_commit(buffer, event);
 		ftrace_trace_stack(buffer, flags, 6, pc);
Signature · 1 line
2.1.3