Skip to contentSkip to conversation

tracing: Better output when ftrace_bug() is hit

PATCH New Steven Rostedt 1 participant 6 messages Nov 26, 2015

Subsystems (4)
x86 Tracing ftrace Tracing ring buffer
lore
Share & tools
lore

Steven Rostedt

author maintainer
#0 lore raw

cover tracing: Better output when ftrace_bug() is hit

Better output in ftrace_bug() for debugging when ftrace fails to modify a location. Also, removed module modifications that were left over from debugging before (rebased).

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

Head SHA1: 39daa7b9e89512f234b7fb5d55812a78318251fc

Steven Rostedt (Red Hat) (4):
ring-buffer: Process commits whenever moving to a new page.
ftrace: Add new type to distinguish what kind of ftrace_bug()
ftrace: Add variable ftrace_expected for archs to show expected code
ftrace: Show all tramps registered to a record on ftrace_bug()

Tom Zanussi (1):
tracing: Update cond flag when enabling or disabling a trigger

----

 arch/x86/kernel/ftrace.c            |  9 ++++
 include/linux/ftrace.h              | 15 ++++++
 kernel/trace/ftrace.c               | 92 ++++++++++++++++++++++++++++++++-----
 kernel/trace/ring_buffer.c          |  7 +++
 kernel/trace/trace_events_trigger.c | 10 ++--
 5 files changed, 117 insertions(+), 16 deletions(-)
author maintainer
#1 lore raw

PATCH 1/5 ring-buffer: Process commits whenever moving to a new page.

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

When crossing over to a new page, commit the current work. This will allow readers to get data with less latency, and also simplifies the work to get timestamps working for interrupted events.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/ring_buffer.c | 7 +++++++
 1 file changed, 7 insertions(+)
kernel/trace/ring_buffer.c +7 -0
index 631541a53baf..95181e36891a 100644
@@ -2129,6 +2129,8 @@ rb_reset_tail(struct ring_buffer_per_cpu *cpu_buffer,
 	local_sub(length, &tail_page->write);
 }
 
+static inline void rb_end_commit(struct ring_buffer_per_cpu *cpu_buffer);
+
 /*
  * This is the slow path, force gcc not to inline it.
  */

@@ -2220,6 +2222,11 @@ rb_move_tail(struct ring_buffer_per_cpu *cpu_buffer,
 
 	rb_reset_tail(cpu_buffer, tail, info);
 
+	/* Commit what we have for now. */
+	rb_end_commit(cpu_buffer);
+	/* rb_end_commit() decs committing */
+	local_inc(&cpu_buffer->committing);
+
 	/* fail and let the caller try again */
 	return ERR_PTR(-EAGAIN);
Signature · 1 line
2.6.1
author maintainer
#2 lore raw

PATCH 2/5 tracing: Update cond flag when enabling or disabling a trigger

In reply to Steven Rostedt

From: Tom Zanussi <[email protected]>

When a trigger is enabled, the cond flag should be set beforehand, otherwise a trigger that's expecting to process a trace record (e.g. one with post_trigger set) could be invoked without one.

Likewise a trigger's cond flag should be reset after it's disabled, not before.

Link http://lkml.kernel.org/r/a420b52a67b1c2d3cab017914362d153255acb99.1448303214.git.tom.zanussi@linux.intel.com open here
Signed-off-by Tom Zanussi <[email protected]>
Signed-off-by Daniel Wagner <[email protected]>
Reviewed-by Masami Hiramatsu <[email protected]>
Reviewed-by Namhyung Kim <[email protected]>
Tested-by Masami Hiramatsu <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/trace_events_trigger.c | 10 ++++++----
 1 file changed, 6 insertions(+), 4 deletions(-)
kernel/trace/trace_events_trigger.c +6 -4
index 42a4009fd75a..4d2f3ccc56f6 100644
@@ -543,11 +543,12 @@ static int register_trigger(char *glob, struct event_trigger_ops *ops,
 	list_add_rcu(&data->list, &file->triggers);
 	ret++;
 
+	update_cond_flag(file);
 	if (trace_event_trigger_enable_disable(file, 1) < 0) {
 		list_del_rcu(&data->list);
+		update_cond_flag(file);
 		ret--;
 	}
-	update_cond_flag(file);
 out:
 	return ret;
 }

@@ -575,8 +576,8 @@ static void unregister_trigger(char *glob, struct event_trigger_ops *ops,
 		if (data->cmd_ops->trigger_type == test->cmd_ops->trigger_type) {
 			unregistered = true;
 			list_del_rcu(&data->list);
-			update_cond_flag(file);
 			trace_event_trigger_enable_disable(file, 0);
+			update_cond_flag(file);
 			break;
 		}
 	}

@@ -1319,11 +1320,12 @@ static int event_enable_register_trigger(char *glob,
 	list_add_rcu(&data->list, &file->triggers);
 	ret++;
 
+	update_cond_flag(file);
 	if (trace_event_trigger_enable_disable(file, 1) < 0) {
 		list_del_rcu(&data->list);
+		update_cond_flag(file);
 		ret--;
 	}
-	update_cond_flag(file);
 out:
 	return ret;
 }

@@ -1344,8 +1346,8 @@ static void event_enable_unregister_trigger(char *glob,
 		    (enable_data->file == test_enable_data->file)) {
 			unregistered = true;
 			list_del_rcu(&data->list);
-			update_cond_flag(file);
 			trace_event_trigger_enable_disable(file, 0);
+			update_cond_flag(file);
 			break;
 		}
 	}
