perf script : wrong symoff in callchain

mirror of https://lore.kernel.org/lkml/
 help / color / mirror / Atom feed

* perf script : wrong symoff in callchain
@ 2017-10-03 10:19 Matthieu CASTET
  2017-10-03 10:34 ` Adrian Hunter
  0 siblings, 1 reply; 4+ messages in thread
From: Matthieu CASTET @ 2017-10-03 10:19 UTC (permalink / raw)
  To: linux-kernel; +Cc: Arnaldo Carvalho de Melo, Adrian Hunter

Hi,

while using perf on x86_64, I saw strange output for symoff.

$ perf record -g -- sleep 1
$ perf script -F comm,tid,pid,time,ip,sym,dso,symoff

[...]
sleep 11656/11656 1045318.546436: 
            7fff9542e5b5 __d_lookup_rcu+0x80006ae02035 ([kernel.kallsyms])
            7fff9541e132 lookup_fast+0x80006ae02052 ([kernel.kallsyms])
            7fff9541eae8 walk_component+0x80006ae02048 ([kernel.kallsyms])
            7fff9541efa2 link_path_walk+0x80006ae021b2 ([kernel.kallsyms])
            7fff9541c92d path_init+0x80006ae021bd ([kernel.kallsyms])
            7fff9542100b path_openat+0x80006ae020fb ([kernel.kallsyms])
            7fff953c14fe handle_mm_fault+0x80006ae020ee ([kernel.kallsyms])
            7fff95423669 do_filp_open+0x80006ae02099 ([kernel.kallsyms])
            7fff95433414 __alloc_fd+0x80006ae02044 ([kernel.kallsyms])
            7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
            7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
            7fff95850abb system_call_fast_compare_end+0x80006ae0200c ([kernel.kallsyms])
                   2aecf _nl_load_locale_from_archive+0xffff014b5a92841f (/lib/x86_64-linux-gnu/libc-2.24.so)


I tried to revert a4eb24a49566db77ee999b46603f602a0302f481 and I got
good result :
[...]
sleep 11656/11656 1045318.546436: 
            7fff9542e5b5 __d_lookup_rcu+0x35 ([kernel.kallsyms])
            7fff9541e132 lookup_fast+0x52 ([kernel.kallsyms])
            7fff9541eae8 walk_component+0x48 ([kernel.kallsyms])
            7fff9541efa2 link_path_walk+0x1b2 ([kernel.kallsyms])
            7fff9541c92d path_init+0x1bd ([kernel.kallsyms])
            7fff9542100b path_openat+0xfb ([kernel.kallsyms])
            7fff953c14fe handle_mm_fault+0xee ([kernel.kallsyms])
            7fff95423669 do_filp_open+0x99 ([kernel.kallsyms])
            7fff95433414 __alloc_fd+0x44 ([kernel.kallsyms])
            7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
            7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
            7fff95850abb system_call_fast_compare_end+0xc ([kernel.kallsyms])
                   2aecf _nl_load_locale_from_archive+0x41f (/lib/x86_64-linux-gnu/libc-2.24.so)


Any idea ?


Regards,

Matthieu

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: perf script : wrong symoff in callchain
  2017-10-03 10:19 perf script : wrong symoff in callchain Matthieu CASTET
@ 2017-10-03 10:34 ` Adrian Hunter
  2017-10-03 11:45   ` Matthieu CASTET
  0 siblings, 1 reply; 4+ messages in thread
From: Adrian Hunter @ 2017-10-03 10:34 UTC (permalink / raw)
  To: Matthieu CASTET, linux-kernel; +Cc: Arnaldo Carvalho de Melo

On 03/10/17 13:19, Matthieu CASTET wrote:
> Hi,
> 
> while using perf on x86_64, I saw strange output for symoff.
> 
> $ perf record -g -- sleep 1
> $ perf script -F comm,tid,pid,time,ip,sym,dso,symoff
> 
> [...]
> sleep 11656/11656 1045318.546436: 
>             7fff9542e5b5 __d_lookup_rcu+0x80006ae02035 ([kernel.kallsyms])
>             7fff9541e132 lookup_fast+0x80006ae02052 ([kernel.kallsyms])
>             7fff9541eae8 walk_component+0x80006ae02048 ([kernel.kallsyms])
>             7fff9541efa2 link_path_walk+0x80006ae021b2 ([kernel.kallsyms])
>             7fff9541c92d path_init+0x80006ae021bd ([kernel.kallsyms])
>             7fff9542100b path_openat+0x80006ae020fb ([kernel.kallsyms])
>             7fff953c14fe handle_mm_fault+0x80006ae020ee ([kernel.kallsyms])
>             7fff95423669 do_filp_open+0x80006ae02099 ([kernel.kallsyms])
>             7fff95433414 __alloc_fd+0x80006ae02044 ([kernel.kallsyms])
>             7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
>             7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
>             7fff95850abb system_call_fast_compare_end+0x80006ae0200c ([kernel.kallsyms])
>                    2aecf _nl_load_locale_from_archive+0xffff014b5a92841f (/lib/x86_64-linux-gnu/libc-2.24.so)
> 
> 
> I tried to revert a4eb24a49566db77ee999b46603f602a0302f481 and I got
> good result :
> [...]
> sleep 11656/11656 1045318.546436: 
>             7fff9542e5b5 __d_lookup_rcu+0x35 ([kernel.kallsyms])
>             7fff9541e132 lookup_fast+0x52 ([kernel.kallsyms])
>             7fff9541eae8 walk_component+0x48 ([kernel.kallsyms])
>             7fff9541efa2 link_path_walk+0x1b2 ([kernel.kallsyms])
>             7fff9541c92d path_init+0x1bd ([kernel.kallsyms])
>             7fff9542100b path_openat+0xfb ([kernel.kallsyms])
>             7fff953c14fe handle_mm_fault+0xee ([kernel.kallsyms])
>             7fff95423669 do_filp_open+0x99 ([kernel.kallsyms])
>             7fff95433414 __alloc_fd+0x44 ([kernel.kallsyms])
>             7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
>             7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
>             7fff95850abb system_call_fast_compare_end+0xc ([kernel.kallsyms])
>                    2aecf _nl_load_locale_from_archive+0x41f (/lib/x86_64-linux-gnu/libc-2.24.so)
> 
> 
> Any idea ?

It could be the problem with add_callchain_ip() described here:

	https://www.spinics.net/lists/linux-perf-users/msg03172.html

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: perf script : wrong symoff in callchain
  2017-10-03 10:34 ` Adrian Hunter
