Re: PROBLEM: The --call-graph=fp data does do not agree with the --call-graph=dwarf results

[Milian Wolff <milian.wolff@kdab.com>]

[-- Attachment #1: Type: text/plain, Size: 3638 bytes --]

On Mittwoch, 31. August 2022 14:17:26 CEST Jiri Olsa wrote:
> On Tue, Aug 30, 2022 at 10:21:28AM -0400, William Cohen wrote:
> > With a perf Fedora 36 perf-tools-5.18.13-200.fc36 I was examining
> > where perf-report was spending its time when generating its report and
> > found there was an efficiency issue in Fedora 36's binutils-2.37.  The
> > efficient issue been addressed in Fedora rawhide and will be
> > backported to Fedora 36
> > (https://bugzilla.redhat.com/show_bug.cgi?id=2120752).  This was
> 
> nice :)
> 
> > initially discovered when processing perf.data files created with
> > --call-graph=dwarf.  The output of the perf-report call-graph for
> > dwarf information notes inlined functions in the report. The excessive
> > time spent in binutils bfd's lookup_func_by_offset was caused by
> > perf-report building up a red-black tree mapping IP addresses to
> > functions
> > including inlined functions.
> > 
> > I ran a similar experiment with --call-graph=fp to see if it triggered
> > the same execessive overhead in building the red-black tree for
> > inlined functions.  It did not.  The resulting output of the perf-report
> > for --call-graph=fp does not include information about inlined functions.
> > 
> > I have a small reproducer in the attached perf_inlined.tar.gz that
> > demonstrates the difference between the two methods of storing
> > call-chain information. Compile and collect data with:
> > 
> > tar xvfz perf_inlined.tar.gz
> > cd perf_inlined
> > make all
> > perf report --input=perf_fp.data > fp.log
> > perf report --input=perf_dwarf.data > dwarf.log
> > 
> > The dwarf.log has the expected call structure for main:
> >                main
> >                
> >                 --85.72%--fill_array (inlined)
> >                 
> >                           |--78.09%--rand
> >                           |
> >                           |           --75.10%--__random
> >                           |           
> >                           |                      --9.14%--__random_r
> >                           |
> >                           |--1.58%--compute_sqrt (inlined)
> >                           |
> >                            --1.32%--_init
> > 
> > The fp.log looks odd given program:
> what's odd about that? perhaps the confusion is that you are
> in children mode? you could try --no-children
> 
> >    99.99%     0.00%  time_waste  libc.so.6             [.]
> >    __libc_start_call_main>    
> >             ---__libc_start_call_main
> >             
> >                |--66.07%--__random
> >                |
> >                |--21.28%--main
> >                |
> >                |--8.42%--__random_r
> >                |
> >                |--2.91%--rand
> >                |
> >                 --1.31%--_init
> > 
> > Given how common that functions are inlined in optimized code it seems
> > like perf-report of --call-graph=fp should include information about
> > time spent in inlined functions.
> 
> hum, so 'fp' call graph is tracersing frame pointers which I would
> not expect for inlined functions

I think the oddity is that there is no mention of any (inlined) frames at all 
in frame pointer unwinding. I guess this is simply an oversight - I never had 
a setup where frame pointers are available and thus never implemented that. It 
might be that similar issues arises for LBR unwinding? Hopefully it's just a 
matter of reusing some of the DWARF code for FP/LBR.

Cheers

-- 
Milian Wolff | milian.wolff@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt, C++ and OpenGL Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5272 bytes --]