Signature · 1 line
2.6.1
author maintainer
#3 lore raw

PATCH 3/5 ftrace: Add new type to distinguish what kind of ftrace_bug()

In reply to Steven Rostedt

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

The ftrace function hook utility has several internal checks to make sure that whatever it modifies is exactly what it expects to be modifying. This is essential as modifying running code can be extremely dangerous to the system.

When an anomaly is detected, ftrace_bug() is called which sends a splat to the console and disables function tracing. There's some extra information that is printed to help diagnose the issue.

One thing that is missing though is output of what ftrace was doing at the time of the crash. Was it updating a call site or perhaps converting a call site to a nop? A new global enum variable is created to state what ftrace was doing at the time of the anomaly, and this is reported in ftrace_bug().

Signed-off-by Steven Rostedt <[email protected]>
---
 include/linux/ftrace.h |  9 +++++++++
 kernel/trace/ftrace.c  | 37 ++++++++++++++++++++++++++++++++++++-
 2 files changed, 45 insertions(+), 1 deletion(-)
include/linux/ftrace.h +9 -0
index eae6548efbf0..870c8eea38cd 100644
@@ -296,6 +296,15 @@ int ftrace_arch_code_modify_post_process(void);
 
 struct dyn_ftrace;
 
+enum ftrace_bug_type {
+	FTRACE_BUG_UNKNOWN,
+	FTRACE_BUG_INIT,
+	FTRACE_BUG_NOP,
+	FTRACE_BUG_CALL,
+	FTRACE_BUG_UPDATE,
+};
+extern enum ftrace_bug_type ftrace_bug_type;
+
 void ftrace_bug(int err, struct dyn_ftrace *rec);
 
 struct seq_file;
kernel/trace/ftrace.c +36 -1
index 3f743b147247..b95efcac9dfe 100644
@@ -1953,6 +1953,28 @@ static void print_ip_ins(const char *fmt, unsigned char *p)
 static struct ftrace_ops *
 ftrace_find_tramp_ops_any(struct dyn_ftrace *rec);
 
