Re: [linux-next] perf report runtime extremely long

[Namhyung Kim <namhyung@kernel.org>]

Hello,

On Wed, Oct 29, 2025 at 09:47:00AM -0700, Ian Rogers wrote:
> On Wed, Oct 29, 2025 at 9:12 AM Thomas Richter <tmricht@linux.ibm.com> wrote:
> >
> > On 10/29/25 09:03, Thomas Richter wrote:
> > > Hi all,
> > >
> > > has something changed recently in perf report in linux-next repo?
> > >
> > > I run perf report -i <file> -D | grep something
> > > on s390 with 2 different kernels:
> > >
> > > master 6.18.0rc3:
> > > # uname -a
> > > Linux a35lp67.lnxne.boe 6.18.0-rc3m-perf+ #23 SMP Tue Oct 28 15:53:44 CET 2025 s390x GNU/Linux
> > > # ll /tmp/perf2-eSso2q-2
> > > -rw------- 1 root root 8538184 Oct 29 08:44 /tmp/perf2-eSso2q-2
> > > # time perf report -i/tmp/perf2-eSso2q-2 -D | grep Counter:000 > /dev/null
> > >
> > > real  0m22.262s
> > > user  0m22.068s
> > > sys   0m0.200s
> > > #
> > >
> > > This runtime is ok for the perf.data file size.
> > >
> > > linux-next:
> > > # uname -a
> > > Linux s83lp47.lnxne.boe 6.18.0-20251028.rc3.git141.f7d2388eeec2.63.fc42.s390x+next #1 SMP Tue Oct 28 20:06:13 CET 2025 s390x GNU/Linux
> > > #ll /tmp/perf2-eSso2q-2
> > > -rw-------. 1 root root 8538184 Oct 29 08:47 /tmp/perf2-eSso2q-2
> > > # time perf report -i/tmp/perf2-eSso2q-2 -D | grep Counter:000 > /dev/null
> > >
> > > real  2m53.601s
> > > user  2m52.938s
> > > sys   0m0.575s
> > > #
> > >
> > > Same perf.data file and run time increased from 22 seconds to nearly 300 seconds, roughly 14 times longer
> > > for the same input!
> > >
> > > Has anybody similar observations?
> > >
> > > Thanks a lot
> > >
> >
> > Ian,
> >
> > sorry sent button pushed too early...
> >
> > here is a second try without option -D.
> >
> > This is much better:
> >
> > root in 🌐 s83lp47 in ~
> > ❯ ll perf1.data
> > -rw-------. 1 root root 99692290 Oct 29 16:17 perf1.data
> >
> > root in 🌐 s83lp47 in ~
> > ❯ time perf record -- perf report -i perf1.data  > /dev/null
> > [ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 0.027 MB perf.data (246 samples) ]
> >
> > real    0m1.097s
> > user    0m0.082s
> > sys     0m0.167s
> >
> > root in 🌐 s83lp47 in ~
> > ❯ perf report --stdio
> > # To display the perf.data header info, please use --header/--header-only options.
> > #
> > #
> > # Total Lost Samples: 0
> > #
> > # Samples: 246  of event 'cpum_cf/cycles/P'
> > # Event count (approx.): 307500000
> > #
> > # Overhead  Command  Shared Object        Symbol
> > # ........  .......  ...................  ..................................................
> > #
> >      9.35%  perf     perf                 [.] reader__read_event
> >      4.47%  perf     perf                 [.] perf_env__arch
> >      2.85%  perf     ld64.so.1            [.] _dl_relocate_object_no_relro
> >      2.44%  perf     ld64.so.1            [.] _dl_lookup_symbol_x
> >      2.44%  perf     ld64.so.1            [.] do_lookup_x
> >      2.44%  perf     perf                 [.] down_read
> >      2.03%  perf     perf                 [.] hists__findnew_entry
> >      2.03%  perf     perf                 [.] perf_hpp__is_dynamic_entry
> >      1.63%  perf     [kernel.kallsyms]    [k] __s390_indirect_jump_r14
> >      1.63%  perf     [kernel.kallsyms]    [k] format_decode
> >      1.63%  perf     libc.so.6            [.] cfree@GLIBC_2.2
> >      1.63%  perf     perf                 [.] evsel__parse_sample
> >      1.63%  perf     perf                 [.] map__put
> >      1.63%  perf     perf                 [.] sort__comm_cmp
> >      1.63%  perf     perf                 [.] thread__put
> >      1.22%  perf     [kernel.kallsyms]    [k] folio_add_file_rmap_ptes
> >      1.22%  perf     [kernel.kallsyms]    [k] get_page_from_freelist
> >      1.22%  perf     ld64.so.1            [.] _dl_name_match_p
> >      1.22%  perf     perf                 [.] dump_printf
> >      1.22%  perf     perf                 [.] evlist__event2evsel
> >      1.22%  perf     perf                 [.] hashmap_find
> >      1.22%  perf     perf                 [.] perf_session__deliver_event
> 
> Hmm.. for perf_env__arch we could probably cache better:
> ```
> diff --git a/tools/perf/util/env.c b/tools/perf/util/env.c
> index f1626d2032cd..2591f71c7c42 100644
> --- a/tools/perf/util/env.c
> +++ b/tools/perf/util/env.c
> @@ -593,17 +593,27 @@ static const char *normalize_arch(char *arch)
> 
> const char *perf_env__arch(struct perf_env *env)
> {
> -       char *arch_name;
> +       if (env && env->arch && env->arch_name_normalized)
> +               return env->arch;
> 
>        if (!env || !env->arch) { /* Assume local operation */
>                static struct utsname uts = { .machine[0] = '\0', };
>                if (uts.machine[0] == '\0' && uname(&uts) < 0)
>                        return NULL;
> -               arch_name = uts.machine;
> -       } else
> -               arch_name = env->arch;
> 
> -       return normalize_arch(arch_name);
> +               if (!env)
> +                       return normalize_arch(uts.machine);
> +
> +               env->arch = strdup(normalize_arch(uts.machine));
> +               env->arch_name_normalized = true;
> +       } else {
> +               char *normalized = strdup(normalize_arch(env->arch));
> +
> +               free(env->arch);
> +               env->arch = normalized;
> +               env->arch_name_normalized = true;
> +       }
> +       return env->arch;
> }
> 
> #if defined(HAVE_LIBTRACEEVENT)
> diff --git a/tools/perf/util/env.h b/tools/perf/util/env.h
> index 9977b85523a8..da20bc3810bd 100644
> --- a/tools/perf/util/env.h
> +++ b/tools/perf/util/env.h
> @@ -61,6 +61,7 @@ struct perf_env {
>        char                    *os_release;
>        char                    *version;
>        char                    *arch;
> +       bool                    arch_name_normalized;
>        int                     nr_cpus_online;
>        int                     nr_cpus_avail;
>        char                    *cpu_desc;
> ```
> or just force the normalize before assignment.
> 
> For reader__read_event and the perf_env these changes may be relevant:
> "perf sample: Remove arch notion of sample parsing"
> https://lore.kernel.org/r/20250724163302.596743-21-irogers@google.com
> "perf env: Remove global perf_env"
> https://lore.kernel.org/r/20250724163302.596743-20-irogers@google.com
> 
> I wonder if for some reason the env is NULL in your cases, so we go
> slow path a lot.
> 
> The histogram stuff, Namhyung may know more.

There only 2 entries for the hist code.  The hists__findnew_entry() is
expected as it's the main routine to aggregate the samples.  But the
perf_hpp__is_dynamic_entry() is strange.  It should be very small and
fast.

But I guess the actual problem is when you use -D in perf report.  And
it doesn't show hist related functions IIUC.

Thanks,
Namhyung