Re: perf report does not resolve symbols on s390x

[Arnaldo Carvalho de Melo <acme@kernel.org>]

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