perf report does not resolve symbols on s390x

perf report does not resolve symbols on s390x

[Thomas-Mich Richter]

I use linux 4.12 kernel and the perf report --stdio does not resolve all symbols:
Only very few symbols are resolved and none listed in the call back chain.

Here is an example:

    50.00%    50.00%  true     [kernel.vmlinux]  [k] __rb_insert_augmented
            |
            ---0x6a0624
               0x2d7c00
               0x2d79c8
               0x2b5a26
               0x2da542
               0x2da01a
               0x2d6c2e
               0x2d6b86

    50.00%     0.00%  true     [unknown]         [k] 0x000000000011e90a
            |
            ---0x11e90a
               0x2d39a4
               0x2d3238
               0x288140
               0x2cf404
               0x2df5d8
               0x31618c
               0x19b0ae

These addresses are all in the /proc/kallsyms and valid.

When I do a perf script it works:
[root@s8360046 perf]# perf script
true  4384  7991.047063:     250000 cpu-clock: 
                  19c0ae lock_acquire (/lib/modules/4.12.0perf+/build/vmlinux)
                  31718c lock_page_memcg (/lib/modules/4.12.0perf+/build/vmlinux)
                  2e05d8 page_add_file_rmap (/lib/modules/4.12.0perf+/build/vmlinux)
                  2d0404 alloc_set_pte (/lib/modules/4.12.0perf+/build/vmlinux)
                  289140 filemap_map_pages (/lib/modules/4.12.0perf+/build/vmlinux)
                  2d4238 __handle_mm_fault (/lib/modules/4.12.0perf+/build/vmlinux)
                  2d49a4 handle_mm_fault (/lib/modules/4.12.0perf+/build/vmlinux)
                  11f90a do_dat_exception (/lib/modules/4.12.0perf+/build/vmlinux)
                  6a1962 pgm_check_handler (/lib/modules/4.12.0perf+/build/vmlinux)


Any ideas in which area of the perf report tool to dig into to get this fixed.

When I use -vvvvv I see all kernel symbols read in and listed, so I fail to see
why they are not resolved.
Maybe someone can point me to the area of code to start digging.

Thanks a lot.

-- 
Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
--
Vorsitzende des Aufsichtsrats: Martina Koederitz 
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: perf report does not resolve symbols on s390x

[Arnaldo Carvalho de Melo]

Em Wed, Jul 05, 2017 at 04:45:49PM +0200, Thomas-Mich Richter escreveu:
> I use linux 4.12 kernel and the perf report --stdio does not resolve all symbols:
> Only very few symbols are resolved and none listed in the call back chain.
> 
> Here is an example:
> 
>     50.00%    50.00%  true     [kernel.vmlinux]  [k] __rb_insert_augmented
>             |
>             ---0x6a0624
>                0x2d7c00
>                0x2d79c8
>                0x2b5a26
>                0x2da542
>                0x2da01a
>                0x2d6c2e
>                0x2d6b86
> 
>     50.00%     0.00%  true     [unknown]         [k] 0x000000000011e90a
>             |
>             ---0x11e90a
>                0x2d39a4
>                0x2d3238
>                0x288140
>                0x2cf404
>                0x2df5d8
>                0x31618c
>                0x19b0ae
> 
> These addresses are all in the /proc/kallsyms and valid.
> 
> When I do a perf script it works:
> [root@s8360046 perf]# perf script

This is the strange part, 'script' resolving things 'report' doesn't,
they should be using the same machinery... Since the DSO is not being
resolved on the one failing above, this would look like its some
PERF_RECORD_MMAP/PERF_RECORD_MMAP2 that is being missed, so you should
look at the processing of such records, which is done via:

 perf_tool.mmap() and perf_tool.mmap2()

the perf_tool ops table is passed to:

  perf_session__new(&file, false, &report.tool);

