Jump to content
  • Advertisement
Sign in to follow this  
Jack Bartlett

Measuring the time spent on code executions

This topic is 3322 days old which is more than the 365 day threshold we allow for new replies. Please post a new topic.

If you intended to correct an error in the post then please contact us.

Recommended Posts

I've been looking for a way to log the time spent on execution of functions in my codes, and came up with the following idea.
class CScopeLog
{
	const char *m_pText;

	const time m_StartTime;

public:

	inline CScopeLog( const char *pText );
	inline ~CScopeLog();
};


inline CScopeLog::CScopeLog( const char *pText )
:
m_pText(pText),
m_StartTime(GetCurrentTime())
{
	printf( "Entered: %s\n", m_pText );
}


inline CScopeLog::~CScopeLog()
{
	printf( "Leaving: %s\n", m_pText );

	time time_spent = GetCurrentTime() - m_StartTime;

	printf( "%s - Total Time: %d ms\n", m_pText, time_spent.get_msec() );
}


#define LOG_SCOPE( title )   CScopeLog scope_log(title)
#define LOG_FUNCTION_SCOPE() CScopeLog function_scope_log(__FUNCTION__)


/*

// usage samples
void do_sth()
{
	LOG_FUNCTION_SCOPE(); // Don't put anything before this.

	// calculate something
}

void do_sth_else
{

	// calculate x

	{
		LOG_SCOPE( "calculate x" ); // Don't put anything before this in this scope.
	}
}

*/

The basic idea is to use constructor and destructor to get the start and end time, and calculate the time spent on execution of the code within a scope. Using the macros above, you can print the time with a single line of code and don't have to do the same calculation every time. Now, one of my colleagues suggested that this does not work unless it is guaranteed that constructor and destructor are called in the exact order shown in the code. For example, he said that he's not sure if the destructor call is done exactly when the thread exits the scope or it could be delayed. I'd appreciate it if anyone teach me if there are any problems in measuring the time this way, or where I can find related resources (books, websites, etc.) Thanks.

Share this post


Link to post
Share on other sites
Advertisement
Your idea is fine. I've used it before with no problems. Destructors will get called at the right time.

Share this post


Link to post
Share on other sites
Quote:
For example, he said that he's not sure if the destructor call is done
exactly when the thread exits the scope or it could be delayed.


Auto-allocated members are destroyed exactly when they are no longer accessible, which in majority of cases means when they go out of scope. There are slight variations to this rule, but none that would apply to you in majority of cases. Example.

Delayed invocation however happens in Python, but for different reasons.

Also, assume that you will not get absolutely perfect results (nano-second or CPU tick precision), so make sure to consider accuracy when evaluating results. If you are profiling 1ms+ functions however, it should be fine with high resolution timers.

Another safety would be to make m_StartTime, or even the class itself volatile. That should prevent compiler from potentially rearranging the code order in some cases.

Share this post


Link to post
Share on other sites
Note you shouldn't use getCurrentTime for small times, it's fine for anything over a couple of seconds, but below that it's extremely inaccurate.

Share this post


Link to post
Share on other sites
Note also that the act of printing timing messages will throw off your timing by quite a bit. :)

Share this post


Link to post
Share on other sites
You should also aggregate all of your times somewhere before ever calling cout (You are using c++, ditch the printf!).
Printing to the console is really really slow by comparison to most of what you time. So if you ever nest your profiles (profile Foo, foo calls bar, bar also has a profile). Then the profile times are going to be wildly inacurate.

You need to look into a high performance timer like window's QueryPerformanceCounter() if you expect to get reasonable timing values.

Share this post


Link to post
Share on other sites
Thanks for your help.


Original post by Antheus
Quote:
Another safety would be to make m_StartTime, or even the class itself volatile. That should prevent compiler from potentially rearranging the code order in some cases.



I will change macros to declare the variable with 'volatile',


#define LOG_SCOPE( title ) volatile CScopeLog scope_log(title)
#define LOG_FUNCTION_SCOPE() volatile CScopeLog function_scope_log(__FUNCTION__)





Quote:
Original post by sirpalee
Note you shouldn't use getCurrentTime for small times, it's fine for anything over a couple of seconds, but below that it's extremely inaccurate.



Do you mean any specific API by getCurrentTime()?
I'm sorry that I confused you, but I just wrote GetCurrentTime()
to mean calling some function that returns the current time.
e.g. the time that elapsed since the application startup.
In my actual code, I use QueryPerformanceCounter().

Anyway, I noticed that it's not really the best thing to measure the time this way
since print function calls will be bottleneck at every measuring point.
Dropping printf() in ctor and dtor would help. However, as KulSeran suggested,
if the CScopeLog is defined multiple times in nest, the printf() at the end
will make the measuring inaccurate.

Actually, I've been using some other runtime profiler to profile my code
in millisecond accuracy (rendering, update, etc).
The reason to created all this is to measure time spent on some init functions
that are executed once at the startup and takes at least 500ms or so.

Anyway, thanks for all your help.

Share this post


Link to post
Share on other sites
Sign in to follow this  

  • Advertisement
×

Important Information

By using GameDev.net, you agree to our community Guidelines, Terms of Use, and Privacy Policy.

Participate in the game development conversation and more when you create an account on GameDev.net!

Sign me up!