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.
}
}
*/
Measuring the time spent on code executions
Author
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.
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.
Your idea is fine. I've used it before with no problems. Destructors will get called at the right time.
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.
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.
Note also that the act of printing timing messages will throw off your timing by quite a bit. :)
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.
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.
Author
Thanks for your help.
Original post by AntheusQuote: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.
This topic is closed to new replies.
Advertisement
Popular Topics
Advertisement