Which will call the mmap() and mmap2() functions to process those
records, if you look at script it has:

  
        struct perf_script script = {
                .tool = {
                        .sample          = process_sample_event,
                        .mmap            = perf_event__process_mmap,
                        .mmap2           = perf_event__process_mmap2,
<SNIP>

and then:

  session = perf_session__new(&file, false, &script.tool);

Which is the same as done for report:

          struct report report = {
                .tool = {
                        .sample          = process_sample_event,
                        .mmap            = perf_event__process_mmap,
                        .mmap2           = perf_event__process_mmap2,
<SNIP>

  perf_session__new(&file, false, &report.tool);

I.e. both use the same functions to resolve PERF_RECORD_MMAP/MMAP2 records,
then you should look at how samples are processed, its static functions, tool specific
functions, both named process_sample_event, in tools/perf/builtin->{report,script}.c,
and both will basically do:

        if (machine__resolve(machine, &al, sample) < 0) {
                pr_debug("problem processing %d event, skipping it.\n",
                         event->header.type);
                return -1;
        }

That will do lookups on trees populated by perf_event__process_mmap,
perf_event__process_mmap2, and the routines handling PERF_RECORD_FORK, etc.

Is this enough to help you go from here to investigate your problem?

- Arnaldo

> true  4384  7991.047063:     250000 cpu-clock: 
>                   19c0ae lock_acquire (/lib/modules/4.12.0perf+/build/vmlinux)
>                   31718c lock_page_memcg (/lib/modules/4.12.0perf+/build/vmlinux)
>                   2e05d8 page_add_file_rmap (/lib/modules/4.12.0perf+/build/vmlinux)
>                   2d0404 alloc_set_pte (/lib/modules/4.12.0perf+/build/vmlinux)
>                   289140 filemap_map_pages (/lib/modules/4.12.0perf+/build/vmlinux)
>                   2d4238 __handle_mm_fault (/lib/modules/4.12.0perf+/build/vmlinux)
>                   2d49a4 handle_mm_fault (/lib/modules/4.12.0perf+/build/vmlinux)
>                   11f90a do_dat_exception (/lib/modules/4.12.0perf+/build/vmlinux)
>                   6a1962 pgm_check_handler (/lib/modules/4.12.0perf+/build/vmlinux)
> 
> 
> Any ideas in which area of the perf report tool to dig into to get this fixed.
> 
> When I use -vvvvv I see all kernel symbols read in and listed, so I fail to see
> why they are not resolved.
> Maybe someone can point me to the area of code to start digging.
> 
> Thanks a lot.
> 
> -- 
> Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
> --
> Vorsitzende des Aufsichtsrats: Martina Koederitz 
> Geschäftsführung: Dirk Wittkopp
> Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: perf report does not resolve symbols on s390x

[Thomas-Mich Richter]

On 07/05/2017 05:50 PM, Arnaldo Carvalho de Melo wrote:
> Em Wed, Jul 05, 2017 at 04:45:49PM +0200, Thomas-Mich Richter escreveu:
>> I use linux 4.12 kernel and the perf report --stdio does not resolve all symbols:
>> Only very few symbols are resolved and none listed in the call back chain.
>>
>> Here is an example:
>>
>>     50.00%    50.00%  true     [kernel.vmlinux]  [k] __rb_insert_augmented
>>             |
>>             ---0x6a0624
>>                0x2d7c00
>>                0x2d79c8
>>                0x2b5a26
>>                0x2da542
>>                0x2da01a
>>                0x2d6c2e
>>                0x2d6b86
>>
>>     50.00%     0.00%  true     [unknown]         [k] 0x000000000011e90a
>>             |
>>             ---0x11e90a
>>                0x2d39a4
>>                0x2d3238
>>                0x288140
>>                0x2cf404
>>                0x2df5d8
>>                0x31618c
>>                0x19b0ae
>>
>> These addresses are all in the /proc/kallsyms and valid.
>>
>> When I do a perf script it works:
>> [root@s8360046 perf]# perf script
> 
> This is the strange part, 'script' resolving things 'report' doesn't,
> they should be using the same machinery... Since the DSO is not being
> resolved on the one failing above, this would look like its some
> PERF_RECORD_MMAP/PERF_RECORD_MMAP2 that is being missed, so you should
> look at the processing of such records, which is done via:
> 
>  perf_tool.mmap() and perf_tool.mmap2()
> 
> the perf_tool ops table is passed to:
> 
>   perf_session__new(&file, false, &report.tool);
> 
> Which will call the mmap() and mmap2() functions to process those
> records, if you look at script it has:
> 
>   
>         struct perf_script script = {
>                 .tool = {
>                         .sample          = process_sample_event,
>                         .mmap            = perf_event__process_mmap,
>                         .mmap2           = perf_event__process_mmap2,
> <SNIP>
> 
> and then:
> 
>   session = perf_session__new(&file, false, &script.tool);
> 
> Which is the same as done for report:
> 
>           struct report report = {
>                 .tool = {
>                         .sample          = process_sample_event,
>                         .mmap            = perf_event__process_mmap,
>                         .mmap2           = perf_event__process_mmap2,
> <SNIP>
> 
>   perf_session__new(&file, false, &report.tool);
> 
> I.e. both use the same functions to resolve PERF_RECORD_MMAP/MMAP2 records,
> then you should look at how samples are processed, its static functions, tool specific
> functions, both named process_sample_event, in tools/perf/builtin->{report,script}.c,
> and both will basically do:
> 
>         if (machine__resolve(machine, &al, sample) < 0) {
>                 pr_debug("problem processing %d event, skipping it.\n",
>                          event->header.type);
>                 return -1;
>         }
> 
> That will do lookups on trees populated by perf_event__process_mmap,
> perf_event__process_mmap2, and the routines handling PERF_RECORD_FORK, etc.
> 
> Is this enough to help you go from here to investigate your problem?
> 
> - Arnaldo
> 

Thanks a lot for the direction to dig into. I am quiet new to perf and still
do not have an understanding of all the structures and how their interact together.

Maybe there is some documentation of the internals of perf someone can share with
me? Or post it to the mailing list.

Thanks.

-- 
Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
--
Vorsitzende des Aufsichtsrats: Martina Koederitz 
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: perf report does not resolve symbols on s390x

[Thomas-Mich Richter]

On 07/05/2017 05:50 PM, Arnaldo Carvalho de Melo wrote:
> Em Wed, Jul 05, 2017 at 04:45:49PM +0200, Thomas-Mich Richter escreveu:
>> I use linux 4.12 kernel and the perf report --stdio does not resolve all symbols:
>> Only very few symbols are resolved and none listed in the call back chain.
>>
>> Here is an example:
>>
>>     50.00%    50.00%  true     [kernel.vmlinux]  [k] __rb_insert_augmented
>>             |
>>             ---0x6a0624
>>                0x2d7c00
>>                0x2d79c8
>>                0x2b5a26
>>                0x2da542
>>                0x2da01a
>>                0x2d6c2e
>>                0x2d6b86
>>
>>     50.00%     0.00%  true     [unknown]         [k] 0x000000000011e90a
>>             |
>>             ---0x11e90a
>>                0x2d39a4
>>                0x2d3238
>>                0x288140
>>                0x2cf404
>>                0x2df5d8
>>                0x31618c
>>                0x19b0ae
>>
>> These addresses are all in the /proc/kallsyms and valid.
>>
>> When I do a perf script it works:
>> [root@s8360046 perf]# perf script
> 
> This is the strange part, 'script' resolving things 'report' doesn't,
> they should be using the same machinery... Since the DSO is not being
> resolved on the one failing above, this would look like its some
> PERF_RECORD_MMAP/PERF_RECORD_MMAP2 that is being missed, so you should
> look at the processing of such records, which is done via:
> 
>  perf_tool.mmap() and perf_tool.mmap2()
> 
> the perf_tool ops table is passed to:
> 
>   perf_session__new(&file, false, &report.tool);
> 
> Which will call the mmap() and mmap2() functions to process those
> records, if you look at script it has:
> 
>   
>         struct perf_script script = {
>                 .tool = {
>                         .sample          = process_sample_event,
>                         .mmap            = perf_event__process_mmap,
>                         .mmap2           = perf_event__process_mmap2,
> <SNIP>
> 
> and then:
> 
>   session = perf_session__new(&file, false, &script.tool);
> 
> Which is the same as done for report:
> 
>           struct report report = {
>                 .tool = {
>                         .sample          = process_sample_event,
>                         .mmap            = perf_event__process_mmap,
>                         .mmap2           = perf_event__process_mmap2,
> <SNIP>
> 
>   perf_session__new(&file, false, &report.tool);
> 
> I.e. both use the same functions to resolve PERF_RECORD_MMAP/MMAP2 records,
> then you should look at how samples are processed, its static functions, tool specific
> functions, both named process_sample_event, in tools/perf/builtin->{report,script}.c,
> and both will basically do:
> 
>         if (machine__resolve(machine, &al, sample) < 0) {
>                 pr_debug("problem processing %d event, skipping it.\n",
>                          event->header.type);
>                 return -1;
>         }
> 
> That will do lookups on trees populated by perf_event__process_mmap,
> perf_event__process_mmap2, and the routines handling PERF_RECORD_FORK, etc.
> 
> Is this enough to help you go from here to investigate your problem?
> 
> - Arnaldo
> 

Thanks for the explanation. I investigated the process_sample_event()
from the builtin-report.c and builtin-script.c. I used the same perf.data
file:

[root@s8360046 perf]# ./perf script -D -vvvvv > /tmp/script.out 2>&1
[root@s8360046 perf]# ./perf report -D -vvvvv > /tmp/report.out 2>&1
[root@s8360046 perf]#  fgrep PERF_RECORD_MMAP //tmp/script.out|wc -l
10
[root@s8360046 perf]#  fgrep PERF_RECORD_MMAP //tmp/report.out|wc -l
10
[root@s8360046 perf]#

Both tools see the same number of PREF_RECORD_MMAP* events and
use the same data base.

Next I digged into process_sample_event() call chains and added printf's.
All lines marked with a star (*) are my printf's

builtin-script.c:
I see a long list of symbol__new debug info, showing kernel symbols and addresses.

After a PERF_RECORD_SAMPLE(IP, 0x1):
7991046816204 0x518 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 4384/4384: 0x487b12 period: 250000 addr: 0
... FP chain: nr:10
.....  0: ffffffffffffff80
.....  1: 00000000002d6b86
.....  2: 00000000002d6c2e
.....  3: 00000000002da01a
.....  4: 00000000002da542
.....  5: 00000000002b5a26
.....  6: 00000000002d79c8
.....  7: 00000000002d7c00
.....  8: 00000000006a0624
.....  9: fffffffffffffe00
* process_sample_event 1
... thread: true:4384
* dso__load_vmlinux_path i:0 vmlinux err:-1
* dso__load_vmlinux_path i:1 /boot/vmlinux err:-1
* dso__load_vmlinux_path i:2 /boot/vmlinux-4.12.0perf+ err:-1
* dso__load_vmlinux_path i:3 /usr/lib/debug/boot/vmlinux-4.12.0perf+ err:-1
* dso__load_vmlinux_path i:4 /lib/modules/4.12.0perf+/build/vmlinux err:21340
...... dso: /lib/modules/4.12.0perf+/build/vmlinux
* machine__resolve al->filtered:0 al->map:0x352aec20 al->sym:0x3540c9d0
* process_sample_event al:0x488b12 sym:0x3540c9d0 map:0-0xa47000@0x1000
* process_sample_event name:__rb_insert_augmented
true  4384  7991.046816:     250000 cpu-clock:
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x3545b7a0
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x353150a0
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x3542d910
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x35408d60
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x353d0100
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x35458ef0
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x35427250
* thread__find_addr_location pid:4384 al->map:0x352aec20 al->sym:0x353b4900

The first symbol is __rb_insert_augmented. It is found in the kernel map.
The call chain is:
process_sample_event(builtin-script.c)
machine__resolve()
process_event(builtin-script.c)
thread__resolve_callchain(util/machine.c)
thread__resolve_callchain_sample(util/machine.c)
add_callchain_ip(./util/machine.c)
thread__find_addr_location(./util/event.c)

The interesting thing is function machine__resolve(). It has a valid map
and sym pointer and this map (pointer to the kernel symbol table) is
used for the callchain. So we end up with a call chain and resolved symbols.



builtin-report.c:
I see a long list of symbol__new debug info, showing kernel symbols and addresses.

7991046816204 0x518 [0x80]: PERF_RECORD_SAMPLE(IP, 0x1): 4384/4384: 0x487b12 period: 250000 addr: 0
... FP chain: nr:10
.....  0: ffffffffffffff80
.....  1: 00000000002d6b86
.....  2: 00000000002d6c2e
.....  3: 00000000002da01a
.....  4: 00000000002da542
.....  5: 00000000002b5a26
.....  6: 00000000002d79c8
.....  7: 00000000002d7c00
.....  8: 00000000006a0624
.....  9: fffffffffffffe00
* process_sample_event 1
... thread: true:4384
* dso__load_vmlinux_path i:0 vmlinux err:-1
* dso__load_vmlinux_path i:1 /boot/vmlinux err:-1
* dso__load_vmlinux_path i:2 /boot/vmlinux-4.12.0perf+ err:-1
* dso__load_vmlinux_path i:3 /usr/lib/debug/boot/vmlinux-4.12.0perf+ err:-1
* dso__load_vmlinux_path i:4 /lib/modules/4.12.0perf+/build/vmlinux err:21340
...... dso: /lib/modules/4.12.0perf+/build/vmlinux
* machine__resolve al->filtered:0 al->map:0x76ca190 al->sym:0x7827f40
* process_sample_event al:0x488b12 sym:0x7827f40 map:0-0xa47000@0x1000 <-- printed after machine__resolve
* sample__resolve_callchain al->map:0x425cc190 al->sym:0x42729f40
* thread__resolve_callchain al->map:0x425cc190 al->sym:0x42729f40
* thread__resolve_callchain_sample al->map:0x425cc190 al->sym:0x42729f40
* thread__find_addr_location pid:4384 al->addr,0x6a0624 al->map:(nil) al->sym:(nil)
* thread__find_addr_location pid:4384 al->addr,0x2d7c00 al->map:(nil) al->sym:(nil)
* thread__find_addr_location pid:4384 al->addr,0x2d79c8 al->map:(nil) al->sym:(nil)
* thread__find_addr_location pid:4384 al->addr,0x2b5a26 al->map:(nil) al->sym:(nil)
* thread__find_addr_location pid:4384 al->addr,0x2da542 al->map:(nil) al->sym:(nil)
* thread__find_addr_location pid:4384 al->addr,0x2da01a al->map:(nil) al->sym:(nil)
* thread__find_addr_location pid:4384 al->addr,0x2d6c2e al->map:(nil) al->sym:(nil)
* thread__find_addr_location pid:4384 al->addr,0x2d6b86 al->map:(nil) al->sym:(nil)
* hist_entry_iter__add sample__resolve_callchain:0
* hists__add_entry al->addr:0x488b12, symbol:0x7827f40
* hists__add_entry start:0x488ad8 end:0x488d90 len:21 name:__rb_insert_augmented
* hist_iter__report_callback 1
* hists__add_entry al->addr:0x6a0624, symbol:(nil)
* hist_iter__report_callback 1
* hists__add_entry al->addr:0x2d7c00, symbol:(nil)
* hist_iter__report_callback 1
* hists__add_entry al->addr:0x2d79c8, symbol:(nil)
* hist_iter__report_callback 1
* hists__add_entry al->addr:0x2b5a26, symbol:(nil)
...

Function machine__resolve(util/event.c) returns the al->map and al->sym
pointers as in the builtin-script case.
The call chain is:
process_sample_event(builtin-report.c)
machine__resolve()
hist_entry_iter__add(./util/hist.c)
sample__resolve_callchain(util/callchain.c)
thread__resolve_callchain(util/machine.c)
thread__resolve_callchain_sample(util/machine.c)
add_callchain_ip(./util/machine.c)
thread__find_addr_location(./util/event.c)

Somehow that al->map information gets lost and later on the calls
thread__find_addr_location() this information is not available
and the lookup fails. And than the hist__add_entry fails as well.

I am still seeing tooooo much fog.....

This is not a threading issue??? That is perf report spawns threads and
one thread takes longer than the other thread and on s390x I hat some kind
of strange scheduling???
-- 
Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
--
Vorsitzende des Aufsichtsrats: Martina Koederitz 
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: perf report does not resolve symbols on s390x

[Thomas-Mich Richter]

On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
> On 07/05/2017 05:50 PM, Arnaldo Carvalho de Melo wrote:
>> Em Wed, Jul 05, 2017 at 04:45:49PM +0200, Thomas-Mich Richter escreveu:
>>> I use linux 4.12 kernel and the perf report --stdio does not resolve all symbols:
>>> Only very few symbols are resolved and none listed in the call back chain.
>>>
>>> Here is an example:
>>>
>>>     50.00%    50.00%  true     [kernel.vmlinux]  [k] __rb_insert_augmented
>>>             |
>>>             ---0x6a0624
>>>                0x2d7c00
>>>                0x2d79c8
>>>                0x2b5a26
>>>                0x2da542
>>>                0x2da01a
>>>                0x2d6c2e
>>>                0x2d6b86
>>>
>>>     50.00%     0.00%  true     [unknown]         [k] 0x000000000011e90a
>>>             |
>>>             ---0x11e90a
>>>                0x2d39a4
>>>                0x2d3238
>>>                0x288140
>>>                0x2cf404
>>>                0x2df5d8
>>>                0x31618c
>>>                0x19b0ae
>>>
>>> These addresses are all in the /proc/kallsyms and valid.
>>>
>>> When I do a perf script it works:
>>> [root@s8360046 perf]# perf script
>>
>> This is the strange part, 'script' resolving things 'report' doesn't,
>> they should be using the same machinery... Since the DSO is not being
>> resolved on the one failing above, this would look like its some
>> PERF_RECORD_MMAP/PERF_RECORD_MMAP2 that is being missed, so you should
>> look at the processing of such records, which is done via:
>>
>>  perf_tool.mmap() and perf_tool.mmap2()
>>
>> the perf_tool ops table is passed to:
>>
>>   perf_session__new(&file, false, &report.tool);
>>
>> Which will call the mmap() and mmap2() functions to process those
>> records, if you look at script it has:
>>
>>   
>>         struct perf_script script = {
>>                 .tool = {
>>                         .sample          = process_sample_event,
>>                         .mmap            = perf_event__process_mmap,
>>                         .mmap2           = perf_event__process_mmap2,
>> <SNIP>
>>
>> and then:
>>
>>   session = perf_session__new(&file, false, &script.tool);
>>
>> Which is the same as done for report:
>>
>>           struct report report = {
>>                 .tool = {
>>                         .sample          = process_sample_event,
>>                         .mmap            = perf_event__process_mmap,
>>                         .mmap2           = perf_event__process_mmap2,
>> <SNIP>
>>
>>   perf_session__new(&file, false, &report.tool);
>>
>> I.e. both use the same functions to resolve PERF_RECORD_MMAP/MMAP2 records,
>> then you should look at how samples are processed, its static functions, tool specific
>> functions, both named process_sample_event, in tools/perf/builtin->{report,script}.c,
>> and both will basically do:
>>
>>         if (machine__resolve(machine, &al, sample) < 0) {
>>                 pr_debug("problem processing %d event, skipping it.\n",
>>                          event->header.type);
>>                 return -1;
>>         }
>>
>> That will do lookups on trees populated by perf_event__process_mmap,
>> perf_event__process_mmap2, and the routines handling PERF_RECORD_FORK, etc.
>>
>> Is this enough to help you go from here to investigate your problem?
>>
>> - Arnaldo
>>
> 

[....]

> Somehow that al->map information gets lost and later on the calls
> thread__find_addr_location() this information is not available
> and the lookup fails. And than the hist__add_entry fails as well.
> 
> I am still seeing tooooo much fog.....
> 

The fog has lifted and I found the root cause. Digging into machine__resolve was the
right hint...

What happens is this (short version)
machine__resolve has map and sym pointers ( al->map:0x32629190 al->sym:0x32776f40 )
--> sample__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
    --> thread__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
        --> thread__resolve_callchain_sample
            creates a new struct addr_location to find the ip addr and its details.
            --> add_callchain_ip (cpumode:2 --> user space address indicator)
                --> thread__find_addr_map 
                    this function can not resolve the address and as a last action
                    tries to resolve the address within kernel address space 
                    --> machine__get_kernel_start

Now this function is interesting:

int machine__get_kernel_start(struct machine *machine)
{
        struct map *map = machine__kernel_map(machine);
        int err = 0;

        /*
         * The only addresses above 2^63 are kernel addresses of a 64-bit
         * kernel.  Note that addresses are unsigned so that on a 32-bit system
         * all addresses including kernel addresses are less than 2^32.  In
         * that case (32-bit system), if the kernel mapping is unknown, all
         * addresses will be assumed to be in user space - see
         * machine__kernel_ip().
         */
        machine->kernel_start = 1ULL << 63;
        if (map) {
                err = map__load(map);
                if (map->start)
                        machine->kernel_start = map->start;
        }
        return err;
}

It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
On s390x
- The kernel starts at 0x0 (value of map->start) and thus all checks in function 
  thread__find_addr_map() fail and no symbol is found for the specified addresses
  because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.

When I set this correctly (for example by setting kernel_start to 0x200) I get this:
 50.00%    50.00%  true     [kernel.vmlinux]  [k] lock_acquire
            |
            ---pgm_check_handler
               do_dat_exception
               handle_mm_fault
               __handle_mm_fault
               filemap_map_pages
               alloc_set_pte
               page_add_file_rmap
               lock_page_memcg
               lock_acquire


This raises 2 questions:
1. s390 has a 64 bit address space for user and kernel. The processor status word (PSW)
   determines which address space to use. That requires the PSW in the sample. Not sure
   this is the case?
2. How does this work on sparc and other architectures with the same addressing scheme?

Thanks.
-- 
Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
--
Vorsitzende des Aufsichtsrats: Martina Koederitz 
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: perf report does not resolve symbols on s390x

[Arnaldo Carvalho de Melo]

Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
> It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
> On s390x
> - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
>   thread__find_addr_map() fail and no symbol is found for the specified addresses
>   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.

oops, thanks for drilling down! We've had two other problems wrt s390
using 0 as the kernel start address, I'll dig the csets later, in a
hurry now, this is just another case where we have to consider zero a
valid address, will try and get this fixed.

- Arnaldo

Re: perf report does not resolve symbols on s390x

[Arnaldo Carvalho de Melo]

Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
> On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
> > On 07/05/2017 05:50 PM, Arnaldo Carvalho de Melo wrote:
> >> Em Wed, Jul 05, 2017 at 04:45:49PM +0200, Thomas-Mich Richter escreveu:
> >>> I use linux 4.12 kernel and the perf report --stdio does not resolve all symbols:
> >>> Only very few symbols are resolved and none listed in the call back chain.

> >>> Here is an example:

> >>>     50.00%    50.00%  true     [kernel.vmlinux]  [k] __rb_insert_augmented
> >>>             |
> >>>             ---0x6a0624
> >>>                0x2d7c00
> >>>                0x2d79c8
> >>>                0x2b5a26
> >>>                0x2da542
> >>>                0x2da01a
> >>>                0x2d6c2e
> >>>                0x2d6b86
> >>>
> >>>     50.00%     0.00%  true     [unknown]         [k] 0x000000000011e90a
> >>>             |
> >>>             ---0x11e90a
> >>>                0x2d39a4
> >>>                0x2d3238
> >>>                0x288140
> >>>                0x2cf404
> >>>                0x2df5d8
> >>>                0x31618c
> >>>                0x19b0ae

> >>> These addresses are all in the /proc/kallsyms and valid.

> >>> When I do a perf script it works:
> >>> [root@s8360046 perf]# perf script

> >> This is the strange part, 'script' resolving things 'report' doesn't,
> >> they should be using the same machinery... Since the DSO is not being
> >> resolved on the one failing above, this would look like its some
> >> PERF_RECORD_MMAP/PERF_RECORD_MMAP2 that is being missed, so you should
> >> look at the processing of such records, which is done via:

> >>  perf_tool.mmap() and perf_tool.mmap2()

> >> the perf_tool ops table is passed to:

> >>   perf_session__new(&file, false, &report.tool);

> >> Which will call the mmap() and mmap2() functions to process those
> >> records, if you look at script it has:

> >>         struct perf_script script = {
> >>                 .tool = {
> >>                         .sample          = process_sample_event,
> >>                         .mmap            = perf_event__process_mmap,
> >>                         .mmap2           = perf_event__process_mmap2,
> >> <SNIP>

> >> and then:

> >>   session = perf_session__new(&file, false, &script.tool);

> >> Which is the same as done for report:
> >>
> >>           struct report report = {
> >>                 .tool = {
> >>                         .sample          = process_sample_event,
> >>                         .mmap            = perf_event__process_mmap,
> >>                         .mmap2           = perf_event__process_mmap2,
> >> <SNIP>
> >>
> >>   perf_session__new(&file, false, &report.tool);
> >>
> >> I.e. both use the same functions to resolve PERF_RECORD_MMAP/MMAP2 records,
> >> then you should look at how samples are processed, its static functions, tool specific
> >> functions, both named process_sample_event, in tools/perf/builtin->{report,script}.c,
> >> and both will basically do:
> >>
> >>         if (machine__resolve(machine, &al, sample) < 0) {
> >>                 pr_debug("problem processing %d event, skipping it.\n",
> >>                          event->header.type);
> >>                 return -1;
> >>         }
> >>
> >> That will do lookups on trees populated by perf_event__process_mmap,
> >> perf_event__process_mmap2, and the routines handling PERF_RECORD_FORK, etc.
> >>
> >> Is this enough to help you go from here to investigate your problem?
 
> [....]
 
> > Somehow that al->map information gets lost and later on the calls
> > thread__find_addr_location() this information is not available
> > and the lookup fails. And than the hist__add_entry fails as well.

> > I am still seeing tooooo much fog.....
 
> The fog has lifted and I found the root cause. Digging into machine__resolve was the
> right hint...
 
> What happens is this (short version)
> machine__resolve has map and sym pointers ( al->map:0x32629190 al->sym:0x32776f40 )
> --> sample__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
>     --> thread__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
>         --> thread__resolve_callchain_sample
>             creates a new struct addr_location to find the ip addr and its details.
>             --> add_callchain_ip (cpumode:2 --> user space address indicator)
>                 --> thread__find_addr_map 
>                     this function can not resolve the address and as a last action
>                     tries to resolve the address within kernel address space 
>                     --> machine__get_kernel_start
 
> Now this function is interesting:
 
> int machine__get_kernel_start(struct machine *machine)
> {
>         struct map *map = machine__kernel_map(machine);
>         int err = 0;
 
>         /*
>          * The only addresses above 2^63 are kernel addresses of a 64-bit
>          * kernel.  Note that addresses are unsigned so that on a 32-bit system
>          * all addresses including kernel addresses are less than 2^32.  In
>          * that case (32-bit system), if the kernel mapping is unknown, all
>          * addresses will be assumed to be in user space - see
>          * machine__kernel_ip().
>          */
>         machine->kernel_start = 1ULL << 63;
>         if (map) {
>                 err = map__load(map);
>                 if (map->start)
>                         machine->kernel_start = map->start;
>         }
>         return err;
> }
 
> It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
> On s390x
> - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
>   thread__find_addr_map() fail and no symbol is found for the specified addresses
>   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.

Hi Thomas, really nice debugging session!

I'm trying the one-liner below, Adrian, can you please check this and
provide an ack? I think that that comment about the address that it will
default when map__load() fails needs rewriting in light of Thomas
comments about other arches (see further below)?

I did a quick check of machine->kernel_start usage in Intel PT and since
on x86 that assumption about partitioning the address space holds, no
problem should be introduced by the one-liner fix, right?

- Arnaldo

diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index 5de2b86b9880..2e9eb6aa3ce2 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -2209,7 +2209,7 @@ int machine__get_kernel_start(struct machine *machine)
 	machine->kernel_start = 1ULL << 63;
 	if (map) {
 		err = map__load(map);
-		if (map->start)
+		if (!err)
 			machine->kernel_start = map->start;
 	}
 	return err;

 
> When I set this correctly (for example by setting kernel_start to 0x200) I get this:
>  50.00%    50.00%  true     [kernel.vmlinux]  [k] lock_acquire
>             |
>             ---pgm_check_handler
>                do_dat_exception
>                handle_mm_fault
>                __handle_mm_fault
>                filemap_map_pages
>                alloc_set_pte
>                page_add_file_rmap
>                lock_page_memcg
>                lock_acquire
> 
> 
> This raises 2 questions:
> 1. s390 has a 64 bit address space for user and kernel. The processor status word (PSW)
>    determines which address space to use. That requires the PSW in the sample. Not sure
>    this is the case?
> 2. How does this work on sparc and other architectures with the same addressing scheme?
> 
> Thanks.
> -- 
> Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
> --
> Vorsitzende des Aufsichtsrats: Martina Koederitz 
> Geschäftsführung: Dirk Wittkopp
> Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: perf report does not resolve symbols on s390x

[Arnaldo Carvalho de Melo]

Em Tue, Jul 11, 2017 at 04:03:04PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
> > On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
> > > On 07/05/2017 05:50 PM, Arnaldo Carvalho de Melo wrote:
> > >> Em Wed, Jul 05, 2017 at 04:45:49PM +0200, Thomas-Mich Richter escreveu:
> > >>> I use linux 4.12 kernel and the perf report --stdio does not resolve all symbols:
> > >>> Only very few symbols are resolved and none listed in the call back chain.
> 
> > >>> Here is an example:
> 
> > >>>     50.00%    50.00%  true     [kernel.vmlinux]  [k] __rb_insert_augmented
> > >>>             |
> > >>>             ---0x6a0624
> > >>>                0x2d7c00
> > >>>                0x2d79c8
> > >>>                0x2b5a26
> > >>>                0x2da542
> > >>>                0x2da01a
> > >>>                0x2d6c2e
> > >>>                0x2d6b86
> > >>>
> > >>>     50.00%     0.00%  true     [unknown]         [k] 0x000000000011e90a
> > >>>             |
> > >>>             ---0x11e90a
> > >>>                0x2d39a4
> > >>>                0x2d3238
> > >>>                0x288140
> > >>>                0x2cf404
> > >>>                0x2df5d8
> > >>>                0x31618c
> > >>>                0x19b0ae
> 
> > >>> These addresses are all in the /proc/kallsyms and valid.
> 
> > >>> When I do a perf script it works:
> > >>> [root@s8360046 perf]# perf script
> 
> > >> This is the strange part, 'script' resolving things 'report' doesn't,
> > >> they should be using the same machinery... Since the DSO is not being
> > >> resolved on the one failing above, this would look like its some
> > >> PERF_RECORD_MMAP/PERF_RECORD_MMAP2 that is being missed, so you should
> > >> look at the processing of such records, which is done via:
> 
> > >>  perf_tool.mmap() and perf_tool.mmap2()
> 
> > >> the perf_tool ops table is passed to:
> 
> > >>   perf_session__new(&file, false, &report.tool);
> 
> > >> Which will call the mmap() and mmap2() functions to process those
> > >> records, if you look at script it has:
> 
> > >>         struct perf_script script = {
> > >>                 .tool = {
> > >>                         .sample          = process_sample_event,
> > >>                         .mmap            = perf_event__process_mmap,
> > >>                         .mmap2           = perf_event__process_mmap2,
> > >> <SNIP>
> 
> > >> and then:
> 
> > >>   session = perf_session__new(&file, false, &script.tool);
> 
> > >> Which is the same as done for report:
> > >>
> > >>           struct report report = {
> > >>                 .tool = {
> > >>                         .sample          = process_sample_event,
> > >>                         .mmap            = perf_event__process_mmap,
> > >>                         .mmap2           = perf_event__process_mmap2,
> > >> <SNIP>
> > >>
> > >>   perf_session__new(&file, false, &report.tool);
> > >>
> > >> I.e. both use the same functions to resolve PERF_RECORD_MMAP/MMAP2 records,
> > >> then you should look at how samples are processed, its static functions, tool specific
> > >> functions, both named process_sample_event, in tools/perf/builtin->{report,script}.c,
> > >> and both will basically do:
> > >>
> > >>         if (machine__resolve(machine, &al, sample) < 0) {
> > >>                 pr_debug("problem processing %d event, skipping it.\n",
> > >>                          event->header.type);
> > >>                 return -1;
> > >>         }
> > >>
> > >> That will do lookups on trees populated by perf_event__process_mmap,
> > >> perf_event__process_mmap2, and the routines handling PERF_RECORD_FORK, etc.
> > >>
> > >> Is this enough to help you go from here to investigate your problem?
>  
> > [....]
>  
> > > Somehow that al->map information gets lost and later on the calls
> > > thread__find_addr_location() this information is not available
> > > and the lookup fails. And than the hist__add_entry fails as well.
> 
> > > I am still seeing tooooo much fog.....
>  
> > The fog has lifted and I found the root cause. Digging into machine__resolve was the
> > right hint...
>  
> > What happens is this (short version)
> > machine__resolve has map and sym pointers ( al->map:0x32629190 al->sym:0x32776f40 )
> > --> sample__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
> >     --> thread__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
> >         --> thread__resolve_callchain_sample
> >             creates a new struct addr_location to find the ip addr and its details.
> >             --> add_callchain_ip (cpumode:2 --> user space address indicator)
> >                 --> thread__find_addr_map 
> >                     this function can not resolve the address and as a last action
> >                     tries to resolve the address within kernel address space 
> >                     --> machine__get_kernel_start
>  
> > Now this function is interesting:
>  
> > int machine__get_kernel_start(struct machine *machine)
> > {
> >         struct map *map = machine__kernel_map(machine);
> >         int err = 0;
>  
> >         /*
> >          * The only addresses above 2^63 are kernel addresses of a 64-bit
> >          * kernel.  Note that addresses are unsigned so that on a 32-bit system
> >          * all addresses including kernel addresses are less than 2^32.  In
> >          * that case (32-bit system), if the kernel mapping is unknown, all
> >          * addresses will be assumed to be in user space - see
> >          * machine__kernel_ip().
> >          */
> >         machine->kernel_start = 1ULL << 63;
> >         if (map) {
> >                 err = map__load(map);
> >                 if (map->start)
> >                         machine->kernel_start = map->start;
> >         }
> >         return err;
> > }
>  
> > It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
> > On s390x
> > - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
> >   thread__find_addr_map() fail and no symbol is found for the specified addresses
> >   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.
> 
> Hi Thomas, really nice debugging session!
> 
> I'm trying the one-liner below, Adrian, can you please check this and
> provide an ack? I think that that comment about the address that it will
> default when map__load() fails needs rewriting in light of Thomas
> comments about other arches (see further below)?
> 
> I did a quick check of machine->kernel_start usage in Intel PT and since
> on x86 that assumption about partitioning the address space holds, no
> problem should be introduced by the one-liner fix, right?

Argh, this is also broken:

static inline bool machine__kernel_ip(struct machine *machine, u64 ip)
{
        u64 kernel_start = machine__kernel_start(machine);

        return ip >= kernel_start;
}

We can't judge if a address is in the kernel like that :-\
 
> - Arnaldo
> 
> diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
> index 5de2b86b9880..2e9eb6aa3ce2 100644
> --- a/tools/perf/util/machine.c
> +++ b/tools/perf/util/machine.c
> @@ -2209,7 +2209,7 @@ int machine__get_kernel_start(struct machine *machine)
>  	machine->kernel_start = 1ULL << 63;
>  	if (map) {
>  		err = map__load(map);
> -		if (map->start)
> +		if (!err)
>  			machine->kernel_start = map->start;
>  	}
>  	return err;
> 
>  
> > When I set this correctly (for example by setting kernel_start to 0x200) I get this:
> >  50.00%    50.00%  true     [kernel.vmlinux]  [k] lock_acquire
> >             |
> >             ---pgm_check_handler
> >                do_dat_exception
> >                handle_mm_fault
> >                __handle_mm_fault
> >                filemap_map_pages
> >                alloc_set_pte
> >                page_add_file_rmap
> >                lock_page_memcg
> >                lock_acquire
> > 
> > 
> > This raises 2 questions:
> > 1. s390 has a 64 bit address space for user and kernel. The processor status word (PSW)
> >    determines which address space to use. That requires the PSW in the sample. Not sure
> >    this is the case?
> > 2. How does this work on sparc and other architectures with the same addressing scheme?
> > 
> > Thanks.
> > -- 
> > Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
> > --
> > Vorsitzende des Aufsichtsrats: Martina Koederitz 
> > Geschäftsführung: Dirk Wittkopp
> > Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: perf report does not resolve symbols on s390x

[Arnaldo Carvalho de Melo]

Em Tue, Jul 11, 2017 at 04:38:28PM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Tue, Jul 11, 2017 at 04:03:04PM -0300, Arnaldo Carvalho de Melo escreveu:
> > Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
> > > On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
> > > It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
> > > On s390x
> > > - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
> > >   thread__find_addr_map() fail and no symbol is found for the specified addresses
> > >   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.

> > Hi Thomas, really nice debugging session!

> > I'm trying the one-liner below, Adrian, can you please check this and
> > provide an ack? I think that that comment about the address that it will
> > default when map__load() fails needs rewriting in light of Thomas
> > comments about other arches (see further below)?

> > I did a quick check of machine->kernel_start usage in Intel PT and since
> > on x86 that assumption about partitioning the address space holds, no
> > problem should be introduced by the one-liner fix, right?
 
> Argh, this is also broken:
 
> static inline bool machine__kernel_ip(struct machine *machine, u64 ip)
> {
>         u64 kernel_start = machine__kernel_start(machine);
> 
>         return ip >= kernel_start;
> }
> 
> We can't judge if a address is in the kernel like that :-\

So, this is used by:

[acme@jouet linux]$ find tools/ -name "*.[ch]" | xargs grep -w machine__kernel_ip
tools/perf/builtin-script.c:	kernel = machine__kernel_ip(machine, start);
tools/perf/builtin-script.c:	if (kernel != machine__kernel_ip(machine, end)) {

That is just for "brstackinsn", would that make sense for Sparc, S/390?

tools/perf/util/intel-bts.c:	if (machine__kernel_ip(machine, ip))
tools/perf/util/intel-bts.c:		if (!machine__kernel_ip(btsq->bts->machine, branch->from) &&
tools/perf/util/intel-bts.c:		    machine__kernel_ip(btsq->bts->machine, branch->to) &&

Intel specific stuff, so should be ok.

tools/perf/util/event.c:		    machine__kernel_ip(machine, al->addr)) {

For this last one, that affects all arches, I think we can just remove
this check and look at the kernel when not finding it anywhere else?

diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
index dc5c3bb69d73..8e435baaae6a 100644
--- a/tools/perf/util/event.c
+++ b/tools/perf/util/event.c
@@ -1432,8 +1432,7 @@ void thread__find_addr_map(struct thread *thread, u8 cpumode,
 		 * in the whole kernel symbol list.
 		 */
 		if (cpumode == PERF_RECORD_MISC_USER && machine &&
-		    mg != &machine->kmaps &&
-		    machine__kernel_ip(machine, al->addr)) {
+		    mg != &machine->kmaps) {
 			mg = &machine->kmaps;
 			load_map = true;
 			goto try_again;

> > > This raises 2 questions:
> > > 1. s390 has a 64 bit address space for user and kernel. The processor status word (PSW)
> > >    determines which address space to use. That requires the PSW in the sample. Not sure
> > >    this is the case?
> > > 2. How does this work on sparc and other architectures with the same addressing scheme?
> > >
> > > Thanks.
> > > --
> > > Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany

Re: perf report does not resolve symbols on s390x

[Thomas-Mich Richter]

On 07/11/2017 09:48 PM, Arnaldo Carvalho de Melo wrote:
> Em Tue, Jul 11, 2017 at 04:38:28PM -0300, Arnaldo Carvalho de Melo escreveu:
>> Em Tue, Jul 11, 2017 at 04:03:04PM -0300, Arnaldo Carvalho de Melo escreveu:
>>> Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
.....

> 
>> Argh, this is also broken:
> 
>> static inline bool machine__kernel_ip(struct machine *machine, u64 ip)
>> {
>>         u64 kernel_start = machine__kernel_start(machine);
>>
>>         return ip >= kernel_start;
>> }
>>
>> We can't judge if a address is in the kernel like that :-\
> 
> So, this is used by:
> 
> [acme@jouet linux]$ find tools/ -name "*.[ch]" | xargs grep -w machine__kernel_ip
> tools/perf/builtin-script.c:	kernel = machine__kernel_ip(machine, start);
> tools/perf/builtin-script.c:	if (kernel != machine__kernel_ip(machine, end)) {
> 
> That is just for "brstackinsn", would that make sense for Sparc, S/390?

No we don't have that on s/390
> 
> tools/perf/util/intel-bts.c:	if (machine__kernel_ip(machine, ip))
> tools/perf/util/intel-bts.c:		if (!machine__kernel_ip(btsq->bts->machine, branch->from) &&
> tools/perf/util/intel-bts.c:		    machine__kernel_ip(btsq->bts->machine, branch->to) &&
> 
> Intel specific stuff, so should be ok.
> 
> tools/perf/util/event.c:		    machine__kernel_ip(machine, al->addr)) {
> 
> For this last one, that affects all arches, I think we can just remove
> this check and look at the kernel when not finding it anywhere else?
> 
> diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
> index dc5c3bb69d73..8e435baaae6a 100644
> --- a/tools/perf/util/event.c
> +++ b/tools/perf/util/event.c
> @@ -1432,8 +1432,7 @@ void thread__find_addr_map(struct thread *thread, u8 cpumode,
>  		 * in the whole kernel symbol list.
>  		 */
>  		if (cpumode == PERF_RECORD_MISC_USER && machine &&
> -		    mg != &machine->kmaps &&
> -		    machine__kernel_ip(machine, al->addr)) {
> +		    mg != &machine->kmaps) {
>  			mg = &machine->kmaps;
>  			load_map = true;
>  			goto try_again;
> 
>>>> This raises 2 questions:
>>>> 1. s390 has a 64 bit address space for user and kernel. The processor status word (PSW)
>>>>    determines which address space to use. That requires the PSW in the sample. Not sure
>>>>    this is the case?
>>>> 2. How does this work on sparc and other architectures with the same addressing scheme?
>>>>
>>>> Thanks.
>>>> --
>>>> Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 


-- 
Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
--
Vorsitzende des Aufsichtsrats: Martina Koederitz 
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294

Re: perf report does not resolve symbols on s390x

[Michael Ellerman]

Arnaldo Carvalho de Melo <acme@kernel.org> writes:

> Em Tue, Jul 11, 2017 at 04:38:28PM -0300, Arnaldo Carvalho de Melo escreveu:
>> Em Tue, Jul 11, 2017 at 04:03:04PM -0300, Arnaldo Carvalho de Melo escreveu:
>> > Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
>> > > On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
>> > > It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
>> > > On s390x
>> > > - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
>> > >   thread__find_addr_map() fail and no symbol is found for the specified addresses
>> > >   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.
>
>> > Hi Thomas, really nice debugging session!
>
>> > I'm trying the one-liner below, Adrian, can you please check this and
>> > provide an ack? I think that that comment about the address that it will
>> > default when map__load() fails needs rewriting in light of Thomas
>> > comments about other arches (see further below)?
>
>> > I did a quick check of machine->kernel_start usage in Intel PT and since
>> > on x86 that assumption about partitioning the address space holds, no
>> > problem should be introduced by the one-liner fix, right?
>  
>> Argh, this is also broken:
>  
>> static inline bool machine__kernel_ip(struct machine *machine, u64 ip)
>> {
>>         u64 kernel_start = machine__kernel_start(machine);
>> 
>>         return ip >= kernel_start;
>> }
>> 
>> We can't judge if a address is in the kernel like that :-\
>
> So, this is used by:
>
> [acme@jouet linux]$ find tools/ -name "*.[ch]" | xargs grep -w machine__kernel_ip
> tools/perf/builtin-script.c:	kernel = machine__kernel_ip(machine, start);
> tools/perf/builtin-script.c:	if (kernel != machine__kernel_ip(machine, end)) {
>
> That is just for "brstackinsn", would that make sense for Sparc, S/390?
>
> tools/perf/util/intel-bts.c:	if (machine__kernel_ip(machine, ip))
> tools/perf/util/intel-bts.c:		if (!machine__kernel_ip(btsq->bts->machine, branch->from) &&
> tools/perf/util/intel-bts.c:		    machine__kernel_ip(btsq->bts->machine, branch->to) &&
>
> Intel specific stuff, so should be ok.
>
> tools/perf/util/event.c:		    machine__kernel_ip(machine, al->addr)) {
>
> For this last one, that affects all arches, I think we can just remove
> this check and look at the kernel when not finding it anywhere else?
>
> diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
> index dc5c3bb69d73..8e435baaae6a 100644
> --- a/tools/perf/util/event.c
> +++ b/tools/perf/util/event.c
> @@ -1432,8 +1432,7 @@ void thread__find_addr_map(struct thread *thread, u8 cpumode,
>  		 * in the whole kernel symbol list.
>  		 */
>  		if (cpumode == PERF_RECORD_MISC_USER && machine &&
> -		    mg != &machine->kmaps &&
> -		    machine__kernel_ip(machine, al->addr)) {
> +		    mg != &machine->kmaps) {
>  			mg = &machine->kmaps;
>  			load_map = true;
>  			goto try_again;

Am I reading this right? We have a sample that claims to be in
userspace, but was not found in any symbol map, so we try looking for it
in the kernel map.

And the change is that previously we checked if the address was >= (1 << 63),
whereas after we don't bother.

Seems harmless™.

cheers

Re: perf report does not resolve symbols on s390x

[Arnaldo Carvalho de Melo]

Em Wed, Jul 12, 2017 at 08:40:57PM +1000, Michael Ellerman escreveu:
> Arnaldo Carvalho de Melo <acme@kernel.org> writes:
> 
> > Em Tue, Jul 11, 2017 at 04:38:28PM -0300, Arnaldo Carvalho de Melo escreveu:
> >> Em Tue, Jul 11, 2017 at 04:03:04PM -0300, Arnaldo Carvalho de Melo escreveu:
> >> > Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
> >> > > On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
> >> > > It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
> >> > > On s390x
> >> > > - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
> >> > >   thread__find_addr_map() fail and no symbol is found for the specified addresses
> >> > >   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.
> >
> >> > Hi Thomas, really nice debugging session!
> >
> >> > I'm trying the one-liner below, Adrian, can you please check this and
> >> > provide an ack? I think that that comment about the address that it will
> >> > default when map__load() fails needs rewriting in light of Thomas
> >> > comments about other arches (see further below)?
> >
> >> > I did a quick check of machine->kernel_start usage in Intel PT and since
> >> > on x86 that assumption about partitioning the address space holds, no
> >> > problem should be introduced by the one-liner fix, right?
> >  
> >> Argh, this is also broken:
> >  
> >> static inline bool machine__kernel_ip(struct machine *machine, u64 ip)
> >> {
> >>         u64 kernel_start = machine__kernel_start(machine);
> >> 
> >>         return ip >= kernel_start;
> >> }
> >> 
> >> We can't judge if a address is in the kernel like that :-\
> >
> > So, this is used by:
> >
> > [acme@jouet linux]$ find tools/ -name "*.[ch]" | xargs grep -w machine__kernel_ip
> > tools/perf/builtin-script.c:	kernel = machine__kernel_ip(machine, start);
> > tools/perf/builtin-script.c:	if (kernel != machine__kernel_ip(machine, end)) {
> >
> > That is just for "brstackinsn", would that make sense for Sparc, S/390?
> >
> > tools/perf/util/intel-bts.c:	if (machine__kernel_ip(machine, ip))
> > tools/perf/util/intel-bts.c:		if (!machine__kernel_ip(btsq->bts->machine, branch->from) &&
> > tools/perf/util/intel-bts.c:		    machine__kernel_ip(btsq->bts->machine, branch->to) &&
> >
> > Intel specific stuff, so should be ok.
> >
> > tools/perf/util/event.c:		    machine__kernel_ip(machine, al->addr)) {
> >
> > For this last one, that affects all arches, I think we can just remove
> > this check and look at the kernel when not finding it anywhere else?
> >
> > diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
> > index dc5c3bb69d73..8e435baaae6a 100644
> > --- a/tools/perf/util/event.c
> > +++ b/tools/perf/util/event.c
> > @@ -1432,8 +1432,7 @@ void thread__find_addr_map(struct thread *thread, u8 cpumode,
> >  		 * in the whole kernel symbol list.
> >  		 */
> >  		if (cpumode == PERF_RECORD_MISC_USER && machine &&
> > -		    mg != &machine->kmaps &&
> > -		    machine__kernel_ip(machine, al->addr)) {
> > +		    mg != &machine->kmaps) {
> >  			mg = &machine->kmaps;
> >  			load_map = true;
> >  			goto try_again;
> 
> Am I reading this right? We have a sample that claims to be in
> userspace, but was not found in any symbol map, so we try looking for it
> in the kernel map.
> 
> And the change is that previously we checked if the address was >= (1 << 63),
> whereas after we don't bother.
> 
> Seems harmless™.

Thanks, will take that as an Acked-by:, ok?

 
> cheers

Re: perf report does not resolve symbols on s390x

[Michael Ellerman]

Arnaldo Carvalho de Melo <acme@kernel.org> writes:

> Em Wed, Jul 12, 2017 at 08:40:57PM +1000, Michael Ellerman escreveu:
>> Arnaldo Carvalho de Melo <acme@kernel.org> writes:
>> 
>> > Em Tue, Jul 11, 2017 at 04:38:28PM -0300, Arnaldo Carvalho de Melo escreveu:
>> >> Em Tue, Jul 11, 2017 at 04:03:04PM -0300, Arnaldo Carvalho de Melo escreveu:
>> >> > Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
>> >> > > On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
>> >> > > It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
>> >> > > On s390x
>> >> > > - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
>> >> > >   thread__find_addr_map() fail and no symbol is found for the specified addresses
>> >> > >   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.
>> >
>> >> > Hi Thomas, really nice debugging session!
>> >
>> >> > I'm trying the one-liner below, Adrian, can you please check this and
>> >> > provide an ack? I think that that comment about the address that it will
>> >> > default when map__load() fails needs rewriting in light of Thomas
>> >> > comments about other arches (see further below)?
>> >
>> >> > I did a quick check of machine->kernel_start usage in Intel PT and since
>> >> > on x86 that assumption about partitioning the address space holds, no
>> >> > problem should be introduced by the one-liner fix, right?
>> >  
>> >> Argh, this is also broken:
>> >  
>> >> static inline bool machine__kernel_ip(struct machine *machine, u64 ip)
>> >> {
>> >>         u64 kernel_start = machine__kernel_start(machine);
>> >> 
>> >>         return ip >= kernel_start;
>> >> }
>> >> 
>> >> We can't judge if a address is in the kernel like that :-\
>> >
>> > So, this is used by:
>> >
>> > [acme@jouet linux]$ find tools/ -name "*.[ch]" | xargs grep -w machine__kernel_ip
>> > tools/perf/builtin-script.c:	kernel = machine__kernel_ip(machine, start);
>> > tools/perf/builtin-script.c:	if (kernel != machine__kernel_ip(machine, end)) {
>> >
>> > That is just for "brstackinsn", would that make sense for Sparc, S/390?
>> >
>> > tools/perf/util/intel-bts.c:	if (machine__kernel_ip(machine, ip))
>> > tools/perf/util/intel-bts.c:		if (!machine__kernel_ip(btsq->bts->machine, branch->from) &&
>> > tools/perf/util/intel-bts.c:		    machine__kernel_ip(btsq->bts->machine, branch->to) &&
>> >
>> > Intel specific stuff, so should be ok.
>> >
>> > tools/perf/util/event.c:		    machine__kernel_ip(machine, al->addr)) {
>> >
>> > For this last one, that affects all arches, I think we can just remove
>> > this check and look at the kernel when not finding it anywhere else?
>> >
>> > diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
>> > index dc5c3bb69d73..8e435baaae6a 100644
>> > --- a/tools/perf/util/event.c
>> > +++ b/tools/perf/util/event.c
>> > @@ -1432,8 +1432,7 @@ void thread__find_addr_map(struct thread *thread, u8 cpumode,
>> >  		 * in the whole kernel symbol list.
>> >  		 */
>> >  		if (cpumode == PERF_RECORD_MISC_USER && machine &&
>> > -		    mg != &machine->kmaps &&
>> > -		    machine__kernel_ip(machine, al->addr)) {
>> > +		    mg != &machine->kmaps) {
>> >  			mg = &machine->kmaps;
>> >  			load_map = true;
>> >  			goto try_again;
>> 
>> Am I reading this right? We have a sample that claims to be in
>> userspace, but was not found in any symbol map, so we try looking for it
>> in the kernel map.
>> 
>> And the change is that previously we checked if the address was >= (1 << 63),
>> whereas after we don't bother.
>> 
>> Seems harmless™.
>
> Thanks, will take that as an Acked-by:, ok?

Seems-harmless-but-will-probably-break-something-obscure-by: ... :)

Sure.

Acked-by: Michael Ellerman <mpe@ellerman.id.au> (powerpc)

cheers

Re: perf report does not resolve symbols on s390x

[Thomas-Mich Richter]

On 07/11/2017 09:03 PM, Arnaldo Carvalho de Melo wrote:
> Em Fri, Jul 07, 2017 at 02:17:25PM +0200, Thomas-Mich Richter escreveu:
>> On 07/06/2017 02:35 PM, Thomas-Mich Richter wrote:
>>> On 07/05/2017 05:50 PM, Arnaldo Carvalho de Melo wrote:

[...]

>> The fog has lifted and I found the root cause. Digging into machine__resolve was the
>> right hint...
> 
>> What happens is this (short version)
>> machine__resolve has map and sym pointers ( al->map:0x32629190 al->sym:0x32776f40 )
>> --> sample__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
>>     --> thread__resolve_callchain al->map:0x32629190 al->sym:0x32776f40
>>         --> thread__resolve_callchain_sample
>>             creates a new struct addr_location to find the ip addr and its details.
>>             --> add_callchain_ip (cpumode:2 --> user space address indicator)
>>                 --> thread__find_addr_map 
>>                     this function can not resolve the address and as a last action
>>                     tries to resolve the address within kernel address space 
>>                     --> machine__get_kernel_start
> 
>> Now this function is interesting:
> 
>> int machine__get_kernel_start(struct machine *machine)
>> {
>>         struct map *map = machine__kernel_map(machine);
>>         int err = 0;
> 
>>         /*
>>          * The only addresses above 2^63 are kernel addresses of a 64-bit
>>          * kernel.  Note that addresses are unsigned so that on a 32-bit system
>>          * all addresses including kernel addresses are less than 2^32.  In
>>          * that case (32-bit system), if the kernel mapping is unknown, all
>>          * addresses will be assumed to be in user space - see
>>          * machine__kernel_ip().
>>          */
>>         machine->kernel_start = 1ULL << 63;
>>         if (map) {
>>                 err = map__load(map);
>>                 if (map->start)
>>                         machine->kernel_start = map->start;
>>         }
>>         return err;
>> }
> 
>> It determines the kernel starts at address 1<<63 and loads the kernel address mapping.
>> On s390x
>> - The kernel starts at 0x0 (value of map->start) and thus all checks in function 
>>   thread__find_addr_map() fail and no symbol is found for the specified addresses
>>   because the kernel starts at 0x8000000000000000. Which is wrong the kernel start at 0x0.
> 
> Hi Thomas, really nice debugging session!

Thanks for the credit.... :-)
> 
> I'm trying the one-liner below, Adrian, can you please check this and
> provide an ack? I think that that comment about the address that it will
> default when map__load() fails needs rewriting in light of Thomas
> comments about other arches (see further below)?
> 
> I did a quick check of machine->kernel_start usage in Intel PT and since
> on x86 that assumption about partitioning the address space holds, no
> problem should be introduced by the one-liner fix, right?
> 
> - Arnaldo
> 
> diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
> index 5de2b86b9880..2e9eb6aa3ce2 100644
> --- a/tools/perf/util/machine.c
> +++ b/tools/perf/util/machine.c
> @@ -2209,7 +2209,7 @@ int machine__get_kernel_start(struct machine *machine)
>  	machine->kernel_start = 1ULL << 63;
>  	if (map) {
>  		err = map__load(map);
> -		if (map->start)
> +		if (!err)
>  			machine->kernel_start = map->start;
>  	}
>  	return err;
> 
> 

I like this patch. I have done a new build and removed all my debug output to start
from scratch. Without your patch I get this:

 To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 4  of event 'cpu-clock'
# Event count (approx.): 1000000
#
# Children      Self  Command  Shared Object     Symbol                  
# ........  ........  .......  ................  ........................
#
    75.00%     0.00%  true     [unknown]         [k] 0x00000000004bedda
            |
            ---0x4bedda
               |          
               |--50.00%--0x42693a
               |          |          
               |           --25.00%--0x2a72e0
               |                     0x2af0ca
               |                     0x3d1003fe4c0
               |          
                --25.00%--0x4272bc
                          0x26fa84


and with your patch (I just rebuilt the perf tool, nothing else and used the same
perf.data file as input):

# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 4  of event 'cpu-clock'
# Event count (approx.): 1000000
#
# Children      Self  Command  Shared Object               Symbol                            
# ........  ........  .......  ..........................  ..................................
#
    75.00%     0.00%  true     [kernel.vmlinux]            [k] pgm_check_handler
            |
            ---pgm_check_handler
               do_dat_exception
               handle_mm_fault
               __handle_mm_fault
               filemap_map_pages
               |          
               |--25.00%--rcu_read_lock_held
               |          rcu_lockdep_current_cpu_online
               |          0x3d1003ff4c0
               |          
                --25.00%--lock_release


Looks good to me....

>> -- 
>> Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
>> --
>> Vorsitzende des Aufsichtsrats: Martina Koederitz 
>> Geschäftsführung: Dirk Wittkopp
>> Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294
> 


-- 
Thomas Richter, Dept 3303, IBM LTC Boeblingen Germany
--
Vorsitzende des Aufsichtsrats: Martina Koederitz 
Geschäftsführung: Dirk Wittkopp
Sitz der Gesellschaft: Böblingen / Registergericht: Amtsgericht Stuttgart, HRB 243294