Re: [PATCH] mm: kfence: print the age time for alloacted objectes to trace memleak

[Marco Elver <elver@google.com>]

On Sat, 3 Aug 2024 at 15:36, Qiwu Chen <qiwuchen55@gmail.com> wrote:
>
> From: "qiwu.chen" <qiwu.chen@transsion.com>
>
> For a convienince of tracing slab object leak, print the age time for

typo: convenience

What do you mean by "object leak"?

From what I see the additional info is only printed on out-of-bounds access.

Or do you mean when you inspect /sys/kernel/debug/kfence/objects? If
so, that information would be useful in the commit message.

However, to detect leaks there are better tools than KFENCE. Have you
tried KMEMLEAK? KFENCE is really not a good choice to manually look
for old objects, which themselves are sampled, to find leaks.
Have you been able to successfully debug a leak this way?

> alloacted objectes in kfence_print_stack().

typo: allocated objects

> Signed-off-by: qiwu.chen <qiwu.chen@transsion.com>
> ---
>  mm/kfence/report.c | 14 ++++++++++++--
>  1 file changed, 12 insertions(+), 2 deletions(-)
>
> diff --git a/mm/kfence/report.c b/mm/kfence/report.c
> index c509aed326ce..44c3f82b25a8 100644
> --- a/mm/kfence/report.c
> +++ b/mm/kfence/report.c
> @@ -16,6 +16,7 @@
>  #include <linux/sprintf.h>
>  #include <linux/stacktrace.h>
>  #include <linux/string.h>
> +#include <linux/sched/clock.h>
>  #include <trace/events/error_report.h>
>
>  #include <asm/kfence.h>
> @@ -110,9 +111,18 @@ static void kfence_print_stack(struct seq_file *seq, const struct kfence_metadat
>         unsigned long rem_nsec = do_div(ts_sec, NSEC_PER_SEC);
>
>         /* Timestamp matches printk timestamp format. */
> -       seq_con_printf(seq, "%s by task %d on cpu %d at %lu.%06lus:\n",
> +       if (meta->state == KFENCE_OBJECT_ALLOCATED) {

In principle, the additonal info is convenient, but I'd like to
generalize if possible.

> +               u64 interval_nsec = local_clock() - meta->alloc_track.ts_nsec;
> +               unsigned long rem_interval_nsec = do_div(interval_nsec, NSEC_PER_SEC);
> +
> +               seq_con_printf(seq, "%s by task %d on cpu %d at %lu.%06lus (age: %lu.%06lus):\n",

I've found myself trying to figure out the elapsed time since the
allocation or free, based on the current timestamp.

So something that would be more helpful is if you just change the
printed line for all alloc and free stack infos to say something like:

    seq_con_printf(seq, "%s by task %d on cpu %d at %lu.%06lus
(%lu.%06lus ago):\n",

So rather than saying this info is the "age", we just say the elapsed
time. That generalizes this bit of info, and it'll be available for
both alloc and free stacks.

Does that work for you?

>                        show_alloc ? "allocated" : "freed", track->pid,
> -                      track->cpu, (unsigned long)ts_sec, rem_nsec / 1000);
> +                      track->cpu, (unsigned long)ts_sec, rem_nsec / 1000,
> +                          (unsigned long)interval_nsec, rem_interval_nsec / 1000);
> +       } else

Add braces {} even though it's a single statement - it spans several
lines and the above is also {}-enclosed, so it looks balanced.

But if you follow my suggestion, you won't have the else branch anymore.

> +               seq_con_printf(seq, "%s by task %d on cpu %d at %lu.%06lus:\n",
> +                                  show_alloc ? "allocated" : "freed", track->pid,
> +                                  track->cpu, (unsigned long)ts_sec, rem_nsec / 1000);
>
>         if (track->num_stack_entries) {
>                 /* Skip allocation/free internals stack. */