[PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[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]


Signed-off-by: Abhishek Sagar <sagar.abhishek@gmail.com>
---

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 0feae23..12f5e81 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -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;
 		}

Re: [PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[Steven Rostedt]

On Wed, 28 May 2008, Abhishek Sagar wrote:
>
> 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 <sagar.abhishek@gmail.com>

Thanks Abhishek,

Acked-by: Steven Rostedt <srostedt@redhat.com>

-- Steve

Re: [PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 28 May 2008, Abhishek Sagar wrote:
> >
> > 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 <sagar.abhishek@gmail.com>
> 
> Thanks Abhishek,
> 
> Acked-by: Steven Rostedt <srostedt@redhat.com>

applied to tip/tracing/ftrace, thanks.

	Ingo

Re: [PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[Steven Rostedt]

On Wed, 28 May 2008, Abhishek Sagar wrote:
> 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]
> 
> 

[...]

> +
> +#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


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

Re: [PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[Steven Rostedt]

On Thu, 30 Oct 2008, Steven Rostedt wrote:
> 
> > +
> > +#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).
> 

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

Re: [PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[Abhishek Sagar]

On Fri, Oct 31, 2008 at 10:36 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
>> 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

Re: [PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[Steven Rostedt]

On Fri, 31 Oct 2008, Abhishek Sagar wrote:
> >
> > 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 <srostedt@redhat.com>
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 <srostedt@redhat.com>
---
 kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
 1 file changed, 21 insertions(+), 18 deletions(-)

Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c	2008-10-31 10:41:29.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.c	2008-10-31 11:25:21.000000000 -0400
@@ -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;
 		}

Re: [PATCH] ftrace: distinguish kretprobe'd functions in trace logs

[Abhishek Sagar]

On Fri, Oct 31, 2008 at 11:50 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> From: Steven Rostedt <srostedt@redhat.com>
> 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 <srostedt@redhat.com>
> ---
>  kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
>  1 file changed, 21 insertions(+), 18 deletions(-)

Looks good, and worked on x86-32.

Acked-by: Abhishek Sagar <sagar.abhishek@gmail.com>

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

[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.

Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Tested-by: Abhishek Sagar <sagar.abhishek@gmail.com>
Acked-by: Abhishek Sagar <sagar.abhishek@gmail.com>
---
 kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
 1 file changed, 21 insertions(+), 18 deletions(-)

Index: linux-tip.git/kernel/trace/trace.c
===================================================================
--- linux-tip.git.orig/kernel/trace/trace.c	2008-10-31 10:41:29.000000000 -0400
+++ linux-tip.git/kernel/trace/trace.c	2008-10-31 11:25:21.000000000 -0400
@@ -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;
 		}

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

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> [
>   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.
> 
> Signed-off-by: Steven Rostedt <srostedt@redhat.com>
> Tested-by: Abhishek Sagar <sagar.abhishek@gmail.com>
> Acked-by: Abhishek Sagar <sagar.abhishek@gmail.com>
> ---
>  kernel/trace/trace.c |   39 +++++++++++++++++++++------------------
>  1 file changed, 21 insertions(+), 18 deletions(-)

applied to tip/tracing/urgent, thanks!

	Ingo