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

[Thomas Richter <tmricht@linux.ibm.com>]

On 10/29/25 17:47, 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.
> 
> Thanks!
> Ian
> 

Thanks Ian,

I tested your patch, but there is no big difference:
root in 🌐 s83lp47 in ~ 
❯ ll ~/perf.data-test
-rw-------. 1 root root 152280778 Oct 30 07:58 /root/perf.data-test

here is the output with your patch:
root in 🌐 s83lp47 in ~ 
❯ time mirror-linux-next/tools/perf/perf report -D -i ~/perf.data-test > /dev/null

real	46m26.350s
user	46m17.559s
sys	0m7.434s


Here is the output from the linux-next perf version:

root in 🌐 s83lp47 in ~ took 46m26s 
❯ time perf report -D -i ~/perf.data-test > /dev/null

real	49m14.364s
user	49m4.872s
sys	0m8.037s

root in 🌐 s83lp47 in ~ took 49m14s 

When I go back history and use:

# pwd
/root/mirror-linux-next/tools/perf
# git branch
* (HEAD detached at v6.10)
  master
]# ll ~/perf.data-test
-rw------- 1 root root 152280778 Oct 30 08:38 /root/perf.data-test
# time ./perf report -D -i ~/perf.data-test > /dev/null

real	8m49.089s
user	8m47.898s
sys	0m0.848s
# 

Thanks for the pointer. Since the issue is with s390 specific code
I will do a git bisect and we go from there.

-- 
Thomas Richter, Dept 3303, IBM s390 Linux Development, Boeblingen, Germany
--
IBM Deutschland Research & Development GmbH

Vorsitzender des Aufsichtsrats: Wolfgang Wendt

Geschäftsführung: David Faller

Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294