Putting execution timing code into a function, OpenCV?

Question

I have this code snippet that I use everywhere in my programs (C++ and OpenCV). It is for timing some operations:

double t;

// Some code...

t = (double)getTickCount();

Object1.LotOfComputing();

t = 1000*((double)getTickCount() - t)/getTickFrequency();
cout << "Time for LotOfComputing =" << t << " milliseconds."<< endl;
cout << "=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=" << endl;

This is how the OpenCV doc recommend to time a function/portion of code and it seems to works for me after using it for some weeks. The times I measure are ranging from about 1ms to 700ms, and I round them to the millisecond.

The problem is that I time a lot of different operations in my program and the code is cluttered by these snippets.

I wonder if it would be wise to put these lines of code into a function, like:

double timing(double time){

timing = 1000*((double)getTickCount() - time)/getTickFrequency();
cout << "Time for LotOfComputing =" << timing << " milliseconds."<< endl;
cout << "=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=" << endl;

return timing;

}

So I could be able to use this:

double t;

// Some code...

t = (double)getTickCount();

Object1.LotOfComputing();

timing(t);

I am simply concerned about the execution time of going through function calls... Maybe I am simply worrying for nothing!

Answer 1

here's a little profiler magic ;)

basically, it makes static counters per scope (think a pair of {}), which get initialized at module startup, and get read out at module release time. of course this takes time, too, so you don't want this inside some tight loop.

// you might want to change the clock
#define get_ticks cv::getTickCount
#define get_freq  cv::getTickFrequency
double dt(int64 t) { return double(t*1000/get_freq())/1000.0; }

struct Profile
{
    string name;
    int64 t; // accumulated time
    int64 c; // function calls

    Profile(const string & name) 
        : name(name)
        , t(0) 
        , c(0)
    {}   

    ~Profile() 
    {
        cerr << format("%-24s %8u ",name.c_str(),c);
        cerr << format("%13.6f ",dt(t/c)); 
        cerr << format("%13.6f ",dt(t));
        cerr << format("%14u",t);
        cerr << endl;
    }

    struct Scope
    {
        Profile & p;
        int64 t;

        Scope(Profile & p) 
            : p(p) 
            , t(get_ticks()) 
        {}

        ~Scope() 
        { 
            int64 t1 = get_ticks();
            if ( t1 > t )
            {
                p.t += t1 - t;
                p.c ++;
            }
         }
    }; 
};

#define PROFILEX(s) static Profile _a_rose(s); Profile::Scope _is_a_rose_is(_a_rose);
#define PROFILE PROFILEX(__FUNCTION__)

later use it:

void foo() {
   PROFILE;
   int k=10;
   while (k) {
       PROFILEX("foo while loop");
       k --;
   }
}
void bar() {
   PROFILE;
}

int main() {
    PROFILE;
    {
        PROFILEX("useless scope");
        bar();
        bar();
    }
    foo();
    return 0;
}

---

foo while loop                 10      0.000000      0.000002           3959
foo                             1      0.000007      0.000007          13000
bar                             2      0.000000      0.000000            843
useless scope                   1      0.000004      0.000004           7710
main                            1      0.000017      0.000017          31712