[boost] Re: [function] timing trivia

From: matt_at_[hidden]
Date: 2004-02-15 06:46:22

"Pavel Vozenilek" wrote in message news:c0nfp0$pp5$1_at_sea.gmane.org...
>
> "Hurd, Matthew" <hurdm_at_[hidden]> wrote
>
> > This is an Intel P43.2 I'm running on now and I'm getting output like:
> >
> > boost function measurements: median time = 250.698 microseconds
> > direct in-line: median time = 250.691 microseconds
> >
> > You see here I look at the median time for boost function and
> > direct-inline and see only a 7 ns difference which is probably smaller
> > than I can truly measure I suspect...
> >
> I wrote my own test (the most simple one, call function/boost::fn
> in loop and measuring total time).
>
> The numbers I got give me ~18 microseconds overhead per single
> boost::function call (raw call takes ~404 microseconds).
>
> I use Intel C++ 8.0 plugged in VC6 IDE,, release mode,
> Athlon XP 2200+, W2K.
>
> /Pavel
>
<snipped code>

> ----------------------------------
>
> test1() and test2() took each 30-40 seconds.
> GetTickCount() resolution is at least 10 milliseconds.

Thanks Pavel.  I ran your test with vc7.1 in an optimised form as is with
the only change being test1 and test1 returning tick2-tick1 as a long.

Similar ball park figures for overall run time as you.
    test1 = 33312 ms
    test2 = 30625 ms
Yep, boost function call based loop is faster.

vc7.1, athlon 2800+, xp1a

Also the 18 microseconds cost you measured, or roughly 30 microseconds
benefit measured with my optimisation settings, can't just be put down to
the boost::function difference I think as 18 microseconds is 36,000 cycles
at 2 GHz and I don't think boost function could possibly cost that.

If I crank the loop down to #define MAX_FN_LOOP 1e2 with 10,000,000
iterations in the test fn's I get
    test1 = 3578 ms
    test2 = 3219 ms

Still curiously faster.  Though the overhead indicated is 3.6 nanoseconds...

If I turn my optimisations off for the last case, but still run in release
mode I get:
    test1 = 8594 ms
    test2 = 8797 ms

Which is the way around you'd expect it to be with boost::function being
slower given some kind of abstraction penalty.

So, I guess the insight is, your mileage may vary, optimisers are strange
beasts, benchmarks are often misleading and weird... cliches are cliches.

By the way, I have a slightly improved little bench harness that correctly
measures emptiness at zero nanoseconds for an instrusive style of
benchmark now if you or any one is interested I can email it to you.

That is it correctly measures:
  inline double blank( matt::timer& t )
  {
    double now;
    t.restart();
    now = t.elapsed();
    return now;
  }
to be zero ns consistently for me.

Thanks again for your numbers Pavel.

Regards,

Matt Hurd.