[boost] Re: Re: Profiling Library suggestion

From: Preston A. Elder (prez_at_[hidden])
Date: 2005-02-11 16:34:36

Hum

I don't know why, but my last e-mail on this subject went AWOL, so I'm
going to re-type it (which is a shame, as it was quite long).

I think the profiler is making great progress, however I still have two
major issues with it.

First, that the policy stuff is all static.  This makes it impossible for
me to have two or more individual profilers going, using the same policy,
but, say, a different output file, without making the policy extremely
complex and doing all kinds of string matching to sort out whats what.

For example:

void MyFunc()
{
    Profile huge("MyFunc");

    {
        Profile big("loop1");
        for (i=0; i<100; ++i)
        {
            {
                Profile small("op1");
                op1_part1();
                op1_part2();
            }
            {
                Profile small("op2");
                op2_part1();
                op2_part2();
            }
            {
                Profile small("op3");
                op3_part1();
                op3_part2();
            }
        }
    }

    {
        Profile big("some_act");
        do_something();
    }

    {
        Profile big("loop2");
        for (i=0; i<100; ++i)
        {
            {
                Profile small("op4");
                op4_part1();
                op4_part2();
            }
            {
                Profile small("op5");
                op5_part1();
                op5_part2();
            }
            {
                Profile small("op6");
                op6_part1();
                op6_part2();
            }
        }
    }
}

I want the 'huge', 'big' and 'small' profile instances to use different
collectors that all use the same policy (accumulate and count, plus print
to file every, say, 30s), but, say, output to different files.  With the
static nature of everything you have in there regarding this, I would need
to either:
a) create a separate policy just to change the output file.
or b) in the policy, some how determine which named entries go to which
accumulator, and then record as such.

Having them separate would allow me to disable them separately, too.  For
example, I could use the 'huge' to get a general idea of what section of
code on average takes the longest.  Then I could drill down slightly
further to find out which portion of that code is taking the longest, and
then even further to find out which particular options are taking longest,
and I could do it all individually.

Second is the syntax, which requires me to either declare all profiled
sections ahead of time, pause them, then when I get to the part I want
resume and pause them again, or use ugly scoping syntax to encapsulate
multiple blocks of code.

For an example of the first, assume in the MyFunc I want every opX_*
call profiled as one.  The goal here is to find out, over calls to MyFunc,
how much time opX_* is taking, not how many times opX_* is called and the
average time for that call.  Like so:

void MyFunc()
{
    Profile p_op1("op1"), p_op2("op2"), p_op3("op3");
    p_op1.pause();
    p_op2.pause();
    p_op3.pause();

    for (i=0; i<100; ++i)
    {
        p_op1.resume();
        op1_part1();
        op1_part2();
        p_op1.pause();

        p_op2.resume();
        op2_part1();
        op2_part2();
        p_op2.pause();

        p_op3.resume();
        op3_part1();
        op3_part2();
        p_op3.pause();
    }

    do_something();

    for (i=0; i<100; ++i)
    {
        p_op1.resume();
        op1_part1();
        op1_part2();
        p_op1.pause();

        p_op2.resume();
        op2_part1();
        op2_part2();
        p_op2.pause();

        p_op3.resume();
        op3_part1();
        op3_part2();
        p_op3.pause();
    }
}

This is the only way to get all opX_* functions accumulated together, so
that the count goes up by 1 for each call to MyFunc, and the time for all
instances of opX_* is added, as opposed to getting a 200 count opX_*
function calls, and then the averaging being the time per call (which is
not what I want in this case).

For an example of the second, try this:

void MyFunc()
{
    {
        Profile op1("op1");
        op1_part1();
        int rv1 = op1_part2();
    }

    {
        Profile op2("op2");
        op2_part1();
        op2_part2();
    }

    if (rv > 30)
        Profile::generate_report();

    {
        Profile op1("op1");
        op1_part1();
        op1_part2();
    }
}

Obviously, in the example, I want the profiling data done before the
report generate in the report generated.  And the stuff afterwards not. 
So I can't, as in the previous example, declare it at the beginning. 
Either way, the scoping operators used here are kind of ugly.

BTW, I'm wondering why you don't use something like this as the basis for
your high-resolution timer:

boost::posix_time::ptime get_highres_time()
{
#ifdef BOOST_DATE_TIME_HAS_HIGH_PRECISION_CLOCK
    return boost::date_time::microsec_clock<boost::posix_time::ptime>::local_time();
#else
    boost::xtime now;
    boost::xtime_get(&now, boost::TIME_UTC);
    boost::posix_time::ptime rv = boost::posix_time::from_time_t(now.sec);
# ifdef BOOST_DATE_TIME_HAS_NANOSECONDS
    return (rv + boost::posix_time::nanoseconds(now.nsec));
# else
    return (rv + boost::posix_time::microseconds(now.nsec / 1000));
# endif
#endif
}

It doesn't matter that the first is in local time and the second is in UTC
time, since either way, you'll only be looking at the difference between
two times gained by the same function:

boost::posix_time::ptime start = get_highres_time();
// do something
boost::posix_time::time_duration = (get_highres_time() - start);

This doesn't rely on any windows or posix specific code, either.

Just a thought :)

PreZ :)