+enum ftrace_bug_type ftrace_bug_type;
+
+static void print_bug_type(void)
+{
+	switch (ftrace_bug_type) {
+	case FTRACE_BUG_UNKNOWN:
+		break;
+	case FTRACE_BUG_INIT:
+		pr_info("Initializing ftrace call sites\n");
+		break;
+	case FTRACE_BUG_NOP:
+		pr_info("Setting ftrace call site to NOP\n");
+		break;
+	case FTRACE_BUG_CALL:
+		pr_info("Setting ftrace call site to call ftrace function\n");
+		break;
+	case FTRACE_BUG_UPDATE:
+		pr_info("Updating ftrace call site to call a different ftrace function\n");
+		break;
+	}
+}
+
 /**
  * ftrace_bug - report and shutdown function tracer
  * @failed: The failed type (EFAULT, EINVAL, EPERM)

@@ -1992,6 +2014,7 @@ void ftrace_bug(int failed, struct dyn_ftrace *rec)
 		pr_info("ftrace faulted on unknown error ");
 		print_ip_sym(ip);
 	}
+	print_bug_type();
 	if (rec) {
 		struct ftrace_ops *ops = NULL;
 

@@ -2016,6 +2039,8 @@ static int ftrace_check_record(struct dyn_ftrace *rec, int enable, int update)
 {
 	unsigned long flag = 0UL;
 
+	ftrace_bug_type = FTRACE_BUG_UNKNOWN;
+
 	/*
 	 * If we are updating calls:
 	 *

@@ -2077,9 +2102,12 @@ static int ftrace_check_record(struct dyn_ftrace *rec, int enable, int update)
 		 *   from the save regs, to a non-save regs function or
 		 *   vice versa, or from a trampoline call.
 		 */
-		if (flag & FTRACE_FL_ENABLED)
+		if (flag & FTRACE_FL_ENABLED) {
+			ftrace_bug_type = FTRACE_BUG_CALL;
 			return FTRACE_UPDATE_MAKE_CALL;
+		}
 
+		ftrace_bug_type = FTRACE_BUG_UPDATE;
 		return FTRACE_UPDATE_MODIFY_CALL;
 	}
 

@@ -2096,6 +2124,7 @@ static int ftrace_check_record(struct dyn_ftrace *rec, int enable, int update)
 					FTRACE_FL_REGS_EN);
 	}
 
+	ftrace_bug_type = FTRACE_BUG_NOP;
 	return FTRACE_UPDATE_MAKE_NOP;
 }
 

@@ -2307,17 +2336,22 @@ __ftrace_replace_code(struct dyn_ftrace *rec, int enable)
 
 	ret = ftrace_update_record(rec, enable);
 
+	ftrace_bug_type = FTRACE_BUG_UNKNOWN;
+
 	switch (ret) {
 	case FTRACE_UPDATE_IGNORE:
 		return 0;
 
 	case FTRACE_UPDATE_MAKE_CALL:
+		ftrace_bug_type = FTRACE_BUG_CALL;
 		return ftrace_make_call(rec, ftrace_addr);
 
 	case FTRACE_UPDATE_MAKE_NOP:
+		ftrace_bug_type = FTRACE_BUG_NOP;
 		return ftrace_make_nop(NULL, rec, ftrace_old_addr);
 
 	case FTRACE_UPDATE_MODIFY_CALL:
+		ftrace_bug_type = FTRACE_BUG_UPDATE;
 		return ftrace_modify_call(rec, ftrace_old_addr, ftrace_addr);
 	}
 

@@ -2425,6 +2459,7 @@ ftrace_code_disable(struct module *mod, struct dyn_ftrace *rec)
 
 	ret = ftrace_make_nop(mod, rec, MCOUNT_ADDR);
 	if (ret) {
+		ftrace_bug_type = FTRACE_BUG_INIT;
 		ftrace_bug(ret, rec);
 		return 0;
 	}
Signature · 1 line
2.6.1
author maintainer
#4 lore raw

PATCH 4/5 ftrace: Add variable ftrace_expected for archs to show expected code

In reply to Steven Rostedt

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

When an anomaly is found while modifying function code, ftrace_bug() is called which disables the function tracing infrastructure and reports information about what failed. If the code that is to be replaced does not match what is expected, then actual code is shown. Currently there is no arch generic way to show what was expected.

Add a new variable pointer calld ftrace_expected that the arch code can set to point to what it expected so that ftrace_bug() can report the actual text as well as the text that was expected to be there.

