Timing code blocks

21 views
Skip to first unread message

deadlyhead

unread,
Mar 5, 2010, 1:34:47 AM3/5/10
to
I've been trying to determine if there is any significant performance
difference between two functionally equivalent pieces of code. I've
done the standard thing and, using the Ada.Real_Time package, I'm
saving the time when the code starts, then the time when the code
ends, then examining the difference between them after the code runs.

The problem I'm having, though, is that the timing just isn't
happening. This code will run for 15 seconds and when I examine the
time span, it tells me that no time passed.

Here's my actual code

----------------------------------------------------------------------

-- A test of the cost of conditionals

with Ada.Text_IO; use Ada.Text_IO;
with Ada.Real_Time; use Ada.Real_Time;
procedure Conditional_Test is

Test_Dur : constant := 100_000;

-- We require the input/output for Duration
package Duration_IO is new Fixed_IO (Duration);
use Duration_IO;


Start_Time : Time;
End_Time : Time;
Is_Even : Boolean;
Is_Odd : Boolean;
Junk : Positive;
Junk_In : Natural := 0;

begin -- Conditional_test

Put_Line ("---Starting per-branch assignment test---");

Start_Time := Clock;
for I in 1 .. Test_Dur loop
if I rem 2 = 1 then
Is_Odd := True;
else
Is_Even := True;
end if;

if Is_Even then
for J in reverse 1 .. Test_Dur loop
Junk_In := Junk_In + 1;
end loop;
Junk := I;
elsif Is_Odd then
for J in reverse 1 .. Test_Dur loop
Junk_In := Junk_In + 1;
end loop;
Junk := I;
end if;

Is_Even := False;
Is_Odd := False;
end loop;
End_Time := Clock;

Put ("Assignment within each branch took ");
Put (To_Duration (End_Time - Start_Time), 1, 12, 0);
New_Line (2);


Put_Line ("---Starting combined-branch assignment test---");

Start_Time := Clock;
for I in 1 .. Test_Dur loop
if I rem 2 = 1 then
Is_Odd := True;
else
Is_Even := True;
end if;

if Is_Even then
for J in reverse 1 .. Test_Dur loop
Junk_In := Junk_In + 1;
end loop;
elsif Is_Odd then
for J in reverse 1 .. Test_Dur loop
Junk_In := Junk_In + 1;
end loop;
end if;

if Is_Even or Is_Odd then
Junk := I;
end if;

Is_Even := False;
Is_Odd := False;
end loop;
End_Time := Clock;

Put ("Assignment outside of the branching took ");
Put (To_Duration (End_Time - Start_Time), 1, 12, 0);
New_Line (2);

end Conditional_Test;

----------------------------------------------------------------------

The output of this code is as follows:


---Starting per-branch assignment test---
Assignment within each branch took 0.000000000000

---Starting combined-branch assignment test---
Assignment outside of the branching took 0.000000000000


Why wouldn't any time passage be registered?

I know the code above is convoluted, but I've been trying to find a
way to get _some_ timing to happen. I originally ran a test with delay
statements instead of multiple loops, and the timing worked then, but
I felt that there was a real possibility that the delay statements
could be introducing inaccuracies into the timing, with the overhead
of switching processes in the OS and there being no guarantee of
consistently resuming the code. (Ada does not guarantee that code will
resume exactly delay_time from now, it guarantees that the code will
sleep for _at least_ delay_time.)

Anyway, if I'm missing something here, I'd like to know it. I've read
section D.8 of the ARM several times and I'm just about convinced that
something's broken in my compilers (I'm using GNAT on windows, both
the AdaCore binary and a cygwin binary, both with the same output). Is
there something that I'm missing, like the real-time clock doesn't
advance unless the program delays at some point?

I appreciate any insight. This is baffling me.

Dmitry A. Kazakov

unread,
Mar 5, 2010, 2:55:19 AM3/5/10
to
On Thu, 4 Mar 2010 22:34:47 -0800 (PST), deadlyhead wrote:

