perf report fractal output issue

perf report fractal output issue

[Anton Blanchard]

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

Re: perf report fractal output issue

[Frederic Weisbecker]

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.

Re: perf report fractal output issue

[Anton Blanchard]

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

Re: perf report fractal output issue

[Frederic Weisbecker]

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 ....