Signed-off-by Steven Rostedt <[email protected]>
---
 arch/x86/kernel/ftrace.c | 9 +++++++++
 include/linux/ftrace.h   | 6 ++++++
 kernel/trace/ftrace.c    | 9 +++++++--
 3 files changed, 22 insertions(+), 2 deletions(-)
arch/x86/kernel/ftrace.c +9 -0
index 311bcf338f07..909da012406d 100644
@@ -105,6 +105,8 @@ ftrace_modify_code_direct(unsigned long ip, unsigned const char *old_code,
 {
 	unsigned char replaced[MCOUNT_INSN_SIZE];
 
+	ftrace_expected = old_code;
+
 	/*
 	 * Note: Due to modules and __init, code can
 	 *  disappear and change, we need to protect against faulting

@@ -154,6 +156,8 @@ int ftrace_make_nop(struct module *mod,
 	if (addr == MCOUNT_ADDR)
 		return ftrace_modify_code_direct(rec->ip, old, new);
 
+	ftrace_expected = NULL;
+
 	/* Normal cases use add_brk_on_nop */
 	WARN_ONCE(1, "invalid use of ftrace_make_nop");
 	return -EINVAL;

@@ -220,6 +224,7 @@ int ftrace_modify_call(struct dyn_ftrace *rec, unsigned long old_addr,
 				 unsigned long addr)
 {
 	WARN_ON(1);
+	ftrace_expected = NULL;
 	return -EINVAL;
 }
 

@@ -314,6 +319,8 @@ static int add_break(unsigned long ip, const char *old)
 	if (probe_kernel_read(replaced, (void *)ip, MCOUNT_INSN_SIZE))
 		return -EFAULT;
 
+	ftrace_expected = old;
+
 	/* Make sure it is what we expect it to be */
 	if (memcmp(replaced, old, MCOUNT_INSN_SIZE) != 0)
 		return -EINVAL;

@@ -413,6 +420,8 @@ static int remove_breakpoint(struct dyn_ftrace *rec)
 		ftrace_addr = ftrace_get_addr_curr(rec);
 		nop = ftrace_call_replace(ip, ftrace_addr);
 
+		ftrace_expected = nop;
+
 		if (memcmp(&ins[1], &nop[1], MCOUNT_INSN_SIZE - 1) != 0)
 			return -EINVAL;
 	}
include/linux/ftrace.h +6 -0
index 870c8eea38cd..134f8d45b35b 100644
@@ -305,6 +305,12 @@ enum ftrace_bug_type {
 };
 extern enum ftrace_bug_type ftrace_bug_type;
 
+/*
+ * Archs can set this to point to a variable that holds the value that was
+ * expected at the call site before calling ftrace_bug().
+ */
+extern const void *ftrace_expected;
+
 void ftrace_bug(int err, struct dyn_ftrace *rec);
 
 struct seq_file;
kernel/trace/ftrace.c +7 -2
index b95efcac9dfe..7870c03b4c4d 100644
@@ -1940,7 +1940,7 @@ static int ftrace_hash_ipmodify_update(struct ftrace_ops *ops,
 	return __ftrace_hash_update_ipmodify(ops, old_hash, new_hash);
 }
 
-static void print_ip_ins(const char *fmt, unsigned char *p)
+static void print_ip_ins(const char *fmt, const unsigned char *p)
 {
 	int i;
 

@@ -1954,6 +1954,7 @@ static struct ftrace_ops *
 ftrace_find_tramp_ops_any(struct dyn_ftrace *rec);
 
 enum ftrace_bug_type ftrace_bug_type;
+const void *ftrace_expected;
 
 static void print_bug_type(void)
 {

@@ -2001,8 +2002,12 @@ void ftrace_bug(int failed, struct dyn_ftrace *rec)
 		FTRACE_WARN_ON_ONCE(1);
 		pr_info("ftrace failed to modify ");
 		print_ip_sym(ip);
-		print_ip_ins(" actual: ", (unsigned char *)ip);
+		print_ip_ins(" actual:   ", (unsigned char *)ip);
 		pr_cont("\n");
+		if (ftrace_expected) {
+			print_ip_ins(" expected: ", ftrace_expected);
+			pr_cont("\n");
+		}
 		break;
 	case -EPERM:
 		FTRACE_WARN_ON_ONCE(1);
Signature · 1 line
2.6.1
author maintainer
#5 lore raw

PATCH 5/5 ftrace: Show all tramps registered to a record on ftrace_bug()

In reply to Steven Rostedt

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

When an anomaly is detected in the function call modification code, ftrace_bug() is called to disable function tracing as well as give any information that may help debug the problem. Currently, only the first found trampoline that is attached to the failed record is reported. Instead, show all trampolines that are hooked to it.

Also, not only show the ops pointer but also report the function it calls.

While at it, add this info to the enabled_functions debug file too.

Signed-off-by Steven Rostedt <[email protected]>
---
 kernel/trace/ftrace.c | 46 +++++++++++++++++++++++++++++++++++++---------
 1 file changed, 37 insertions(+), 9 deletions(-)
kernel/trace/ftrace.c +37 -9
index 7870c03b4c4d..e371aed51fcf 100644
@@ -1952,6 +1952,8 @@ static void print_ip_ins(const char *fmt, const unsigned char *p)
 
 static struct ftrace_ops *
 ftrace_find_tramp_ops_any(struct dyn_ftrace *rec);
+static struct ftrace_ops *
+ftrace_find_tramp_ops_next(struct dyn_ftrace *rec, struct ftrace_ops *ops);
 
 enum ftrace_bug_type ftrace_bug_type;
 const void *ftrace_expected;

@@ -2028,15 +2030,19 @@ void ftrace_bug(int failed, struct dyn_ftrace *rec)
 			rec->flags & FTRACE_FL_REGS ? " R" : "  ");
 		if (rec->flags & FTRACE_FL_TRAMP_EN) {
 			ops = ftrace_find_tramp_ops_any(rec);
-			if (ops)
-				pr_cont("\ttramp: %pS",
-					(void *)ops->trampoline);
-			else
+			if (ops) {
+				do {
+					pr_cont("\ttramp: %pS (%pS)",
+						(void *)ops->trampoline,
+						(void *)ops->func);
+					ops = ftrace_find_tramp_ops_next(rec, ops);
+				} while (ops);
+			} else
 				pr_cont("\ttramp: ERROR!");
 
 		}
 		ip = ftrace_get_addr_curr(rec);
-		pr_cont(" expected tramp: %lx\n", ip);
+		pr_cont("\n expected tramp: %lx\n", ip);
 	}
 }
 

