ftrace: distinguish kretprobe'd functions in trace logs

PATCH Applied Abhishek Sagar 3 participants 10 messages May 27, 2008 – Nov 3, 2008 Tracing

lore

Share & tools

lore

Abhishek Sagar

author

2008-05-27 18:34 UTC #0 lore raw

PATCH 1/1 ftrace: distinguish kretprobe'd functions in trace logs

Hi Steven,

Tracing functions via ftrace which have a kretprobe installed on them, can produce misleading output in their trace logs. E.g, consider the correct trace of the following sequence:

do_IRQ()
{
~
irq_enter();
~
}

Trace log (sample):
<idle>-0 [00] 4154504455.781616: irq_enter <- do_IRQ

But if irq_enter() has a kretprobe installed on it, the return value stored on the stack at each invocation is modified to divert the return to a kprobe trampoline function called kretprobe_trampoline(). So with this the trace would (currently) look like:

<idle>-0 [00] 4154504455.781616: irq_enter <- kretprobe_trampoline

Now this is quite misleading to the end user, as it suggests something that didn't actually happen. So just to avoid such misinterpretations, the inlined patch aims to output such a log as:

<idle>-0 [00] 4154504455.781616: irq_enter <- [unknown/kretprobe'd]

Signed-off-by Abhishek Sagar <[email protected]>

---

kernel/trace/trace.c +24 -3

index 0feae23..12f5e81 100644
@@ -27,6 +27,7 @@
 #include <linux/poll.h>
 #include <linux/gfp.h>
 #include <linux/fs.h>
+#include <linux/kprobes.h>
 #include <linux/writeback.h>
 
 #include <linux/stacktrace.h>

@@ -1199,6 +1200,20 @@ static void s_stop(struct seq_file *m, void *p)
 	mutex_unlock(&trace_types_lock);
 }
 
+#define KRETPROBE_MSG "[unknown/kretprobe'd]"
+
+#ifdef CONFIG_KRETPROBES
+static inline int kretprobed(unsigned long addr)
+{
+	return addr == (unsigned long)kretprobe_trampoline;
+}
+#else
+static inline int kretprobed(unsigned long addr)
+{
+	return 0;
+}
+#endif /* CONFIG_KRETPROBES */
+
 static int
 seq_print_sym_short(struct trace_seq *s, const char *fmt, unsigned long address)
 {

@@ -1434,7 +1449,10 @@ print_lat_fmt(struct trace_iterator *iter, unsigned int trace_idx, int cpu)
 	case TRACE_FN:
 		seq_print_ip_sym(s, entry->fn.ip, sym_flags);
 		trace_seq_puts(s, " (");
-		seq_print_ip_sym(s, entry->fn.parent_ip, sym_flags);
+		if (kretprobed(entry->fn.parent_ip))
+			trace_seq_puts(s, KRETPROBE_MSG);
+		else
+			seq_print_ip_sym(s, entry->fn.parent_ip, sym_flags);
 		trace_seq_puts(s, ")\n");
 		break;
 	case TRACE_CTX:

@@ -1514,8 +1532,11 @@ static int print_trace_fmt(struct trace_iterator *iter)
 			ret = trace_seq_printf(s, " <-");
 			if (!ret)
 				return 0;
-			ret = seq_print_ip_sym(s, entry->fn.parent_ip,
-					       sym_flags);
+			if (kretprobed(entry->fn.parent_ip))
+				ret = trace_seq_puts(s, KRETPROBE_MSG);
+			else
+				ret = seq_print_ip_sym(s, entry->fn.parent_ip,
+						       sym_flags);
 			if (!ret)
 				return 0;
 		}

Steven Rostedt

maintainer Acked-by on v1 1/1

2008-05-27 18:48 UTC #1 lore raw

Quoted 11 lines · Abhishek Sagar

