Timing code

Posted by Nick Gammon on Sun 20 Jul 2003 11:22 PM — 6 posts, 18,679 views.

Australia Forum Administrator #0
In the process of testing STL I have wanted to know how fast various loops are. After some mucking around doing things the hard way, I made a simple class that will time any "batch" of code, by simply using a single line. For example, to time "something" I might do this:


{
timer t ("testing something");
something ();
}


The interesting thing here is that the entire work is done in the timer class constructor and destructor. The constructor makes a note of the current time, and echoes the "start" message.

The destructor makes a note of the (new) current time, subtracts the finish from the start, and displays the interval.

It is adapted to use the high-performance timer under Windows, and the gettimeofday under Unix.

You can nest calls (see example program) so you can time smaller bits of code while still timer the larger overall picture.

The purpose of the braces is to "scope" the timer class so that when it hits the closing brace it goes out of scope and the destructor is called.

If you simply want to time an entire function, this is not necessary as the destructor is called when the function exits.

eg.


void myfunction (void)
  {
  timer t ("myfunction");

  //  do something lengthy here

  }  // end of myfunction - time elapsed will be displayed


You could make it fancier - eg. make the displaying of the time optional, however this is a good starting point.


// disable warnings about long names
#ifdef WIN32
  #pragma warning( disable : 4786)
#endif

#include <string>
#include <iostream>
#include <iomanip>
#include <deque>
#include <list>
#include <vector>

#ifdef WIN32
  #include <windows.h>    // for QueryPerformanceCounter
#else
  #include <sys/time.h>   // for gettimeofday
#endif

using namespace std;  

class timer
  {
#ifdef WIN32
  LARGE_INTEGER start;
  LONGLONG iCounterFrequency;
#else
  long long start;
#endif

  const string sReason;

  public:

    // constructor remembers time it was constructed
    timer (const string s) : sReason (s)
      {
#ifdef WIN32
      LARGE_INTEGER large_int_frequency;  
      QueryPerformanceFrequency (&large_int_frequency);
      iCounterFrequency = large_int_frequency.QuadPart;
      QueryPerformanceCounter (&start);
#else
      struct timeval t;
      gettimeofday( &t, NULL );
      start = (t.tv_sec * 1000000L) + t.tv_usec;
#endif
      cout << "Start     : " << setw (25) << left << sReason << endl;
      };

    // destructor gets current time, displays difference
    ~timer ()
      {
#ifdef WIN32
      LARGE_INTEGER finish;
      LONGLONG iTimeTaken;    
      QueryPerformanceCounter (&finish);  
      iTimeTaken = finish.QuadPart - start.QuadPart; 
      double fTime = ((double) iTimeTaken) /      
                     ((double) iCounterFrequency);    

#else      
      struct timeval t;
      gettimeofday( &t, NULL );
      long long finish = (t.tv_sec * 1000000L) + t.tv_usec; 
      double fTime = (finish - start) / 1000000.0;
#endif
      cout << "Time taken: " << setw (25) << left << sReason << " = "
           << fixed << fTime << " seconds." << endl;

      }
  };    // end of class timer


#define LOOPS 50000

int main (void)
  {
  timer all_things ("overall");

  {
  timer t ("testing vector");
    
  vector<string> v;

  for (int i = 1; i < LOOPS; i++)
    v.push_back ("hi there");

  }

  {
  timer t ("testing list");
    
  list<string> L;

  for (int i = 1; i < LOOPS; i++)
    L.push_back ("hi there");

  }

  {
  timer t ("testing deque");
    
  deque<string> d;

  for (int i = 1; i < LOOPS; i++)
    d.push_back ("hi there");

  }

  return 0;
  } // end of main




Example Output

Start     : overall
Start     : testing vector
Time taken: testing vector            = 0.094685 seconds.
Start     : testing list
Time taken: testing list              = 0.065218 seconds.
Start     : testing deque
Time taken: testing deque             = 0.045103 seconds.
Time taken: overall                   = 0.206196 seconds.
Amended on Sun 20 Jul 2003 11:26 PM by Nick Gammon
USA #1
That's a very clever way of solving a common problem with just one line... I like!

I also think it's interesting that 150,000 loops took 200ms... that seems very fast. :) What processor did you run this on?
Australia Forum Administrator #2
You are welcome to use it.


The test above was run on my Linux PC, which is:


Linux version 2.4.20-13.9 (bhcompile@porky.devel.redhat.com) (gcc version 3.2.2
20030222 (Red Hat Linux 3.2.2-5)) #1 Mon May 12 10:55:37
...
Initializing CPU#0
Detected 864.478 MHz processor.
...
Memory: 640668k/655296k available (1355k kernel code, 12064k reserved, 1004k data, 132k init, 0k highmem)


In other words, 860 MHz Pentium. My initial test was on my Windows PC, which is a bit slower MHz-wise (166 compared to 860) however the results are a lot slower...

Output on my 166 MHz Pentium under Windows NT 4


Start     : overall
Start     : testing vector
Time taken: testing vector            = 3.414081 seconds.
Start     : testing list
Time taken: testing list              = 2.999875 seconds.
Start     : testing deque
Time taken: testing deque             = 1.976376 seconds.
Time taken: overall                   = 8.424079 seconds.


Based on raw CPU speed you would expect it (the faster PC) to be only 5 times faster, however it is really 41 times faster. Interesting. Perhaps Linux is faster. ;)

To be fair, I tried again with optimised results (release compile under Windows, optimised for speed, and using -O3 under gcc). Here are the results ...