> I've been trying to determine if there is any significant performance
> difference between two functionally equivalent pieces of code. I've
> done the standard thing and, using the Ada.Real_Time package, I'm
> saving the time when the code starts, then the time when the code
> ends, then examining the difference between them after the code runs.
>
> The problem I'm having, though, is that the timing just isn't
> happening. This code will run for 15 seconds and when I examine the
> time span, it tells me that no time passed.
>
> Here's my actual code

This is an ancient bug, which managed to survive a number of GNAT compiler
versions.

As a workaround, add delay 0.0 at the beginning of your program:

> ----------------------------------------------------------------------
>
> -- A test of the cost of conditionals
>
> with Ada.Text_IO; use Ada.Text_IO;
> with Ada.Real_Time; use Ada.Real_Time;
> procedure Conditional_Test is
>
> Test_Dur : constant := 100_000;

Test_Dur : constant := 10_000; -- 100_000 overflows on a 32-bit machine

> -- We require the input/output for Duration
> package Duration_IO is new Fixed_IO (Duration);
> use Duration_IO;
>
>
> Start_Time : Time;
> End_Time : Time;
> Is_Even : Boolean;
> Is_Odd : Boolean;
> Junk : Positive;
> Junk_In : Natural := 0;
>
> begin -- Conditional_test

delay 0.0; -- Wake up that dozing Ada RTL!

--
Regards,
Dmitry A. Kazakov
http://www.dmitry-kazakov.de

deadlyhead

unread,
Mar 5, 2010, 3:16:52 AM3/5/10
to
On Mar 4, 11:55 pm, "Dmitry A. Kazakov" <mail...@dmitry-kazakov.de>
wrote:

>
> This is an ancient bug, which managed to survive a number of GNAT compiler
> versions.
>
> As a workaround, add delay 0.0 at the beginning of your program:
>
> > ----------------------------------------------------------------------
>
> > --  A test of the cost of conditionals
>
> > with Ada.Text_IO;  use Ada.Text_IO;
> > with Ada.Real_Time; use Ada.Real_Time;
> > procedure Conditional_Test is
>

Exactly what was needed. Thank you!