@@ -2179,6 +2185,24 @@ ftrace_find_tramp_ops_any(struct dyn_ftrace *rec)
 }
 
 static struct ftrace_ops *
+ftrace_find_tramp_ops_next(struct dyn_ftrace *rec,
+			   struct ftrace_ops *op)
+{
+	unsigned long ip = rec->ip;
+
+	while_for_each_ftrace_op(op) {
+
+		if (!op->trampoline)
+			continue;
+
+		if (hash_contains_ip(ip, op->func_hash))
+			return op;
+	} 
+
+	return NULL;
+}
+
+static struct ftrace_ops *
 ftrace_find_tramp_ops_curr(struct dyn_ftrace *rec)
 {
 	struct ftrace_ops *op;

@@ -3306,10 +3330,14 @@ static int t_show(struct seq_file *m, void *v)
 			   rec->flags & FTRACE_FL_IPMODIFY ? " I" : "  ");
 		if (rec->flags & FTRACE_FL_TRAMP_EN) {
 			ops = ftrace_find_tramp_ops_any(rec);
-			if (ops)
-				seq_printf(m, "\ttramp: %pS",
-					   (void *)ops->trampoline);
-			else
+			if (ops) {
+				do {
+					seq_printf(m, "\ttramp: %pS (%pS)",
+						   (void *)ops->trampoline,
+						   (void *)ops->func);
+					ops = ftrace_find_tramp_ops_next(rec, ops);
+				} while (ops);
+			} else
 				seq_puts(m, "\ttramp: ERROR!");
 
 		}
Signature · 1 line
2.6.1