@ 2017-10-03 11:45   ` Matthieu CASTET
  2017-10-04  7:12     ` Adrian Hunter
  0 siblings, 1 reply; 4+ messages in thread
From: Matthieu CASTET @ 2017-10-03 11:45 UTC (permalink / raw)
  To: Adrian Hunter; +Cc: linux-kernel, Arnaldo Carvalho de Melo, Chris Phlipot

Le Tue, 3 Oct 2017 13:34:37 +0300,
Adrian Hunter <adrian.hunter@intel.com> a écrit :

> On 03/10/17 13:19, Matthieu CASTET wrote:
> > Hi,
> > 
> > while using perf on x86_64, I saw strange output for symoff.
> > 
> > $ perf record -g -- sleep 1
> > $ perf script -F comm,tid,pid,time,ip,sym,dso,symoff
> > 
> > [...]
> > sleep 11656/11656 1045318.546436: 
> >             7fff9542e5b5 __d_lookup_rcu+0x80006ae02035 ([kernel.kallsyms])
> >             7fff9541e132 lookup_fast+0x80006ae02052 ([kernel.kallsyms])
> >             7fff9541eae8 walk_component+0x80006ae02048 ([kernel.kallsyms])
> >             7fff9541efa2 link_path_walk+0x80006ae021b2 ([kernel.kallsyms])
> >             7fff9541c92d path_init+0x80006ae021bd ([kernel.kallsyms])
> >             7fff9542100b path_openat+0x80006ae020fb ([kernel.kallsyms])
> >             7fff953c14fe handle_mm_fault+0x80006ae020ee ([kernel.kallsyms])
> >             7fff95423669 do_filp_open+0x80006ae02099 ([kernel.kallsyms])
> >             7fff95433414 __alloc_fd+0x80006ae02044 ([kernel.kallsyms])
> >             7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
> >             7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
> >             7fff95850abb system_call_fast_compare_end+0x80006ae0200c ([kernel.kallsyms])
> >                    2aecf _nl_load_locale_from_archive+0xffff014b5a92841f (/lib/x86_64-linux-gnu/libc-2.24.so)
> > 
> > 
> > I tried to revert a4eb24a49566db77ee999b46603f602a0302f481 and I got
> > good result :
> > [...]
> > sleep 11656/11656 1045318.546436: 
> >             7fff9542e5b5 __d_lookup_rcu+0x35 ([kernel.kallsyms])
> >             7fff9541e132 lookup_fast+0x52 ([kernel.kallsyms])
> >             7fff9541eae8 walk_component+0x48 ([kernel.kallsyms])
> >             7fff9541efa2 link_path_walk+0x1b2 ([kernel.kallsyms])
> >             7fff9541c92d path_init+0x1bd ([kernel.kallsyms])
> >             7fff9542100b path_openat+0xfb ([kernel.kallsyms])
> >             7fff953c14fe handle_mm_fault+0xee ([kernel.kallsyms])
> >             7fff95423669 do_filp_open+0x99 ([kernel.kallsyms])
> >             7fff95433414 __alloc_fd+0x44 ([kernel.kallsyms])
> >             7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
> >             7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
> >             7fff95850abb system_call_fast_compare_end+0xc ([kernel.kallsyms])
> >                    2aecf _nl_load_locale_from_archive+0x41f (/lib/x86_64-linux-gnu/libc-2.24.so)
> > 
> > 
> > Any idea ?  
> 
> It could be the problem with add_callchain_ip() described here:
> 
> 	https://www.spinics.net/lists/linux-perf-users/msg03172.html

