Class to help debug how long code takes

The "ProfileTimer" class below is adapted from code I used to use when developing Windows programs. It solves in a neat way the general problem of wanting to time bits of code in a simple way.

With the class installed (eg. from a header file) you can time a function (or part of a function) with a single line, like this:

void readSensors ()
{
ProfileTimer t ("readSensors");

a = analogRead (A0);
b = analogRead (A1);
}

What that does is the ProfileTimer constructor notes the current time. And then when the destructor is reached at the end of the function it displays the time in microseconds. To get rid of it you just comment out or delete a single line.

Example output:

Start     : readSensors
Time taken: readSensors = 4248 microseconds.

You can time part of a function by simply forcing the ProfileTimer class to have local scope like this:

... early part of function here
 {
    ProfileTimer t1 ("multiple reads");
    for (int i = A0; i <= A5; i++)
      analogRead (i);
  }  // end timed bit of code
... rest of function here

Class and example code below. You could easily change it to use millis rather than micros if you prefer. Millis has less resolution but can time a longer interval (micros() can time about 70 minutes, millis() can time about 50 days).

// ProfileTimer class
// Author: Nick Gammon
// Date: 11th May 2011

class ProfileTimer
{
  unsigned long start_;
  const char * sReason_;

public:

  // constructor remembers time it was constructed
  ProfileTimer (const char * reason) : 
  sReason_ (reason)
  {
    Serial.print ("Start     : ");
    Serial.println (sReason_);
    start_ = micros ();
  }

  // destructor gets current time, displays difference
  ~ProfileTimer ()
  {
    unsigned long interval = micros () - start_;
    Serial.print ("Time taken: ");
    Serial.print (sReason_);
    Serial.print (" = ");
    Serial.print (interval);
    Serial.println (" uS.");
  }
};    // end of class ProfileTimer


void setup ()
{
  Serial.begin (115200);
}  // end setup

void loop ()
{
  delay (500);

  ProfileTimer t ("analog read");
  analogRead (A1);

  {
    ProfileTimer t1 ("multiple reads");
    for (int i = A0; i <= A5; i++)
      analogRead (i);
  }  // end timed bit of code

}  // end loop

You can have multiple nested timers as in the example. This can also be used to indicate function coverage (that is, what functions get called in what order). You could, of course, change Serial.print to whatever your specific requirements were for reporting the information.

Example output:

Start     : analog read
Start     : multiple reads
Time taken: multiple reads = 5244 uS.
Time taken: analog read = 11396 uS.

The class is now a library which you can download from here:

http://www.gammon.com.au/Arduino/ProfileTimer.zip (4 Kb)

The example code can now be simplified to:

#include <ProfileTimer.h>

void setup ()
{
  Serial.begin (115200);
}  // end setup

void readSensors ()
  {
 ProfileTimer t ("readSensors");

  int a = analogRead (A0);
  int b = analogRead (A1);
  }
  
void loop ()
{
  delay (500);

  ProfileTimer t ("analog read");
  analogRead (A1);

  {
    ProfileTimer t1 ("multiple reads");
    for (int i = A0; i <= A5; i++)
      analogRead (i);
  }  // end timed bit of code

}  // end loop

Neat. Does some part of C++ guarantee that the object is constructed (and later destroyed) even if it's not otherwise used ?

westfw:
Neat. Does some part of C++ guarantee that the object is constructed (and later destroyed) even if it's not otherwise used ?

Yes, C++ scoping will call the destructor of any local objects when the closing bracket is reached, and it's constructed explicitly: the constructor is called here: timer t ("readSensors");

I got an idea from elsewhere in this forum. If you want to time a function, rather than retyping the function name you can use PRETTY_FUNCTION which returns the current function name and its arguments:

void readSensors ()
  {
  ProfileTimer t (__PRETTY_FUNCTION__);

  //  do something lengthy here
  
  }

Output looks like:

Start     : void readSensors()
Time taken: void readSensors() = 5440 uS.

So you can then make a define to let you time any function:

#define PROFILE_FUNCTION  ProfileTimer t (__PRETTY_FUNCTION__)

And use it like this:

void readSensors ()
  {
  PROFILE_FUNCTION;

  //  do something lengthy here
  
  }

Since it picks up the function name automatically, you just bang in PROFILE_FUNCTION wherever you want to time something.

This define is now in the ProfileTimer.h file.

Modified above posts and downloadable library to rename timer to Timer, to be consistent with other libraries.

Wouldn't it be better to note the start time after printing?

I didn't understand the question, sorry.

Or maybe ...

Did you mean change:

// constructor remembers time it was constructed
ProfileTimer (const char * s) : sReason (s)
  {
    start = micros ();
    Serial.print ("Start     : ");
    Serial.println (sReason);
  };

to:

// constructor remembers time it was constructed
ProfileTimer (const char * s) : sReason (s)
  {
    Serial.print ("Start     : ");
    Serial.println (sReason);
    start = micros ();
  };

?

In which case, yes I think you are very much right.

Amended original post, and downloadable library, to incorporate your suggestion.

I have another problem with the name of the class. The Arduino has a number of timers, and there are libraries for manipulating these timers, with Timer in the name.

Your class, while quite nice, is a bit confusing, with Timer as it's name. Perhaps the class should be called FunctionDuration or IntervalDuration, or even Duration, to make it clear that it is NOT a new class for manipulating one of the timers.

I suggest "ProfileTimer".

I suggest "ProfileTimer".

[ + ]

Wow, haven't been here for a long time. Start browsing for a clue to figure out how long a function takes and crash right into this.

Thanks, really useful!

Posts above, and downloadable file, amended to rename it to ProfileTimer. Added the define PROFILE_FUNCTION to the header file. This makes it simple to profile for debugging.

Thus in your code:

void readSensors ()
  {
  PROFILE_FUNCTION;    // shows when function called

  //  do something lengthy here
  
  }

However once debugged you just put this at the start of your main code:

#undef PROFILE_FUNCTION
#define PROFILE_FUNCTION

That turns the profiling into a no-op.

AWOL:
Wouldn't it be better to note the start time after printing?

It would also be better to calculate the elapsed time before starting to print what it is (the string part). So I amended it to calculate the difference first, and then start printing what it is.

That turns the profiling into a no-op.

Better than that, I would hope - no-ops consume processor cycles! :wink: