Re: Profiling Ada binaries

["Alejandro R. Mosteo" <alejandro@mosteo.com>]

On 22/07/16 16:59, Alejandro R. Mosteo wrote:
> On 22/07/16 15:24, Markus Schöpflin wrote:
>> Dear list,
>>
>> (...)

Incidentally, you might want to try with callgrind / kcachegrind to 
compare results. IIRC gprof is less accurate given that it instruments 
code with some granularity while valgrind does not have that limitation.

Alex.

>>
>> Flat profile:
>>
>> Each sample counts as 0.01 seconds.
>>   %   cumulative   self              self     total
>>  time   seconds   seconds    calls   s/call   s/call  name
>>   4.66      4.91     4.91      429     0.01     0.01  foo1
>>   4.41      9.55     4.64 162635540     0.00     0.00  bar___elabs
>>   3.99     13.76     4.21   515639     0.00     0.00  foo2
>>
>> As one can see, the second line suggests that the elaboration for the
>> spec of the package bar is called 162635540 times. Looking at the call
>> graph of bar___elabs shows:
>>
>>                 0.00    0.00       1/162635540     adainit [92]
>>                 0.00    0.00      33/162635540
>> standard_math__float_32_elementary__arccosX [2249]
>>                 0.00    0.00    1461/162635540
>> standard_math__float_32_elementary__arcsinX [1099]
>>                 0.00    0.00  108848/162635540
>> standard_math__float_64_elementary__arctanX [1573]
>>                 0.00    0.00  109380/162635540
>> standard_math__float_64_elementary__sinX [1572]
>>                 0.00    0.00  163937/162635540
>> standard_math__float_64_elementary__cosX [687]
>>                 0.01    0.00  515639/162635540
>> standard_math__float_32_elementary__OexponX [609]
>>                 0.03    0.00 1029874/162635540
>> standard_math__float_32_elementary__tanX [346]
>>                 0.04    0.00 1358089/162635540
>> standard_math__float_64_elementary__sqrtX [454]
>>                 0.04    0.00 1543778/162635540
>> standard_math__float_32_elementary__logX [558]
>>                 0.50    0.00 17564360/162635540
>> standard_math__float_32_elementary__expX [93]
>>                 0.56    0.00 19681964/162635540
>> standard_math__float_32_elementary__arctanX [56]
>>                 0.79    0.00 27790226/162635540
>> standard_math__float_32_elementary__cosX [51]
>>                 0.82    0.00 28730603/162635540
>> standard_math__float_32_elementary__sinX [49]
>>                 1.83    0.00 64037347/162635540
>> standard_math__float_32_elementary__sqrtX [45]
>> [33]     4.4    4.64    0.00 162635540         bar___elabs [33]
>>
>> There is one legit call from adainit, all other reported calls are most
>> likely incorrect. The many calls to standard math functions most likely
>> are correct, they just don't call bar___elabs.
>
> It's been a long time since I last used gprof, so with the caveat that I
> may be totally off the mark: perhaps you're reading the detail in
> reverse? That is, from the single elaboration call you're calling
> something than in turn calls the math functions.
>
> IIRC these tools tend to show things top/bottom, with times in inner
> calls being summed up as you unwind the call stack. That way you know
> what takes all the time (in this case, elaboration), and smaller parts
> of the pie being shown within it.
>
> But then I miss in these calls whatever is calling the math operations
> in the elaboration code. Perhaps seeing your procedure might help.
>
> Alex.
>
>>
>> Did anybody encounter such anomalies before? Is there a way to get
>> correct profiling information for Ada binaries generated by Gnat?
>> Different compiler flags maybe? Or using a different profiling tool
>> altogether?
>>
>> TIA,
>> Markus
>