The db-export code removed the remapping [1]

So there a mix of mapping in callchain code :
- add_callchain_ip() store al.addr (ip remapped)
- fill_callchain_info do the translation (map_ip)
- sample__fprintf_callchain do the translation
- call_path_from_sample (db-export) don't do anymore the translation


So what should we do : 
- assume we store al.addr and remove mapping from all consumers ?
- store ip and do the mapping in consumers ?



[1]
commit 7a2544c004a6c576b1e307f30925b165affe6a22
Author: Chris Phlipot <cphlipot0@gmail.com>
Date:   Tue May 10 20:26:48 2016 -0700

    perf script: Fix callchain addresses in db-export
    
    Remove the call to map_ip() to adjust al.addr, because it has already
    been called when assembling the callchain, in:
    
      thread__resolve_callchain_sample(perf_sample)
          add_callchain_ip(ip = perf_sample->callchain->ips[j])
              thread__find_addr_location(addr = ip)
                  thread__find_addr_map(addr) {
                      al->addr = addr
                      if (al->map)
                          al->addr = al->map->map_ip(al->map, al->addr);
                  }
    
    Calling it a second time can result in incorrect addresses being used.
    This can have effects such as duplicate symbols being created and
    exported.

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: perf script : wrong symoff in callchain
  2017-10-03 11:45   ` Matthieu CASTET
@ 2017-10-04  7:12     ` Adrian Hunter
  0 siblings, 0 replies; 4+ messages in thread
From: Adrian Hunter @ 2017-10-04  7:12 UTC (permalink / raw)
  To: Matthieu CASTET; +Cc: linux-kernel, Arnaldo Carvalho de Melo, Chris Phlipot

