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

[William Cohen <wcohen@redhat.com>]

On 8/31/22 08:17, 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

Hi,

The --call-graph=dwarf version gives a more accurate picture of what is going on in the code.  The output of --call-graph=fp makes it appear that the call to rand is coming from main when it is actually the result of the inlined fill_array function.  The results fp would be even more confusing if both main and fill_array had a call to rand.  The perf user might overlook the contribution by fill_function's rand  The dwarf handling makes it clearer where to look in the source code.  One could resort to using perf's annotation of  the binary to figure out where in the code, but it seems like a better approach would be to add the additional expansion that --call-graph=dwarf does to the backtrace to --call-graph=fp.

-Will
> 
> jirka
>