But if irq_enter() has a kretprobe installed on it, the return value stored on the stack at each invocation is modified to divert the return to a kprobe trampoline function called kretprobe_trampoline(). So with this the trace would (currently) look like:
<idle>-0 [00] 4154504455.781616: irq_enter <- kretprobe_trampoline
Now this is quite misleading to the end user, as it suggests something that didn't actually happen. So just to avoid such misinterpretations, the inlined patch aims to output such a log as:
<idle>-0 [00] 4154504455.781616: irq_enter <- [unknown/kretprobe'd]
Signed-off-by Abhishek Sagar <[email protected]>

Thanks Abhishek,

Acked-by Steven Rostedt <[email protected]>

-- Steve

Ingo Molnar

Applied

2008-06-02 10:42 UTC #2 lore raw

Quoted 8 lines · Steven Rostedt

Quoted 7 lines · Abhishek Sagar
But if irq_enter() has a kretprobe installed on it, the return value stored on the stack at each invocation is modified to divert the return to a kprobe trampoline function called kretprobe_trampoline(). So with this the trace would (currently) look like:
<idle>-0 [00] 4154504455.781616: irq_enter <- kretprobe_trampoline
Now this is quite misleading to the end user, as it suggests something that didn't actually happen. So just to avoid such misinterpretations, the inlined patch aims to output such a log as:

Quoted 8 lines

Quoted 4 lines
<idle>-0 [00] 4154504455.781616: irq_enter <- [unknown/kretprobe'd]
Signed-off-by Abhishek Sagar <[email protected]>
Thanks Abhishek,
Acked-by Steven Rostedt <[email protected]>

applied to tip/tracing/ftrace, thanks.

Ingo

Steven Rostedt

maintainer

2008-10-31 02:30 UTC #3 lore raw

In reply to Abhishek Sagar

Quoted 25 lines · Abhishek Sagar

Hi Steven,
Tracing functions via ftrace which have a kretprobe installed on them, can produce misleading output in their trace logs. E.g, consider the correct trace of the following sequence:
do_IRQ()
{
~
irq_enter();
~
}
Trace log (sample):
<idle>-0 [00] 4154504455.781616: irq_enter <- do_IRQ
But if irq_enter() has a kretprobe installed on it, the return value stored on the stack at each invocation is modified to divert the return to a kprobe trampoline function called kretprobe_trampoline(). So with this the trace would (currently) look like:
<idle>-0 [00] 4154504455.781616: irq_enter <- kretprobe_trampoline
Now this is quite misleading to the end user, as it suggests something that didn't actually happen. So just to avoid such misinterpretations, the inlined patch aims to output such a log as:
<idle>-0 [00] 4154504455.781616: irq_enter <- [unknown/kretprobe'd]

[...]

kernel/trace/trace.c static void s_stop(struct seq_file *m, void *p) · line 1208

Quoted 5 lines

kernel/trace/trace.c +5 -0

+
+#ifdef CONFIG_KRETPROBES
+static inline int kretprobed(unsigned long addr)
+{
+	return addr == (unsigned long)kretprobe_trampoline;

Hi Abhishek,

Now that this code is in mainline, it has become apparent that kretprobe_trampoline is not defined on all archs as a global like it is in x86. This needs to be fixed (it breaks ia64 build).

Thanks,

-- Steve

Quoted 7 lines

kernel/trace/trace.c +7 -0

+}
+#else
+static inline int kretprobed(unsigned long addr)
+{
+	return 0;
+}
+#endif /* CONFIG_KRETPROBES */

Steven Rostedt

maintainer

2008-10-31 14:37 UTC #4 lore raw

Quoted 9 lines · Steven Rostedt

kernel/trace/trace.c static void s_stop(struct seq_file *m, void *p) · line 1208
Quoted 6 lines
kernel/trace/trace.c +5 -0
+
+#ifdef CONFIG_KRETPROBES
+static inline int kretprobed(unsigned long addr)
+{
+	return addr == (unsigned long)kretprobe_trampoline;
Hi Abhishek,

Quoted 4 lines

Now that this code is in mainline, it has become apparent that kretprobe_trampoline is not defined on all archs as a global like it is in x86. This needs to be fixed (it breaks ia64 build).

Also note that kretprobe_trampoline will not be the return address.

Hmm, I think I can solve this by not even doing the test here, but simply on the name itself.

-- Steve

Abhishek Sagar

author

2008-10-31 15:32 UTC #5 lore raw

Quoted 11 lines · Steven Rostedt

Quoted 6 lines
Hi Abhishek,
Now that this code is in mainline, it has become apparent that kretprobe_trampoline is not defined on all archs as a global like it is in x86. This needs to be fixed (it breaks ia64 build).
Also note that kretprobe_trampoline will not be the return address.
Hmm, I think I can solve this by not even doing the test here, but simply on the name itself.

Ok. I wonder if it would be a good idea to export kretprobe_trampoline (or kretprobe_trampoline->ip) via asm/kprobes.h for all archs, for the kind of checks done here for ftrace (to have them elsewhere too like in OOPs generation etc).

Adding Kprobe folks in CC

-- Abhishek

Steven Rostedt

maintainer

2008-10-31 15:51 UTC #6 lore raw

Quoted 8 lines · Abhishek Sagar

Quoted 3 lines
Hmm, I think I can solve this by not even doing the test here, but simply on the name itself.
Ok. I wonder if it would be a good idea to export kretprobe_trampoline (or kretprobe_trampoline->ip) via asm/kprobes.h for all archs, for the kind of checks done here for ftrace (to have them elsewhere too like in OOPs generation etc).

Careful, I'm not sure that will work on all archs.

Could you test this patch and see if it still solves the issues. It does not require any arch dependent code.

-- Steve

From: Steven Rostedt <[email protected]>
Subject: ftrace: use kretprobe trampoline name to test in output

When a function is kprobed, the return address is set to the kprobe_trampoline, or something similar. This caused the output of the trace to look confusing when the parent seemed to be this "kprobe_trampoline" function.

To fix this, Abhishek Sagar added a test of the instruction pointer of the parent to see if it matched the kprobe_trampoline. If it did, the output would print a "[unknown/kretprobe'd]" instead.

Unfortunately, not all archs do this the same way, and the trampoline function may not be exported, which causes failures in builds.

This patch will compare the name instead of the pointer to see if it matches. This prevents us from depending on a function from being exported, and should work on all archs. The worst that can happen is that an arch might use a different name and then we go back to the confusing output. At least the arch will still build.

Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
 1 file changed, 21 insertions(+), 18 deletions(-)

kernel/trace/trace.c +21 ~~-18~~

Index: linux-tip.git/kernel/trace/trace.c
===================================================================
@@ -1104,17 +1104,20 @@ static void s_stop(struct seq_file *m, v
 	mutex_unlock(&trace_types_lock);
 }
 
-#define KRETPROBE_MSG "[unknown/kretprobe'd]"
-
 #ifdef CONFIG_KRETPROBES
-static inline int kretprobed(unsigned long addr)
+static inline const char *kretprobed(const char *name)
 {
-	return addr == (unsigned long)kretprobe_trampoline;
+	static const char tramp_name[] = "kretprobe_trampoline";
+	int size = sizeof(tramp_name);
+
+	if (strncmp(tramp_name, name, size) == 0)
+		return "[unknown/kretprobe'd]";
+	return name;
 }
 #else
-static inline int kretprobed(unsigned long addr)
+static inline const char *kretprobed(const char *name)
 {
-	return 0;
+	return name;
 }
 #endif /* CONFIG_KRETPROBES */

@@ -1123,10 +1126,13 @@ seq_print_sym_short(struct trace_seq *s,
 {
 #ifdef CONFIG_KALLSYMS
 	char str[KSYM_SYMBOL_LEN];
+	const char *name;
 
 	kallsyms_lookup(address, NULL, NULL, NULL, str);
 
-	return trace_seq_printf(s, fmt, str);
+	name = kretprobed(str);
+
+	return trace_seq_printf(s, fmt, name);
 #endif
 	return 1;
 }

@@ -1137,9 +1143,12 @@ seq_print_sym_offset(struct trace_seq *s
 {
 #ifdef CONFIG_KALLSYMS
 	char str[KSYM_SYMBOL_LEN];
+	const char *name;
 
 	sprint_symbol(str, address);
-	return trace_seq_printf(s, fmt, str);
+	name = kretprobed(str);
+
+	return trace_seq_printf(s, fmt, name);
 #endif
 	return 1;
 }

@@ -1392,10 +1401,7 @@ print_lat_fmt(struct trace_iterator *ite
 
 		seq_print_ip_sym(s, field->ip, sym_flags);
 		trace_seq_puts(s, " (");
-		if (kretprobed(field->parent_ip))
-			trace_seq_puts(s, KRETPROBE_MSG);
-		else
-			seq_print_ip_sym(s, field->parent_ip, sym_flags);
+		seq_print_ip_sym(s, field->parent_ip, sym_flags);
 		trace_seq_puts(s, ")\n");
 		break;
 	}

@@ -1511,12 +1517,9 @@ static enum print_line_t print_trace_fmt
 			ret = trace_seq_printf(s, " <-");
 			if (!ret)
 				return TRACE_TYPE_PARTIAL_LINE;
-			if (kretprobed(field->parent_ip))
-				ret = trace_seq_puts(s, KRETPROBE_MSG);
-			else
-				ret = seq_print_ip_sym(s,
-						       field->parent_ip,
-						       sym_flags);
+			ret = seq_print_ip_sym(s,
+					       field->parent_ip,
+					       sym_flags);
 			if (!ret)
 				return TRACE_TYPE_PARTIAL_LINE;
 		}

Abhishek Sagar

author Acked-by

2008-10-31 19:33 UTC #7 lore raw

Quoted 21 lines · Steven Rostedt

From: Steven Rostedt <[email protected]>
Subject: ftrace: use kretprobe trampoline name to test in output
When a function is kprobed, the return address is set to the kprobe_trampoline, or something similar. This caused the output of the trace to look confusing when the parent seemed to be this "kprobe_trampoline" function.
To fix this, Abhishek Sagar added a test of the instruction pointer of the parent to see if it matched the kprobe_trampoline. If it did, the output would print a "[unknown/kretprobe'd]" instead.
Unfortunately, not all archs do this the same way, and the trampoline function may not be exported, which causes failures in builds.
This patch will compare the name instead of the pointer to see if it matches. This prevents us from depending on a function from being exported, and should work on all archs. The worst that can happen is that an arch might use a different name and then we go back to the confusing output. At least the arch will still build.

Quoted 4 lines

Signed-off-by Steven Rostedt <[email protected]>

---
 kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
 1 file changed, 21 insertions(+), 18 deletions(-)

Looks good, and worked on x86-32.

Acked-by Abhishek Sagar <[email protected]>

Steven Rostedt

maintainer

2008-10-31 19:44 UTC #8 lore raw

PATCH 1/1 ftrace: use kretprobe trampoline name to test in output

[
Ingo,

Can you get this ready for 2.6.28. Without this fix, tracing breaks the ia64 build.
]

To fix this, Abhishek Sagar added a test of the instruction pointer of the parent to see if it matched the kprobe_trampoline. If it did, the output would print a "[unknown/kretprobe'd]" instead.

Unfortunately, not all archs do this the same way, and the trampoline function may not be exported, which causes failures in builds.

Signed-off-by Steven Rostedt <[email protected]>

Tested-by Abhishek Sagar <[email protected]>

Acked-by Abhishek Sagar <[email protected]>

---
 kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
 1 file changed, 21 insertions(+), 18 deletions(-)

kernel/trace/trace.c +21 ~~-18~~

Index: linux-tip.git/kernel/trace/trace.c
===================================================================
@@ -1104,17 +1104,20 @@ static void s_stop(struct seq_file *m, v
 	mutex_unlock(&trace_types_lock);
 }
 
-#define KRETPROBE_MSG "[unknown/kretprobe'd]"
-
 #ifdef CONFIG_KRETPROBES
-static inline int kretprobed(unsigned long addr)
+static inline const char *kretprobed(const char *name)
 {
-	return addr == (unsigned long)kretprobe_trampoline;
+	static const char tramp_name[] = "kretprobe_trampoline";
+	int size = sizeof(tramp_name);
+
+	if (strncmp(tramp_name, name, size) == 0)
+		return "[unknown/kretprobe'd]";
+	return name;
 }
 #else
-static inline int kretprobed(unsigned long addr)
+static inline const char *kretprobed(const char *name)
 {
-	return 0;
+	return name;
 }
 #endif /* CONFIG_KRETPROBES */

@@ -1123,10 +1126,13 @@ seq_print_sym_short(struct trace_seq *s,
 {
 #ifdef CONFIG_KALLSYMS
 	char str[KSYM_SYMBOL_LEN];
+	const char *name;
 
 	kallsyms_lookup(address, NULL, NULL, NULL, str);
 
-	return trace_seq_printf(s, fmt, str);
+	name = kretprobed(str);
+
+	return trace_seq_printf(s, fmt, name);
 #endif
 	return 1;
 }

@@ -1137,9 +1143,12 @@ seq_print_sym_offset(struct trace_seq *s
 {
 #ifdef CONFIG_KALLSYMS
 	char str[KSYM_SYMBOL_LEN];
+	const char *name;
 
 	sprint_symbol(str, address);
-	return trace_seq_printf(s, fmt, str);
+	name = kretprobed(str);
+
+	return trace_seq_printf(s, fmt, name);
 #endif
 	return 1;
 }

@@ -1392,10 +1401,7 @@ print_lat_fmt(struct trace_iterator *ite
 
 		seq_print_ip_sym(s, field->ip, sym_flags);
 		trace_seq_puts(s, " (");
-		if (kretprobed(field->parent_ip))
-			trace_seq_puts(s, KRETPROBE_MSG);
-		else
-			seq_print_ip_sym(s, field->parent_ip, sym_flags);
+		seq_print_ip_sym(s, field->parent_ip, sym_flags);
 		trace_seq_puts(s, ")\n");
 		break;
 	}

@@ -1511,12 +1517,9 @@ static enum print_line_t print_trace_fmt
 			ret = trace_seq_printf(s, " <-");
 			if (!ret)
 				return TRACE_TYPE_PARTIAL_LINE;
-			if (kretprobed(field->parent_ip))
-				ret = trace_seq_puts(s, KRETPROBE_MSG);
-			else
-				ret = seq_print_ip_sym(s,
-						       field->parent_ip,
-						       sym_flags);
+			ret = seq_print_ip_sym(s,
+					       field->parent_ip,
+					       sym_flags);
 			if (!ret)
 				return TRACE_TYPE_PARTIAL_LINE;
 		}

Ingo Molnar

Applied

2008-11-03 09:42 UTC #9 lore raw

Re: [PATCH] ftrace: use kretprobe trampoline name to test in output

Quoted 25 lines · Steven Rostedt

[
Ingo,
Can you get this ready for 2.6.28. Without this fix, tracing breaks the ia64 build.
]
When a function is kprobed, the return address is set to the kprobe_trampoline, or something similar. This caused the output of the trace to look confusing when the parent seemed to be this "kprobe_trampoline" function.
To fix this, Abhishek Sagar added a test of the instruction pointer of the parent to see if it matched the kprobe_trampoline. If it did, the output would print a "[unknown/kretprobe'd]" instead.
Unfortunately, not all archs do this the same way, and the trampoline function may not be exported, which causes failures in builds.
This patch will compare the name instead of the pointer to see if it matches. This prevents us from depending on a function from being exported, and should work on all archs. The worst that can happen is that an arch might use a different name and then we go back to the confusing output. At least the arch will still build.

Quoted 6 lines

Signed-off-by Steven Rostedt <[email protected]>
Tested-by Abhishek Sagar <[email protected]>
Acked-by Abhishek Sagar <[email protected]>
---
 kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
 1 file changed, 21 insertions(+), 18 deletions(-)

applied to tip/tracing/urgent, thanks!

Ingo