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" Newsgroups: comp.lang.ada Subject: Re: Profiling Ada binaries Date: Fri, 22 Jul 2016 16:59:06 +0200 Organization: A noiseless patient Spider Message-ID: References: Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 8bit Injection-Date: Fri, 22 Jul 2016 14:59:06 -0000 (UTC) Injection-Info: mx02.eternal-september.org; posting-host="df6c13c4617621ca1de5ec657b563bf1"; logging-data="6641"; mail-complaints-to="abuse@eternal-september.org"; posting-account="U2FsdGVkX1+nHK4yxVgxAwXuUIbL8LFT" User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.2.0 In-Reply-To: Cancel-Lock: sha1:tdQB0wCTHNzDJ4dkSmIDNaJ6Y2Y= Xref: news.eternal-september.org comp.lang.ada:31123 Date: 2016-07-22T16:59:06+02:00 List-Id: On 22/07/16 15:24, Markus Schöpflin wrote: > Dear list, > > (...) > > 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