* [BUG?] perf: dwarf unwind doesn't work correctly on aarch64
@ 2017-02-23 7:50 Masami Hiramatsu
2017-03-24 3:24 ` Kim Phillips
0 siblings, 1 reply; 4+ messages in thread
From: Masami Hiramatsu @ 2017-02-23 7:50 UTC (permalink / raw)
To: Will Deacon, He Kuang, Wang Nan, Arnaldo Carvalho de Melo
Cc: Peter Zijlstra, Mark Rutland, linux-kernel
[-- Attachment #1: Type: text/plain, Size: 5100 bytes --]
Hello,
perf record -g dwarf (and perf report) doesn't show correct callchain
on aarch64. Here is how to reproduce it.
1) I've prepared an debian8 aarch64 VM on qemu-system-aarch64, and
build/install the latest perftools on it.
2) Build attached program as below
# gcc -O0 -ggdb3 -funwind-tables -o main main.c
3) Run perf to record with dwarf.
# perf record -g --call-graph dwarf,1024 -e cpu-clock:u -o /tmp/perf.data -- ./main
^C[ perf record: Woken up 35 times to write data ]
[ perf record: Captured and wrote 8.526 MB /tmp/perf.data (6495 samples) ]
4) Run perf to report the result.
# perf report -i /tmp/perf.data
# To display the perf.data header info, please use --header/--header-only option
#
#
# Total Lost Samples: 0
#
# Samples: 6K of event 'cpu-clock:u'
# Event count (approx.): 1623750000
#
# Children Self Command Shared Object Symbol
# ........ ........ ....... ............. ..........................
#
17.21% 17.21% main main [.] func2
|
---func2
17.09% 17.09% main main [.] func1
|
---func1
16.67% 16.67% main main [.] main
|
---main
.....
So, as you can see, the call graph reported each function has been
called from itself. If I report it with fp as below, perf reported
correct callgraph.
3') record it with fp
# perf record -g --call-graph fp -e cpu-clock:u -o /tmp/perf.data -- ./main
^C[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0.397 MB /tmp/perf.data (4160 samples) ]
4') report it
# perf report -i /tmp/perf.data # To display the perf.data header info, please use --header/--header-only option
#
#
# Total Lost Samples: 0
#
# Samples: 4K of event 'cpu-clock:u'
# Event count (approx.): 1040000000
#
# Children Self Command Shared Object Symbol
# ........ ........ ....... ............. ...........................
#
99.06% 0.00% main libc-2.19.so [.] __libc_start_main
|
---__libc_start_main
|
--98.94%--main
|
|--80.24%--func0
| |
| |--63.27%--func1
| | |
| | |--47.04%--func2
| | | |
.....
I tried to dump but it seems correct.
# perf report -D -i /tmp/perf.data
[...]
. 0130: c8 05 40 00 00 00 00 00 30 e1 a8 df ff ff 00 00 ..@.....0.......
. 0140: 90 05 40 00 00 00 00 00 [00 04 00 00 00 00 00 00](*) ..@.............
. 0150: 50 e1 a8 df ff ff 00 00 e8 05 40 00 00 00 00 00 P.........@.....
. 0160: 00 00 00 00 00 00 00 00 00 00 00 00 08 00 00 00 ................
. 0170: 70 e1 a8 df ff ff 00 00 08 06 40 00 00 00 00 00 p.........@.....
. 0180: 8c b6 c9 8f ff ff 00 00 00 00 00 00 04 00 00 00 ................
. 0190: 90 e1 a8 df ff ff 00 00 28 06 40 00 00 00 00 00 ........(.@.....
. 01a0: c0 e1 a8 df ff ff 00 00 2c 1d b6 8f 02 00 00 00 ........,.......
. 01b0: b0 e1 a8 df ff ff 00 00 40 06 40 00 00 00 00 00 ........@.@.....
. 01c0: c0 e1 a8 df ff ff 00 00 48 1d b6 8f 01 00 00 00 ........H......
[...]
1207680984048 0xf040 [0x560]: PERF_RECORD_SAMPLE(IP, 0x2): 114/114: 0x400590 per
... FP chain: nr:0
... user regs: mask 0x1ffffffff ABI 64-bit
[...]
.... x29 0xffffdfa8e130
.... lr 0x4005c8
.... sp 0xffffdfa8e130
.... pc 0x400590
... ustack: size 1024, offset 0x148
. data_src: 0x5080021
... thread: main:114
In this entry, ustack should start from offset=0x0148 in event raw data,
I marked it with (*), which is the saved stack size(0x400 = 1024) and
the top of stack has 0xffffdfa8e150 which seems next frame pointer, and
after that there is 0x4005e8, which is next return address.
00000000004005b0 <func3>:
4005b0: a9be7bfd stp x29, x30, [sp,#-32]!
4005b4: 910003fd mov x29, sp
4005b8: b9001fa0 str w0, [x29,#28]
4005bc: b9401fa0 ldr w0, [x29,#28]
4005c0: 11002000 add w0, w0, #0x8
4005c4: 97fffff3 bl 400590 <func4>
4005c8: a8c27bfd ldp x29, x30, [sp],#32
4005cc: d65f03c0 ret
00000000004005d0 <func2>:
4005d0: a9be7bfd stp x29, x30, [sp,#-32]!
4005d4: 910003fd mov x29, sp
4005d8: b9001fa0 str w0, [x29,#28]
4005dc: b9401fa0 ldr w0, [x29,#28]
4005e0: 11001000 add w0, w0, #0x4
4005e4: 97fffff3 bl 4005b0 <func3>
4005e8: a8c27bfd ldp x29, x30, [sp],#32
So, the stack data should be correct.
I guess there is a bug in libunwind on aarch64 or we missed to pass
the stack data to libunwind. (BTW, it works correctly on arm32)
Thank you,
--
Masami Hiramatsu <mhiramat@kernel.org>
[-- Attachment #2: main.c --]
[-- Type: text/x-csrc, Size: 272 bytes --]
int buf = 0;
void func(int a)
{
buf += a;
}
void func4(int a)
{
func (a+16);
}
void func3(int a)
{
func4(a+8);
}
void func2(int a)
{
func3(a+4);
}
void func1(int a)
{
func2(a+2);
}
void func0(int a)
{
func1(a+1);
}
void main()
{
do {
func0(1);
} while (buf);
}
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [BUG?] perf: dwarf unwind doesn't work correctly on aarch64
2017-02-23 7:50 [BUG?] perf: dwarf unwind doesn't work correctly on aarch64 Masami Hiramatsu
@ 2017-03-24 3:24 ` Kim Phillips
2017-03-24 13:00 ` Masami Hiramatsu
0 siblings, 1 reply; 4+ messages in thread
From: Kim Phillips @ 2017-03-24 3:24 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: Will Deacon, He Kuang, Wang Nan, Arnaldo Carvalho de Melo,
Peter Zijlstra, Mark Rutland, linux-kernel
On Thu, 23 Feb 2017 16:50:18 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:
[sorry for the delay, I just saw this]
> perf record -g dwarf (and perf report) doesn't show correct callchain
> on aarch64. Here is how to reproduce it.
...
> # Samples: 6K of event 'cpu-clock:u'
> # Event count (approx.): 1623750000
> #
> # Children Self Command Shared Object Symbol
> # ........ ........ ....... ............. ..........................
> #
> 17.21% 17.21% main main [.] func2
> |
> ---func2
>
> 17.09% 17.09% main main [.] func1
> |
> ---func1
>
> 16.67% 16.67% main main [.] main
> |
> ---main
> .....
>
> So, as you can see, the call graph reported each function has been
> called from itself. If I report it with fp as below, perf reported
> correct callgraph.
...
> I guess there is a bug in libunwind on aarch64 or we missed to pass
> the stack data to libunwind. (BTW, it works correctly on arm32)
Trying to replicate this on a debian 9 ("stretch") arm64 box:
Building acme's 'perf/urgent' branch (currently with the tag
perf-urgent-for-mingo-4.11-20170317), natively (cd tools; make clean;
make DEBUG=5 -C perf) shows this system has unwind support:
Auto-detecting system features:
... dwarf: [ on ]
... dwarf_getlocations: [ on ]
... glibc: [ on ]
... gtk2: [ on ]
... libaudit: [ on ]
... libbfd: [ on ]
... libelf: [ on ]
... libnuma: [ on ]
... numa_num_possible_cpus: [ on ]
... libperl: [ OFF ]
... libpython: [ on ]
... libslang: [ on ]
... libcrypto: [ on ]
... libunwind: [ on ]
... libdw-dwarf-unwind: [ on ]
... zlib: [ on ]
... lzma: [ on ]
... get_cpuid: [ OFF ]
... bpf: [ on ]
for which an apt search unwind returns the version:
libunwind-dev/testing,now 1.1-4.1 arm64 [installed]
library to determine the call-chain of a program - development
libunwind8/testing,now 1.1-4.1 arm64 [installed,automatic]
library to determine the call-chain of a program - runtime
continuing, and ignoring the no debug_frame support perf configure
mentions:
Makefile.config:421: No debug_frame support found in libunwind-aarch64
Makefile.config:480: No debug_frame support found in libunwind
$ ./perf --version
perf version 4.10.rc4.ge7ede72
$ gcc --version
gcc (Debian 6.3.0-6) 6.3.0 20170205
Copyright (C) 2016 Free Software Foundation, Inc.
This is free software; see the source for copying conditions. There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
$ gcc -O0 -ggdb3 -funwind-tables -o main main.c
$ ./perf record -g --call-graph dwarf,1024 -e cpu-clock:u -o /tmp/perf.data -- ./main
^C[ perf record: Woken up 121 times to write data ]
[ perf record: Captured and wrote 30.154 MB /tmp/perf.data (22975 samples) ]
$ ./perf --no-pager report -i /tmp/perf.data --stdio
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 22K of event 'cpu-clock:u'
# Event count (approx.): 5743750000
#
# Children Self Command Shared Object Symbol
# ........ ........ ....... ............. .....................
#
100.00% 8.14% main main [.] main
|
|--91.86%--main
| func0
| |
| --76.41%--func1
| |
| --60.82%--func2
| |
| --45.31%--func3
| |
| --30.17%--func4
| |
| --15.04%--func
|
--8.14%--__libc_start_main
main
...
which looks like it should, i.e., I can't reproduce.
You mentioned you're using the 'latest' sources for libunwind, etc.,
but can you provide more exact details like commit IDs, and what, if
anything, is being cross-built vs. native?
Thanks,
Kim
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [BUG?] perf: dwarf unwind doesn't work correctly on aarch64
2017-03-24 3:24 ` Kim Phillips
@ 2017-03-24 13:00 ` Masami Hiramatsu
2017-03-27 3:39 ` [BUG?] perf: dwarf unwind doesn't work correctly with -static Masami Hiramatsu
0 siblings, 1 reply; 4+ messages in thread
From: Masami Hiramatsu @ 2017-03-24 13:00 UTC (permalink / raw)
To: Kim Phillips
Cc: Will Deacon, He Kuang, Wang Nan, Arnaldo Carvalho de Melo,
Peter Zijlstra, Mark Rutland, linux-kernel
On Thu, 23 Mar 2017 22:24:01 -0500
Kim Phillips <kim.phillips@arm.com> wrote:
> On Thu, 23 Feb 2017 16:50:18 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
>
> [sorry for the delay, I just saw this]
>
> > perf record -g dwarf (and perf report) doesn't show correct callchain
> > on aarch64. Here is how to reproduce it.
> ...
> > # Samples: 6K of event 'cpu-clock:u'
> > # Event count (approx.): 1623750000
> > #
> > # Children Self Command Shared Object Symbol
> > # ........ ........ ....... ............. ..........................
> > #
> > 17.21% 17.21% main main [.] func2
> > |
> > ---func2
> >
> > 17.09% 17.09% main main [.] func1
> > |
> > ---func1
> >
> > 16.67% 16.67% main main [.] main
> > |
> > ---main
> > .....
> >
> > So, as you can see, the call graph reported each function has been
> > called from itself. If I report it with fp as below, perf reported
> > correct callgraph.
> ...
> > I guess there is a bug in libunwind on aarch64 or we missed to pass
> > the stack data to libunwind. (BTW, it works correctly on arm32)
>
> Trying to replicate this on a debian 9 ("stretch") arm64 box:
I'm using debian 8 ("jessie"), but I can try debian 9 too.
> Building acme's 'perf/urgent' branch (currently with the tag
> perf-urgent-for-mingo-4.11-20170317), natively (cd tools; make clean;
> make DEBUG=5 -C perf) shows this system has unwind support:
>
> Auto-detecting system features:
> ... dwarf: [ on ]
> ... dwarf_getlocations: [ on ]
> ... glibc: [ on ]
> ... gtk2: [ on ]
> ... libaudit: [ on ]
> ... libbfd: [ on ]
> ... libelf: [ on ]
> ... libnuma: [ on ]
> ... numa_num_possible_cpus: [ on ]
> ... libperl: [ OFF ]
> ... libpython: [ on ]
> ... libslang: [ on ]
> ... libcrypto: [ on ]
> ... libunwind: [ on ]
> ... libdw-dwarf-unwind: [ on ]
> ... zlib: [ on ]
> ... lzma: [ on ]
> ... get_cpuid: [ OFF ]
> ... bpf: [ on ]
>
> for which an apt search unwind returns the version:
>
> libunwind-dev/testing,now 1.1-4.1 arm64 [installed]
> library to determine the call-chain of a program - development
> libunwind8/testing,now 1.1-4.1 arm64 [installed,automatic]
> library to determine the call-chain of a program - runtime
I've tried the same version and also tried with 1.2 and both not working.
>
> continuing, and ignoring the no debug_frame support perf configure
> mentions:
>
> Makefile.config:421: No debug_frame support found in libunwind-aarch64
> Makefile.config:480: No debug_frame support found in libunwind
Hmm, this seems --call-graph dwarf may not use debuginfo, right?
> $ ./perf --version
> perf version 4.10.rc4.ge7ede72
> $ gcc --version
> gcc (Debian 6.3.0-6) 6.3.0 20170205
> Copyright (C) 2016 Free Software Foundation, Inc.
> This is free software; see the source for copying conditions. There is NO
> warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
>
> $ gcc -O0 -ggdb3 -funwind-tables -o main main.c
> $ ./perf record -g --call-graph dwarf,1024 -e cpu-clock:u -o /tmp/perf.data -- ./main
> ^C[ perf record: Woken up 121 times to write data ]
> [ perf record: Captured and wrote 30.154 MB /tmp/perf.data (22975 samples) ]
>
> $ ./perf --no-pager report -i /tmp/perf.data --stdio
> # To display the perf.data header info, please use --header/--header-only options.
> #
> #
> # Total Lost Samples: 0
> #
> # Samples: 22K of event 'cpu-clock:u'
> # Event count (approx.): 5743750000
> #
> # Children Self Command Shared Object Symbol
> # ........ ........ ....... ............. .....................
> #
> 100.00% 8.14% main main [.] main
> |
> |--91.86%--main
> | func0
> | |
> | --76.41%--func1
> | |
> | --60.82%--func2
> | |
> | --45.31%--func3
> | |
> | --30.17%--func4
> | |
> | --15.04%--func
> |
> --8.14%--__libc_start_main
> main
> ...
>
> which looks like it should, i.e., I can't reproduce.
Sound good news! I'll try to test again on debian 9.
>
> You mentioned you're using the 'latest' sources for libunwind, etc.,
> but can you provide more exact details like commit IDs, and what, if
> anything, is being cross-built vs. native?
I'm using qemu-user-static for install rootfs (by de-bootstrap) and perf.
For running the test code and perf, I'm currently using qemu-system-arm64.
So, it's a kind of native build.
Thank you!
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 4+ messages in thread
* [BUG?] perf: dwarf unwind doesn't work correctly with -static
2017-03-24 13:00 ` Masami Hiramatsu
@ 2017-03-27 3:39 ` Masami Hiramatsu
0 siblings, 0 replies; 4+ messages in thread
From: Masami Hiramatsu @ 2017-03-27 3:39 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: Kim Phillips, Will Deacon, He Kuang, Wang Nan,
Arnaldo Carvalho de Melo, Peter Zijlstra, Mark Rutland,
linux-kernel
Hello,
On Fri, 24 Mar 2017 22:00:30 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:
> On Thu, 23 Mar 2017 22:24:01 -0500
> Kim Phillips <kim.phillips@arm.com> wrote:
>
> > On Thu, 23 Feb 2017 16:50:18 +0900
> > Masami Hiramatsu <mhiramat@kernel.org> wrote:
> >
> > [sorry for the delay, I just saw this]
> >
> > > perf record -g dwarf (and perf report) doesn't show correct callchain
> > > on aarch64. Here is how to reproduce it.
> > ...
> > > # Samples: 6K of event 'cpu-clock:u'
> > > # Event count (approx.): 1623750000
> > > #
> > > # Children Self Command Shared Object Symbol
> > > # ........ ........ ....... ............. ..........................
> > > #
> > > 17.21% 17.21% main main [.] func2
> > > |
> > > ---func2
> > >
> > > 17.09% 17.09% main main [.] func1
> > > |
> > > ---func1
> > >
> > > 16.67% 16.67% main main [.] main
> > > |
> > > ---main
> > > .....
> > >
> > > So, as you can see, the call graph reported each function has been
> > > called from itself. If I report it with fp as below, perf reported
> > > correct callgraph.
> > ...
> > > I guess there is a bug in libunwind on aarch64 or we missed to pass
> > > the stack data to libunwind. (BTW, it works correctly on arm32)
> >
> > Trying to replicate this on a debian 9 ("stretch") arm64 box:
>
> I'm using debian 8 ("jessie"), but I can try debian 9 too.
I've tried debian 9 and found this issue is another reason.
> 2) Build attached program as below
> # gcc -O0 -ggdb3 -funwind-tables -o main main.c
Originally, I reported above, but that is not correct, when I cleaned
up the command line, I missed important piece -- -static.
I've tested several binaries with different gcc, and found that
- Even with linaro-gcc 6.3.1, this issue happened.
- But natively build binary with gcc-6.3 (stretch) I didn't see it.
- Building binary with -static, it happened even with native binary 6.3.
- And I saw this happened even on x86-64 with -static.
So, I think the correct subject is
"perf: dwarf unwind doesn't work correctly with -static"
Thank you,
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2017-03-27 3:40 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-02-23 7:50 [BUG?] perf: dwarf unwind doesn't work correctly on aarch64 Masami Hiramatsu
2017-03-24 3:24 ` Kim Phillips
2017-03-24 13:00 ` Masami Hiramatsu
2017-03-27 3:39 ` [BUG?] perf: dwarf unwind doesn't work correctly with -static Masami Hiramatsu
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
Powered by JetHome