Do you happen to know if this bug has been fixed in the current
development branch? (At home I compile GNAT based on GCC 4.4, but
haven't done any real-time tests with it yet.) This seems like an
unfortunate bug to have lying around in an otherwise respected
compiler. The ease of the workaround, and likewise that it seems so
pointless to have to insert a dummy delay statement, would lead many
to believe that this bug was just a sloppy error, even if the real
reasons it exists are somewhat more complex.

BTW, my test results with -O3 and -Os, there is no difference in
performance between the two loops, and -Os produces code that is about
33% faster than -O3. With -O0, the second loop is faster by an
average of 10%. I would have thought the extra conditional would have
been costlier.

Again, thanks for the reply!
-- deadlyhead

Niklas Holsti

unread,
Mar 5, 2010, 3:21:43 AM3/5/10
to
deadlyhead wrote:
> I've been trying to determine if there is any significant performance
> difference between two functionally equivalent pieces of code. I've
> done the standard thing and, using the Ada.Real_Time package, I'm
> saving the time when the code starts, then the time when the code
> ends, then examining the difference between them after the code runs.
>
> The problem I'm having, though, is that the timing just isn't
> happening. This code will run for 15 seconds and when I examine the
> time span, it tells me that no time passed.
>
> Here's my actual code

[ code elided ]

Dmitry's already answered your main question. But your code also ha some
other issues that I would like point out, in a friendly spirit. I have
tried your code on Debian Lenny with the Debian GNAT compiler.

Firstly, if I compile with my normal options, -g -O2 -gnato
-fstack-check, the code fails after some seconds with Constraint_Error
due to overflow in the assignment Junk_In := Junk_In + 1 on line 42
(counting the line with all '-' as line 1). This is expected, since this
statement would be executed about (10**10)/2 times, leading to overflow
with a 32-bit Natural counter.

Secondly, if I compile without overflow checks (-g -O2) the program runs
very quickly and displays

---Starting per-branch assignment test---
Assignment within each branch took 0.000006000000

---Starting combined-branch assignment test---
Assignment outside of the branching took 0.000002000000

I believe that GNAT optimizes out almost everything in your loops,
because the results are not used in the program. To disable some of this
optimization you can use pragma Volatile to force GNAT to generate code
that actually executes all the accesses to the variables, for example
like this:

Is_Even : Boolean; pragma Volatile (Is_Even);
Is_Odd : Boolean; pragma Volatile (Is_Odd);
Junk : Positive; pragma Volatile (Junk);
Junk_In : Natural := 0; pragma Volatile (Junk_In);

With this change, and compiling with "-g -O2", the code takes about 1
minute 30 seconds to run on my laptop and displays:

---Starting per-branch assignment test---
Assignment within each branch took 44.178160000000

---Starting combined-branch assignment test---
Assignment outside of the branching took 45.378627000000

I don't think you are not going to find valid performance differences
between different styles of code using this kind of artificial test
programs, because the compiler's code generation and optimization make
such profound changes to the code, depending on the surroundings, data
types, etc.

If you have a real performance problem in a real application, I suggest
that you experiment with changes to the real application code. Use a
profiler to find out where the time is spent and focus on that code.

HTH,

--
Niklas Holsti
Tidorum Ltd
niklas holsti tidorum fi
. @ .

Ludovic Brenta

unread,
Mar 5, 2010, 3:33:54 AM3/5/10
to
Dmitry A. Kazakov wrote on comp.lang.ada:

> On Thu, 4 Mar 2010 22:34:47 -0800 (PST), deadlyhead wrote:
>> The problem I'm having, though, is that the timing just isn't
>> happening.  This code will run for 15 seconds and when I examine the
>> time span, it tells me that no time passed.
>
> This is an ancient bug, which managed to survive a number of GNAT compiler
> versions.
>
> As a workaround, add delay 0.0 at the beginning of your program:
[...]

> delay 0.0; -- Wake up that dozing Ada RTL!

I was not aware of this bug; is there a PR in Bugzilla for it? I don't
see one. Perhaps that might explain how this bug survived several
versions of GNAT?

--
Ludovic Brenta.

Dmitry A. Kazakov

unread,
Mar 5, 2010, 3:49:42 AM3/5/10
to
On Fri, 5 Mar 2010 00:16:52 -0800 (PST), deadlyhead wrote:

> On Mar 4, 11:55�pm, "Dmitry A. Kazakov" <mail...@dmitry-kazakov.de>
> wrote:
>>
>> This is an ancient bug, which managed to survive a number of GNAT compiler
>> versions.
>>
>> As a workaround, add delay 0.0 at the beginning of your program:
>>
>>> ----------------------------------------------------------------------
>>
>>> -- �A test of the cost of conditionals
>>
>>> with Ada.Text_IO; �use Ada.Text_IO;
>>> with Ada.Real_Time; use Ada.Real_Time;
>>> procedure Conditional_Test is
>>
>
> Exactly what was needed. Thank you!
>
> Do you happen to know if this bug has been fixed in the current
> development branch? (At home I compile GNAT based on GCC 4.4, but
> haven't done any real-time tests with it yet.)

AFAIK it is still present in GNAT Pro 6.3.1, which is the latest version of
GNAT.

> This seems like an
> unfortunate bug to have lying around in an otherwise respected
> compiler.

Yes, but in real-life applications it does not show itself, because tasking
stuff somehow wakes the RTL up. That is probably the reason, I suggest, why
none of paying customers had yet reported it to AdaCore.

> BTW, my test results with -O3 and -Os, there is no difference in
> performance between the two loops, and -Os produces code that is about
> 33% faster than -O3. With -O0, the second loop is faster by an
> average of 10%. I would have thought the extra conditional would have
> been costlier.

Niklas has posted an excellent comment regarding performance measures. It
is quite difficult to do time measurements right in presence of -O2/3.

As a small addition, here is a technique I am using to subtract looping
overhead:

T := Clock;
for I in 1..N loop
... -- measured stuff
end loop;
D1 := Clock - T;

T := Clock;
for I in 1..N loop
... -- measured stuff
... -- measured stuff (do it twice)
end loop;
D2 := Clock - T;

(D2 - D1) / N is the average time spent on measured stuff without the
overhead caused by looping. Important, as Niklas has pointed out, to fool
the compiler so, that it will not optimize out the things you are
measuring...

Dmitry A. Kazakov

unread,
Mar 5, 2010, 4:04:06 AM3/5/10
to
On Fri, 5 Mar 2010 00:33:54 -0800 (PST), Ludovic Brenta wrote:

> Dmitry A. Kazakov wrote on comp.lang.ada:
>> On Thu, 4 Mar 2010 22:34:47 -0800 (PST), deadlyhead wrote:
>>> The problem I'm having, though, is that the timing just isn't
>>> happening. �This code will run for 15 seconds and when I examine the
>>> time span, it tells me that no time passed.
>>
>> This is an ancient bug, which managed to survive a number of GNAT compiler
>> versions.
>>
>> As a workaround, add delay 0.0 at the beginning of your program:
> [...]
>> delay 0.0; -- Wake up that dozing Ada RTL!
>
> I was not aware of this bug; is there a PR in Bugzilla for it?

As an active member of c.l.a. you should remember it discussed here several
times in recent years. Each time I thought - well, the next version will
certainly fix it, somebody had already reported it... (:-))

Alex Mentis

unread,
Mar 5, 2010, 7:41:12 AM3/5/10
to
On Mar 5, 3:49 am, "Dmitry A. Kazakov" <mail...@dmitry-kazakov.de>

Confirmed: the bug is still present in GNAT GPL 2009. The same code,
timed using Ada.Calendar seems to work just fine, though.
Interesting, and good to know about.

Ludovic Brenta

unread,
Mar 5, 2010, 10:27:43 AM3/5/10
to
Dmitry A. Kazakov wrote on comp.lang.ada:
> On Fri, 5 Mar 2010 00:33:54 -0800 (PST), Ludovic Brenta wrote:
>> I was not aware of this bug; is there a PR in Bugzilla for it?
>
> As an active member of c.l.a. you should remember it discussed here several
> times in recent years.

No, I should not remember it. Remembering bugs is the job of a bug
tracking system.

> Each time I thought - well, the next version will
> certainly fix it, somebody had already reported it... (:-))