On 03/10/17 14:45, Matthieu CASTET wrote:
> Le Tue, 3 Oct 2017 13:34:37 +0300,
> Adrian Hunter <adrian.hunter@intel.com> a écrit :
> 
>> On 03/10/17 13:19, Matthieu CASTET wrote:
>>> Hi,
>>>
>>> while using perf on x86_64, I saw strange output for symoff.
>>>
>>> $ perf record -g -- sleep 1
>>> $ perf script -F comm,tid,pid,time,ip,sym,dso,symoff
>>>
>>> [...]
>>> sleep 11656/11656 1045318.546436: 
>>>             7fff9542e5b5 __d_lookup_rcu+0x80006ae02035 ([kernel.kallsyms])
>>>             7fff9541e132 lookup_fast+0x80006ae02052 ([kernel.kallsyms])
>>>             7fff9541eae8 walk_component+0x80006ae02048 ([kernel.kallsyms])
>>>             7fff9541efa2 link_path_walk+0x80006ae021b2 ([kernel.kallsyms])
>>>             7fff9541c92d path_init+0x80006ae021bd ([kernel.kallsyms])
>>>             7fff9542100b path_openat+0x80006ae020fb ([kernel.kallsyms])
>>>             7fff953c14fe handle_mm_fault+0x80006ae020ee ([kernel.kallsyms])
>>>             7fff95423669 do_filp_open+0x80006ae02099 ([kernel.kallsyms])
>>>             7fff95433414 __alloc_fd+0x80006ae02044 ([kernel.kallsyms])
>>>             7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
>>>             7fff9540ff6e do_sys_open+0x80006ae0212e ([kernel.kallsyms])
>>>             7fff95850abb system_call_fast_compare_end+0x80006ae0200c ([kernel.kallsyms])
>>>                    2aecf _nl_load_locale_from_archive+0xffff014b5a92841f (/lib/x86_64-linux-gnu/libc-2.24.so)
>>>
>>>
>>> I tried to revert a4eb24a49566db77ee999b46603f602a0302f481 and I got
>>> good result :
>>> [...]
>>> sleep 11656/11656 1045318.546436: 
>>>             7fff9542e5b5 __d_lookup_rcu+0x35 ([kernel.kallsyms])
>>>             7fff9541e132 lookup_fast+0x52 ([kernel.kallsyms])
>>>             7fff9541eae8 walk_component+0x48 ([kernel.kallsyms])
>>>             7fff9541efa2 link_path_walk+0x1b2 ([kernel.kallsyms])
>>>             7fff9541c92d path_init+0x1bd ([kernel.kallsyms])
>>>             7fff9542100b path_openat+0xfb ([kernel.kallsyms])
>>>             7fff953c14fe handle_mm_fault+0xee ([kernel.kallsyms])
>>>             7fff95423669 do_filp_open+0x99 ([kernel.kallsyms])
>>>             7fff95433414 __alloc_fd+0x44 ([kernel.kallsyms])
>>>             7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
>>>             7fff9540ff6e do_sys_open+0x12e ([kernel.kallsyms])
>>>             7fff95850abb system_call_fast_compare_end+0xc ([kernel.kallsyms])
>>>                    2aecf _nl_load_locale_from_archive+0x41f (/lib/x86_64-linux-gnu/libc-2.24.so)
>>>
>>>
>>> Any idea ?  
>>
>> It could be the problem with add_callchain_ip() described here:
>>
>> 	https://www.spinics.net/lists/linux-perf-users/msg03172.html
> 
> The db-export code removed the remapping [1]
> 
> So there a mix of mapping in callchain code :
> - add_callchain_ip() store al.addr (ip remapped)
> - fill_callchain_info do the translation (map_ip)
> - sample__fprintf_callchain do the translation
> - call_path_from_sample (db-export) don't do anymore the translation
> 
> 
> So what should we do : 
> - assume we store al.addr and remove mapping from all consumers ?

Seems it got changed to al.addr (per below), so I guess we should
remove mapping from all consumers.


commit 5550171b2a9f8df26ff483051d060db06376b26d
Author: Andi Kleen <ak@linux.intel.com>
Date:   Wed Nov 12 18:05:21 2014 -0800

    perf callchain: Use al.addr to set up call chain

    Use the relative address, this makes get_srcline work correctly in the
    end.

    Signed-off-by: Andi Kleen <ak@linux.intel.com>
    Cc: Jiri Olsa <jolsa@redhat.com>
    Cc: Namhyung Kim <namhyung@kernel.org>
    Link: http://lkml.kernel.org/r/1415844328-4884-4-git-send-email-andi@firstfloor.org
    Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index 84390ee..d97309c 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -1406,7 +1406,7 @@ static int add_callchain_ip(struct thread *thread,
                }
        }

-       return callchain_cursor_append(&callchain_cursor, ip, al.map, al.sym);
+       return callchain_cursor_append(&callchain_cursor, al.addr, al.map, al.sym);
 }

 struct branch_info *sample__resolve_bstack(struct perf_sample *sample,


> - store ip and do the mapping in consumers ?
> 
> 
> 
> [1]
> commit 7a2544c004a6c576b1e307f30925b165affe6a22
> Author: Chris Phlipot <cphlipot0@gmail.com>
> Date:   Tue May 10 20:26:48 2016 -0700
> 
>     perf script: Fix callchain addresses in db-export
>     
>     Remove the call to map_ip() to adjust al.addr, because it has already
>     been called when assembling the callchain, in:
>     
>       thread__resolve_callchain_sample(perf_sample)
>           add_callchain_ip(ip = perf_sample->callchain->ips[j])
>               thread__find_addr_location(addr = ip)
>                   thread__find_addr_map(addr) {
>                       al->addr = addr
>                       if (al->map)
>                           al->addr = al->map->map_ip(al->map, al->addr);
>                   }
>     
>     Calling it a second time can result in incorrect addresses being used.
>     This can have effects such as duplicate symbols being created and
>     exported.
> 

^ permalink raw reply	[flat|nested] 4+ messages in thread

end of thread, other threads:[~2017-10-04  7:18 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-10-03 10:19 perf script : wrong symoff in callchain Matthieu CASTET
2017-10-03 10:34 ` Adrian Hunter
2017-10-03 11:45   ` Matthieu CASTET
2017-10-04  7:12     ` Adrian Hunter

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox

all inboxes | Powered by JetHome®