From mboxrd@z Thu Jan  1 00:00:00 1970
X-Spam-Checker-Version: SpamAssassin 3.4.4 (2020-01-24) on polar.synack.me
X-Spam-Level: 
X-Spam-Status: No, score=-1.9 required=5.0 tests=BAYES_00
	autolearn=unavailable autolearn_force=no version=3.4.4
Path: 
 eternal-september.org!reader01.eternal-september.org!reader02.eternal-september.org!news.eternal-september.org!news.eternal-september.org!.POSTED!not-for-mail
From: "Alejandro R. Mosteo" <alejandro@mosteo.com>
Newsgroups: comp.lang.ada
Subject: Re: Profiling Ada binaries
Date: Fri, 22 Jul 2016 17:05:31 +0200
Organization: A noiseless patient Spider
Message-ID: <nmtcns$81a$1@dont-email.me>
References: <nmt6qe$3d6$1@gioia.aioe.org> <nmtcbq$6fh$1@dont-email.me>
Mime-Version: 1.0
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 8bit
Injection-Date: Fri, 22 Jul 2016 15:05:32 -0000 (UTC)
Injection-Info: mx02.eternal-september.org;
 posting-host="df6c13c4617621ca1de5ec657b563bf1";
	logging-data="8234"; mail-complaints-to="abuse@eternal-september.org";
	posting-account="U2FsdGVkX191Ce3FA1nZAHMP6vf8OhLv"
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101
 Thunderbird/45.2.0
In-Reply-To: <nmtcbq$6fh$1@dont-email.me>
Cancel-Lock: sha1:pvpVG68VSHyGxKJl+ENHEFUHJrU=
Xref: news.eternal-september.org comp.lang.ada:31124
Date: 2016-07-22T17:05:31+02:00
List-Id: <comp.lang.ada>

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
>