Bad news: this bug will not be fixed just because you think it will
and because you happen to remember this bug. It *might* be fixed if
you report it properly in the bug tracking system of GCC. Usenet is
not a bug tracking system. A person's head is not a bug tracking
system.

As an active member of c.l.a, you should remember the appropriate URL
but I'll give it to you once again though: http://gcc.gnu.org/bugzilla

--
Ludovic Brenta.

Simon Wright

unread,
Mar 5, 2010, 3:17:27 PM3/5/10
to
I found the same results as Niklas, the compiler I'm running
is gcc version 4.5.0 20100221 (experimental) [trunk revision 156937]
(GCC) for x86_64-apple-darwin10.2.0.

I just added

Junk_In : Natural := 0;
pragma Volatile (Junk_In); -- <=====

after which -O[0123] all gave pretty similar results.

I didn't have to add 'delay 0.0;' to get the timings.

I did set

Test_Dur : constant := 10_000;

and the timings on this Macbook Pro (2.4 GHz Core 2 Duo are of order
0.292 with -gnato, 0.254 without. The second loop is quicker with -O0.

Jeffrey R. Carter

unread,
Mar 5, 2010, 4:15:09 PM3/5/10
to
Alex Mentis wrote:
>
> Confirmed: the bug is still present in GNAT GPL 2009. The same code,
> timed using Ada.Calendar seems to work just fine, though.
> Interesting, and good to know about.


This error does not appear in GNAT Pro 6.3.0w, at least using

-gnaton -O2 -fstack-check

--
Jeff Carter
"It's all right, Taggart. Just a man and a horse being hung out there."
Blazing Saddles
34

Simon Wright

unread,
Mar 5, 2010, 6:35:07 PM3/5/10
to
"Dmitry A. Kazakov" <mai...@dmitry-kazakov.de> writes:

> Test_Dur : constant := 10_000; -- 100_000 overflows on a 32-bit machine

I had expected that an x86_64 compiler would have 64-bit Integers; not
so! they're still 32-bits. System.Addresses are 64-bit, though.

Simon Wright

unread,
Mar 5, 2010, 6:35:11 PM3/5/10
to
Alex Mentis <asme...@gmail.com> writes:

> Confirmed: the bug is still present in GNAT GPL 2009.

Not on Mac OS X (Snow Leopard), it isn't.

Stephen Leake

unread,
Mar 6, 2010, 2:13:34 AM3/6/10
to
Ludovic Brenta <lud...@ludovic-brenta.org> writes:

> Dmitry A. Kazakov wrote on comp.lang.ada:
>> On Fri, 5 Mar 2010 00:33:54 -0800 (PST), Ludovic Brenta wrote:
>>> I was not aware of this bug; is there a PR in Bugzilla for it?
>>
>> As an active member of c.l.a. you should remember it discussed here several
>> times in recent years.
>
> No, I should not remember it. Remembering bugs is the job of a bug
> tracking system.

+1.

I'm an active member of c.l.a, and I don't remember this bug.

--
-- Stephe

Georg Bauhaus

unread,
Mar 6, 2010, 4:50:52 AM3/6/10
to

Seeing the different behavior, what should be the best update
for
http://en.wikibooks.org/wiki/Ada_Programming/Tips#Quirks


Simon Wright

unread,
Mar 6, 2010, 7:06:43 AM3/6/10
to
Georg Bauhaus <rm-host...@maps.futureapps.de> writes:

That looks _quite_ explicit ("Using GNAT on Windows, ..."). It would be
nice to have a reference to the (Bugzilla?) report!

Alex Mentis

unread,
Mar 6, 2010, 7:12:06 AM3/6/10
to
On Mar 5, 6:35 pm, Simon Wright <si...@pushface.org> wrote:

> Alex Mentis <asmen...@gmail.com> writes:
> > Confirmed: the bug is still present in GNAT GPL 2009.
>
> Not on Mac OS X (Snow Leopard), it isn't.

Good point. I'm running GNAT GPL 2009 on Windows Vista.

Georg Bauhaus

unread,
Mar 6, 2010, 8:02:11 PM3/6/10
to

Interesting in itself, and by coincidence, while reading
Pat Rogers's new contribution to the Shootout, I noticed
some lines that read

delay 0.0; -- yield

http://shootout.alioth.debian.org/u64q/program.php?test=chameneosredux&lang=gnat&id=2

Alex Mentis

unread,
Mar 8, 2010, 7:16:06 AM3/8/10
to
On Mar 6, 8:02 pm, Georg Bauhaus <rm-host.bauh...@maps.futureapps.de>
wrote:

> On 3/6/10 1:06 PM, Simon Wright wrote:
>
> > Georg Bauhaus<rm-host.bauh...@maps.futureapps.de>  writes:

>
> >> On 3/6/10 12:35 AM, Simon Wright wrote:
> >>> Alex Mentis<asmen...@gmail.com>   writes:
>
> >>>> Confirmed: the bug is still present in GNAT GPL 2009.
>
> >>> Not on Mac OS X (Snow Leopard), it isn't.
>
> >> Seeing the different behavior, what should be the best update
> >> for
> >>http://en.wikibooks.org/wiki/Ada_Programming/Tips#Quirks
>
> > That looks _quite_ explicit ("Using GNAT on Windows, ..."). It would be
> > nice to have a reference to the (Bugzilla?) report!
>
> Interesting in itself, and by coincidence, while reading
> Pat Rogers's new contribution to the Shootout, I noticed
> some lines that read
>
>    delay 0.0;  -- yield
>
> http://shootout.alioth.debian.org/u64q/program.php?test=chameneosredu...

Forward from AdaCore, FYI:

> We are able to reproduce the problem.

The problem is now understood and corrected in the development version
of GNAT.
It will most probably be corrected in GNAT GPL 2010.

What is happening here is that there is a missing call to
System.OS_Primitives.Initialize, when you use Ada.Real_Time but not
Ada.Calendar or any of the real time features of Ada, such as a delay
statement.

The fix consists in calling System.OS_Primitives.Initialize during
elaboration of Ada.Real_Time.

On POSIX platforms, because System.OS_Primitives.Initialize is a null
procedure, this missing call did not really matter.

Thank you for this report,

-- Vincent Celier

Reply all
Reply to author
Forward
0 new messages