Re: [RFC PATCH] perf tui: Annotate entries in callchains

Arnaldo Carvalho de Melo
2015-03-20T21:34:36Z

Em Fri, Mar 20, 2015 at 02:12:30PM -0700, Stephane Eranian escreveu:
> On Fri, Mar 20, 2015 at 2:07 PM, Arnaldo Carvalho de Melo
> <arnaldo.melo@gmail.com> wrote:
> > Em Fri, Mar 20, 2015 at 05:39:22PM -0300, Arnaldo Carvalho de Melo escreveu:
> >> Em Fri, Mar 20, 2015 at 10:15:53AM -0700, Stephane Eranian escreveu:
> >> > On Thu, Mar 19, 2015 at 5:39 PM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
> >> > > On Mar 19, 2015 9:34 PM, "Stephane Eranian" <eranian@google.com> wrote:
> >> > >> On Thu, Mar 19, 2015 at 3:58 PM, Arnaldo Carvalho de Melo
> >> > >> <acme@kernel.org> wrote:
> >> > >> > This patch, together with what is in my perf/core branch, should
> >> > >> > implement that feature we talked about recently, i.e. to allow
> >> > >> > annotating entries in callchains, please take a look at see if you think
> >> > >> > it is ok,

> >> > >> I tried on tip.git and a simple example. It does what I wanted.
> >> > >> I will try on more complex test cases.
> >> > >> Thanks for implementing this quickly.

> >> > > Thanks for testing, please let us know if you have further suggestions,

> >> > Ok, it does not work.
> >
> > Are you sure? I just tried, take a look at:
> >
> > http://vger.kernel.org/~acme/perf-report-annotate-callchain-entries-in-multiple-DSOs-in-the-same-hist_entry.png
> >
> > In there you will see that in the unmap_single_vma case there are
> > callchains that pass thru multiple DSOs in userspace (I used --call
> > dwarf in 'perf record') and those are marked as having
> > samples/annotation and when I go to those, pressing 'a' after moving the
> > cursor to it and it works as expected...

> > Do you have some specific example I could try?

> I tried on an example I cannot share.
> But I am guessing you could reproduce with a test which calls a libc
> or libm function
> heavily form multiple callers in the main program.
> Example:
> - pow()
> 50% foo() [main.c]
> 50% bar() [main.c]
>
> If I move the cursor line to foo() and annotate foo() is shows me the
> code of pow().

+ 49.83% pow-me-harder pow-me-harder [.] main
+ 27.16% pow-me-harder libm-2.17.so [.] __ieee754_pow_sse2
- 17.76% pow-me-harder libm-2.17.so [.] __pow
-→__pow libm-2.17.so
-→80.70% main pow-me-harder
__libc_start_main libc-2.17.so
_start pow-me-harder
16.82% 0x4000000000000000 unknown
2.44% 0x1 unknown
+ 2.57% pow-me-harder pow-me-harder [.] pow@plt
+ 2.36% pow-me-harder libm-2.17.so [.] @plt
+ 0.04% pow-me-harder [kernel.vmlinux] [k] intel_thermal_interrupt

And if I go to the line:

-→80.70% main pow-me-harder

And press 'a' I get:

main /home/acme/pow-me-harder
10.25 │ 3e: mov -0x10(%rbp),%rax
1.03 │ test %rax,%rax
4.39 │ ↓ js 53
3.87 │ cvtsi2 %rax,%xmm3
1.63 │ movsd %xmm3,-0x38(%rbp)
│ ↓ jmp 71
0.03 │ 53: mov %rax,%rdx
0.91 │ shr %rdx
0.29 │ and $0x1,%eax
1.85 │ or %rax,%rdx
7.38 │ cvtsi2 %rdx,%xmm0
0.55 │ movapd %xmm0,%xmm2
6.54 │ addsd %xmm0,%xmm2
0.68 │ movsd %xmm2,-0x38(%rbp)
1.44 │ 71: cvtsi2 -0x4(%rbp),%xmm0
2.82 │ movabs $0x4000000000000000,%rax
0.62 │ mov %rax,-0x40(%rbp)
0.07 │ movsd -0x40(%rbp),%xmm1
4.30 │ → callq pow@plt
1.53 │ addsd -0x38(%rbp),%xmm0
4.13 │ ucomis 0xfd(%rip),%xmm0 # 400818 <__dso_handle+0x10>
4.06 │ ↓ jae a8
1.49 │ cvttsd %xmm0,%rax
1.49 │ mov %rax,-0x10(%rbp)
0.35 │ ↓ jmp cb
│ a8: movsd 0xe8(%rip),%xmm1 # 400818 <__dso_handle+0x10>
0.14 │ subsd %xmm1,%xmm0
2.57 │ cvttsd %xmm0,%rax
0.66 │ mov %rax,-0x10(%rbp)
│ movabs $0x8000000000000000,%rax
7.84 │ xor %rax,-0x10(%rbp)
16.80 │ cb: mov -0x10(%rbp),%rax
2.15 │ mov %rax,-0x10(%rbp)
│ int main(int argc, char *argv[])
│ {
│ int n = atoi(argv[1]), i;
│ unsigned long long total = 0;

While if I go to the line:

-→__pow libm-2.17.so

And press 'a', I get:

__pow /usr/lib64/libm-2.17.so
│ Disassembly of section .text:
│
│ 0000000000026290 <pow>:
│ __pow():
│ movapd %xmm0,%xmm2
│ sub $0x18,%rsp
1.70 │ movapd %xmm1,%xmm3
12.86 │ movsd %xmm2,(%rsp)
│ movsd %xmm3,0x8(%rsp)
2.43 │ → callq *ABS*+0x1b110@plt
0.49 │ movabs $0x7fffffffffffffff,%rcx
0.28 │ movabs $0x7fefffffffffffff,%rdx
1.01 │ movq %xmm0,%rax
12.58 │ and %rcx,%rax
2.18 │ movsd (%rsp),%xmm2
1.29 │ cmp %rdx,%rax
19.70 │ movsd 0x8(%rsp),%xmm3
1.50 │ ↓ ja 57
1.58 │ xorpd %xmm1,%xmm1
13.35 │ ucomis %xmm1,%xmm0
0.89 │ ↓ jnp a0
│ 52: add $0x18,%rsp
16.83 │ ← retq
│ 57: mov _DYNAMIC+0x230,%rsi
│ cmpl $0xffffffff,(%rsi)
│ ↑ je 52

Since I don't have glibc-debuginfo installed, I get just assembly.

[acme@ssdandy linux]$ readelf -sw /usr/lib64/libm-2.17.so | grep -w __pow
1737: 0000000000026290 429 FUNC LOCAL DEFAULT 13 __pow
[acme@ssdandy linux]$

Strange, are you pressing 'V' on the main 'perf record' view, i.e. before
getting to the annotation browser, to see the DSO just after the symbol?

Trying with a deeper callchain in pow-me-harder.c...

- Arnaldo