2009-10-14 23:03:08

by Anton Blanchard

[permalink] [raw]
Subject: perf report fractal output issue


Hi,

I noticed a problem where I wasn't always getting callchains:

# perf report
98.47% lock1_processes [kernel] [k] .lock_kernel

0.91% lock1_processes [kernel] [k] .fput


But a flat output confirmed the data is there:

# perf report -g flat
98.47% lock1_processes [kernel] [k] .lock_kernel
98.47%
.lock_kernel
.__posix_lock_file
(nil)
.fcntl_setlk
.sys_fcntl
syscall_exit
0xfffb7d04844
.testcase
.testcase
.affinitize
.new_task
.main
0xfffb7c4933c
0xfffb7c4955c
(nil)

It looks like callchain__fprintf_graph() only prints the callchain if we
have at least one rb entry at the top. In my case all the associated
backtraces are identical so I assume we dont have to do any splitting.

Anton


2009-10-15 12:30:40

by Frederic Weisbecker

[permalink] [raw]
Subject: Re: perf report fractal output issue

On Thu, Oct 15, 2009 at 09:57:26AM +1100, Anton Blanchard wrote:
>
> Hi,
>
> I noticed a problem where I wasn't always getting callchains:
>
> # perf report
> 98.47% lock1_processes [kernel] [k] .lock_kernel
>
> 0.91% lock1_processes [kernel] [k] .fput
>
>
> But a flat output confirmed the data is there:
>
> # perf report -g flat
> 98.47% lock1_processes [kernel] [k] .lock_kernel
> 98.47%
> .lock_kernel
> .__posix_lock_file
> (nil)
> .fcntl_setlk
> .sys_fcntl
> syscall_exit
> 0xfffb7d04844
> .testcase
> .testcase
> .affinitize
> .new_task
> .main
> 0xfffb7c4933c
> 0xfffb7c4955c
> (nil)
>
> It looks like callchain__fprintf_graph() only prints the callchain if we
> have at least one rb entry at the top. In my case all the associated
> backtraces are identical so I assume we dont have to do any splitting.
>
> Anton


Hmm, could you please send me a perf.data where you can see that?
Does that only happen on powerpc?


Thanks.

2009-10-15 23:44:53

by Anton Blanchard

[permalink] [raw]
Subject: Re: perf report fractal output issue


Hi,

> > It looks like callchain__fprintf_graph() only prints the callchain if we
> > have at least one rb entry at the top. In my case all the associated
> > backtraces are identical so I assume we dont have to do any splitting.
>
> Hmm, could you please send me a perf.data where you can see that?
> Does that only happen on powerpc?

I can replicate this on x86 by taking a perf.data and truncating it
after the first sample+backtrace:


# wget http://samba.org/~anton/perf_truncated.test


# perf report -i perf_truncated.test -g fractal
...
100.00% perf [kernel] [k] native_write_msr_safe


# perf report -i perf_truncated.test -g flat
...
100.00% perf [kernel] [k] native_write_msr_safe
100.00%
native_write_msr_safe
intel_pmu_enable_all
hw_perf_enable
perf_enable
__perf_counter_enable
smp_call_function_single
task_oncpu_function_call
perf_counter_enable
perf_counter_for_each_child
perf_ioctl
vfs_ioctl
do_vfs_ioctl
sys_ioctl
system_call_fastpath
0x7f00c1857537

2009-10-20 21:53:16

by Frederic Weisbecker

[permalink] [raw]
Subject: Re: perf report fractal output issue

On Fri, Oct 16, 2009 at 10:41:26AM +1100, Anton Blanchard wrote:
>
> Hi,
>
> > > It looks like callchain__fprintf_graph() only prints the callchain if we
> > > have at least one rb entry at the top. In my case all the associated
> > > backtraces are identical so I assume we dont have to do any splitting.
> >
> > Hmm, could you please send me a perf.data where you can see that?
> > Does that only happen on powerpc?
>
> I can replicate this on x86 by taking a perf.data and truncating it
> after the first sample+backtrace:
>
>
> # wget http://samba.org/~anton/perf_truncated.test
>
>
> # perf report -i perf_truncated.test -g fractal
> ...
> 100.00% perf [kernel] [k] native_write_msr_safe
>
>
> # perf report -i perf_truncated.test -g flat
> ...
> 100.00% perf [kernel] [k] native_write_msr_safe
> 100.00%
> native_write_msr_safe
> intel_pmu_enable_all
> hw_perf_enable
> perf_enable
> __perf_counter_enable
> smp_call_function_single
> task_oncpu_function_call
> perf_counter_enable
> perf_counter_for_each_child
> perf_ioctl
> vfs_ioctl
> do_vfs_ioctl
> sys_ioctl
> system_call_fastpath
> 0x7f00c1857537


Thanks, I can reproduce it with your file.
Actually it was there from the beginning but we have missed it:
the root of the callchain is never printed :-s

Say you have:

hist_entry
|
--------- f1
f2
|
-------- f3
| f4
|
---------f5
f6

Actually you never see that, instead you have:

hist_entry
|
--------- f3
| f4
|
--------- f5
f6

Thanks a lot for this report!
I'm currently fixing it.

I just hope the fix won't be too big for .32 ....