2008-10-31 02:30:35

by Steven Rostedt

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


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 */


2008-10-31 14:37:14

by Steven Rostedt

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


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

2008-10-31 15:32:52

by Abhishek Sagar

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

On Fri, Oct 31, 2008 at 10:36 AM, Steven Rostedt <[email protected]> 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

2008-10-31 15:51:17

by Steven Rostedt

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


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 <[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(-)

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;
}

2008-10-31 19:33:18

by Abhishek Sagar

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

On Fri, Oct 31, 2008 at 11:50 AM, Steven Rostedt <[email protected]> wrote:
> 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(-)

Looks good, and worked on x86-32.

Acked-by: Abhishek Sagar <[email protected]>

2008-10-31 19:44:21

by Steven Rostedt

[permalink] [raw]
Subject: [PATCH] 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.
]

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]>
Tested-by: Abhishek Sagar <[email protected]>
Acked-by: Abhishek Sagar <[email protected]>
---
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;
}

2008-11-03 09:42:39

by Ingo Molnar

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


* Steven Rostedt <[email protected]> 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 <[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