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

This is a discussion on [PATCH] ftrace: distinguish kretprobe'd functions in trace logs - Kernel ; 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): -0 ...

+ Reply to Thread
Results 1 to 10 of 10

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

  1. [PATCH] 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):
    -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:

    -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:

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


    Signed-off-by: Abhishek Sagar
    ---

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

    #include
    @@ -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;
    }
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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


    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:
    >
    > -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:
    >
    > -0 [00] 4154504455.781616: irq_enter <- [unknown/kretprobe'd]
    >
    >
    > Signed-off-by: Abhishek Sagar


    Thanks Abhishek,

    Acked-by: Steven Rostedt

    -- Steve

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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


    * Steven Rostedt 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:
    > >
    > > -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:
    > >
    > > -0 [00] 4154504455.781616: irq_enter <- [unknown/kretprobe'd]
    > >
    > >
    > > Signed-off-by: Abhishek Sagar

    >
    > Thanks Abhishek,
    >
    > Acked-by: Steven Rostedt


    applied to tip/tracing/ftrace, thanks.

    Ingo
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  4. 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):
    > -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:
    >
    > -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:
    >
    > -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 */

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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

    On Fri, Oct 31, 2008 at 10:36 AM, Steven Rostedt 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
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  7. 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
    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
    ---
    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;
    }
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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

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


    Looks good, and worked on x86-32.

    Acked-by: Abhishek Sagar
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  9. [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
    Tested-by: Abhishek Sagar
    Acked-by: Abhishek Sagar
    ---
    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;
    }


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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


    * Steven Rostedt 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
    > Tested-by: Abhishek Sagar
    > Acked-by: Abhishek Sagar
    > ---
    > kernel/trace/trace.c | 39 +++++++++++++++++++++------------------
    > 1 file changed, 21 insertions(+), 18 deletions(-)


    applied to tip/tracing/urgent, thanks!

    Ingo
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

+ Reply to Thread