Linux (860 MHz) ...

Start     : overall
Start     : testing vector
Time taken: testing vector            = 0.060668 seconds.
Start     : testing list
Time taken: testing list              = 0.048561 seconds.
Start     : testing deque
Time taken: testing deque             = 0.037505 seconds.
Time taken: overall                   = 0.147881 seconds.



Windows (166 MHz) ...

Start     : overall
Start     : testing vector
Time taken: testing vector            = 0.475702 seconds.
Start     : testing list
Time taken: testing list              = 0.513529 seconds.
Start     : testing deque
Time taken: testing deque             = 0.381818 seconds.
Time taken: overall                   = 1.400138 seconds.


In this case the faster PC is only 9.5 times faster, which is about twice what you would expect. Perhaps the debug release is much slower under Windows than gcc.
Amended on Mon 21 Jul 2003 11:46 PM by Nick Gammon
Australia Forum Administrator #3
And, as an interesting comparison, trying the same code on an 800 MHz PowerPC G4 (iMac), gave these results:


Start     : overall
Start     : testing vector
Time taken: testing vector            = 0.092482 seconds.
Start     : testing list
Time taken: testing list              = 0.101746 seconds.
Start     : testing deque
Time taken: testing deque             = 0.061732 seconds.
Time taken: overall                   = 0.268990 seconds.

Australia Forum Administrator #4
An interesting comparison also is to compare the SGI STL library to the one shipped with MS VC++. After installing that (for reasons explained in another thread about mem_fun_ref), I re-timed the loops above. This time the release build under Windows, on a 166 MHz PC, gave:


Start     : overall
Start     : testing vector
Time taken: testing vector = 0.340474 seconds.
Start     : testing list
Time taken: testing list = 0.228525 seconds.
Start     : testing deque
Time taken: testing deque = 0.189052 seconds.
Time taken: overall = 0.760359 seconds.


This is almost twice as fast as before (the total previously was 1.400138 seconds).

USA #5
A slightly improved version of the timer class, that lets you specify whether you want the text to be printed, and whether you want the total to be added to a variable somewhere. This is useful if you want to do something like time every loop individually, and total it up, without printing every time.

Note that the default timer behavior remains unchanged (so the new code is backwards compatible.)




/*

code timing class

Author: Nick Gammon	
Date:   22nd July 2003

modfied by:
dhaley oct 12 2003:
- added print/total options
- default behavior remains unchanged

*/

#include <string>
#include <iostream>
#include <iomanip>

using namespace	std;

class timer
{
#ifdef WIN32
	__int64	start;
	__int64	iCounterFrequency;
#else
	long long start;
#endif

private:

	const std::string sReason;
	double * dTotal;
	bool bPrint;

public:

	// constructor remembers time it was constructed
	timer (const std::string s, bool print = true, double * total = NULL);

	// destructor gets current time, displays difference
	~timer ();

}; // end of class timer



// constructor remembers time it was constructed
// dhaley oct 12 2003: added print/total options
timer::timer (const string s, bool print, double * total) : sReason (s)
{
#ifdef WIN32
	LARGE_INTEGER large_int_frequency;	
	QueryPerformanceFrequency (&large_int_frequency);
	iCounterFrequency =	large_int_frequency.QuadPart;
	QueryPerformanceCounter	((LARGE_INTEGER	*) &start);
#else
	struct timeval t;
	gettimeofday( &t, NULL );
	start =	(t.tv_sec *	1000000L) +	t.tv_usec;
#endif
	bPrint = print; // remember if we want to print to cout or not
	if (print)
		cout <<	"Start	   : " << setw (25)	<< left	<< sReason << endl;
	this->dTotal = total; // store the pointer to the total
};	// end constructor

// destructor gets current time, displays difference
timer::~timer ()
{
#ifdef WIN32
	__int64	finish;
	__int64	iTimeTaken;	   
	QueryPerformanceCounter	((LARGE_INTEGER	*) &finish);  
	iTimeTaken = finish	- start; 
	double fTime = ((double) iTimeTaken) /		
		((double) iCounterFrequency);
#else	   
	struct timeval t;
	gettimeofday( &t, NULL );
	long long finish = (t.tv_sec * 1000000L) + t.tv_usec; 
	double fTime = (finish - start)	/ 1000000.0;
#endif
	if ( this->dTotal ) // add to the total, if we have one
		*dTotal += fTime;
	if ( bPrint ) // print if we wanted to
	{
		cout <<	"Time taken: " << setw (25)	<< left	<< sReason << "	= "
			<< fixed <<	fTime << " seconds." <<	endl;
	}

};	   // end destructor


Timers are fun... :)



Modified to add usage example:

double drawTotal = 0;
int main()
{
	int frameNum = 0;
	while (someCondition)
	{
		lifeBoard->Redraw();
		frameNum++;
	}
	cout << "Total draw time: " << drawTotal;
	cout << "Time per frame:  " << drawTotal/frameNum;
	return 0;
}
void cLifeBoard::Redraw()
{
	timer t("Draw", false, &drawTotal);
	ClearCellField(); // see lifeGraphics.h
	for (ushort i = 0; i < NUM_ROWS; i++) // for every row...
	{
		for (ushort j = 0; j < NUM_COLS; j++) // ...for every column...
		{
			// ... draw the cell if active
			if ( this->CurrentGrid->data[i][j] > 0)
				DrawCellAt(i, j, this->CurrentGrid->data[i][j] );
		}
	}
	UpdateDisplay();
}


The Game of Life is fun too. :)