   Measuring the time spent on code executions
  I've been looking for a way to log the time spent on execution of functionsin 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 samplesvoid 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 getthe start and end time, and calculate the time spent on executionof the code within a scope.Using the macros above, you can print the time with a single line of codeand don't have to do the same calculation every time.Now, one of my colleagues suggested that this does not workunless it is guaranteed that constructor and destructor are calledin the exact order shown in the code.For example, he said that he's not sure if the destructor call is doneexactly when the thread exits the scope or it could be delayed.I'd appreciate it if anyone teach me if there are any problemsin 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 doneexactly 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.;  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 sirpaleeNote 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 waysince 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 endwill make the measuring inaccurate.Actually, I've been using some other runtime profiler to profile my codein millisecond accuracy (rendering, update, etc).The reason to created all this is to measure time spent on some init functionsthat are executed once at the startup and takes at least 500ms or so.Anyway, thanks for all your help.