Register forum user name Search FAQ

Gammon Forum

Notice: Any messages purporting to come from this site telling you that your password has expired, or that you need to verify your details, confirm your email, resolve issues, making threats, or asking for money, are spam. We do not email users with any such messages. If you have lost your password you can obtain a new one by using the password reset link.

Due to spam on this forum, all posts now need moderator approval.

 Entire forum ➜ Programming ➜ General ➜ Timing code
Timing code

It is now over 60 days since the last post. This thread is closed.     Refresh page

Posted by Nick Gammon   Australia  (23,173 posts)  Bio   Forum Administrator
Date Sun 20 Jul 2003 11:22 PM (UTC)

Amended on Sun 20 Jul 2003 11:26 PM (UTC) by Nick Gammon

Message
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.
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by David Haley   USA  (3,881 posts)  Bio
Date Reply #1 on Mon 21 Jul 2003 12:34 PM (UTC)
Message
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?
David Haley aka Ksilyan
Head Programmer,
Legends of the Darkstone

http://david.the-haleys.org
Top
Posted by Nick Gammon   Australia  (23,173 posts)  Bio   Forum Administrator
Date Reply #2 on Mon 21 Jul 2003 08:44 PM (UTC)

Amended on Mon 21 Jul 2003 11:46 PM (UTC) by Nick Gammon

Message
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.
- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,173 posts)  Bio   Forum Administrator
Date Reply #3 on Mon 21 Jul 2003 11:32 PM (UTC)
Message
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.

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by Nick Gammon   Australia  (23,173 posts)  Bio   Forum Administrator
Date Reply #4 on Thu 24 Jul 2003 02:13 AM (UTC)
Message
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).

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top
Posted by David Haley   USA  (3,881 posts)  Bio
Date Reply #5 on Wed 15 Oct 2003 01:23 AM (UTC)

Amended on Wed 15 Oct 2003 01:30 AM (UTC) by David Haley

Message
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. :)
David Haley aka Ksilyan
Head Programmer,
Legends of the Darkstone

http://david.the-haleys.org
Top

The dates and times for posts above are shown in Universal Co-ordinated Time (UTC).

To show them in your local time you can join the forum, and then set the 'time correction' field in your profile to the number of hours difference between your location and UTC time.

17,691 views.

It is now over 60 days since the last post. This thread is closed.     Refresh page

Go to topic:           Search the forum

[Go to top] top

Information and images on this site are licensed under the Creative Commons Attribution 3.0 Australia License unless stated otherwise.

Home