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

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

On 10/30/25 09:59, Thomas Richter wrote:
> 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.
> 

This is the first bad commit.... (I actually tested it :-(, obviously without -D option )

commit 0012e0fa221bf9cc54aa6a0e94d848653dc781bb (HEAD)
Author: Ian Rogers <irogers@google.com>
Date:   Sun Oct 5 11:24:16 2025 -0700

    perf jevents: Add legacy-hardware and legacy-cache json
    
    The legacy-hardware.json is added containing hardware events similarly
    to the software.json file. A difference is that for the software PMU
    the name is known and matches sysfs. In the legacy-hardware.json no
    Unit/PMU is specified for the events meaning default_core is used and
    the events will appear for all core PMUs.
    ......

What puzzles me is that the above patch does not change anything in
util/s390-sample-raw.c which handles s390 specific sample interpretation.

Maybe that patch affects perf_pmus__find()?
Not sure how to proceed.

Thanks a lot
-- 
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