C++ Very strange behaviour measuring function execution time - My head exploded

Question

Besides my head exploding this is what happened.

I wanted to measure the execution time of a method from a class. The method was too fast to get an accurate time using QueryPerformanceCounter, GetTickCount or Clock.

I called the method 2000 times and measured the time elapsed.

start=clock();
for (i=0;i<2000;i++)
{
    myObject->myMethod(x);
}
end = clock()-start;
printf("->Partial time: %d\n", end);    

I was getting an elapsed time of 1.1-1.3 seconds.

I made the code into a function.

void testingFunction(MyObject *myObject,int NumberOfRepetitions, int startAt,int endAt)
{ 
    int i,j;
    clock_t start,end;
    for (j=0;j<numberOfRepetitions;j++)
    {
         start=clock();
         for (i=startAt;i<endAt;i++)
         {
             myObject->myMethod(i);
         }
         end = clock()-start;
         printf("->Partial time: %d\n", end);
    }
 }

When calling the function

for(i=0;i<10;i++)
    testingFunction(myObject,1,0,2000);// got time between 1.1-1.3 all 10 times

If calling

testingFunction(myObject,10,0,2000);

the time increased:

Partial time: 1260 
Partial time: 1890
Partial time: 2530
Partial time: 3700
Partial time: 4100
Partial time: 5360
etc

I can't understand why this is happenining.

Answer 1

typo? that comma should be semi-colon?

for (i=startAt;i<endAt,i++)
     {
         myObject->myMethod(i);
     }

Answer 2

It would help a lot if you posted a compilable example of what you're doing.

Until then, I'll suggest you to measure the time using gettimeofday() as exemplified here.

If you're feeling a bit lazy today, you could add this function to your source code:

#include <sys/time.h> 

long myclock()
{
    struct timeval tv;
    gettimeofday(&tv, NULL);
    return (tv.tv_sec * 1000000) + tv.tv_usec;
}

and then to measure time on your code you could do something like:

long start = myclock();

for (i=0;i<2000;i++)
{
    myObject->myMethod(x);
}

long diff = myclock() - start;
std::cout << "[" << time->tm_hour << ":"<< time->tm_min << ":" << time->tm_sec << 
             "] time:" << std::setprecision(3) << diff/1000000.0 << std::endl;

Don't forget to also #include <iostream> on your code.

Answer 3

There must be something else going on. Here is a quick sample program I created with your testing code:

#include <stdio.h>
#include <time.h>

class MyObject
{
    public:
        void myMethod(int i) { for (long k=0; k<100000; k++) { } }
};

void testingFunction(MyObject *myObject,
                     int numberOfRepetitions,
                     int startAt, int endAt) 
{
    int i,j; 
    clock_t start,end; 
    for (j=0;j<numberOfRepetitions;j++) 
    { 
         start=clock();
         for (i=startAt;i<endAt;i++) 
         { 
             myObject->myMethod(i); 
         } 
         end = clock()-start; 
         printf("->Partial time: %d\n", end); 
    } 
 } 


int main(int argc, char * argv[])
{
    MyObject myObject;

    for (int i = 0; i < 10; i++)
    { testingFunction(&myObject, 1, 0, 2000); }

    printf("----\n");

    testingFunction(&myObject, 10, 0, 2000);

    return 0;
}

The results are consistent:

->Partial time: 406
->Partial time: 406
->Partial time: 406
->Partial time: 406
->Partial time: 391
->Partial time: 406
->Partial time: 407
->Partial time: 406
->Partial time: 406
->Partial time: 391
----
->Partial time: 406
->Partial time: 406
->Partial time: 406
->Partial time: 407
->Partial time: 406
->Partial time: 391
->Partial time: 406
->Partial time: 406
->Partial time: 406
->Partial time: 407

Answer 4

Thank you all for your answers,

I'd also like to mention that calling:

testingFunction(myObject,1,0,2000);
//myMethod is called 2000 times with arguments 0-1999

gives a higher time than the cumulated time of calling

testingFunction(myObject,1,0,1000); 
//myMethod is called 1000 times with arguments 0-999
testingFunction(myObject,1,1000,2000);
//myMethod is called 1000 times with arguments 1000-1999

Looks like the method myMethod() is using some resource that is getting used up. In the >initial version you are re-setting the resource but in the extended version you keep using >more and more. The actual answer lies within 'myObject' so we need the class declarations >and all the method definitions and the bit of code that calls your test. What you should >do is provide a compilable piece of code that others can test. – Martin York 2 hours ago

myObject is in fact an interface to a dll that uses COM(did I say that correctly?). I myself don't have the code for the dll, I can only see what methods the interface has.

The dll at the beginning loads some records and myMethod searches through those records. Someone suggested that this could be due to cache miss. But the time can increase even to 20seconds(almost 20 times bigger). Isn't that to big to be created by cache misses?

John Dibling wrote

50 ms was too fast for QueryPerformanceCounter() to measure? Then either
QueryPerformanceCounter() isn't implemented on your platform or you were using it wrong

Not 50ms. 1.1-1.3 seconds / 2000 = 1100-1300 ms / 2000 = 0.55ms - 0.65ms That's too fast for QueryPerformanceCounter() on my PC.

@festo yes that was a typo made when posting here. e.James Thank you for the time you took with this!