Pages: [1] 2   Go Down
Author Topic: Class to help debug how long code takes  (Read 1557 times)
0 Members and 1 Guest are viewing this topic.
Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

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:

Quote
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:

Code:
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:

Code:
... 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).

Code:
// 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:

Code:
Start     : analog read
Start     : multiple reads
Time taken: multiple reads = 5244 uS.
Time taken: analog read = 11396 uS.
« Last Edit: May 11, 2011, 04:14:32 pm by Nick Gammon » Logged


Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

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:

Code:
#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
« Last Edit: May 11, 2011, 04:15:11 pm by Nick Gammon » Logged


SF Bay Area (USA)
Offline Offline
Tesla Member
***
Karma: 133
Posts: 6753
Strongly opinionated, but not official!
View Profile
 Bigger Bigger  Smaller Smaller  Reset Reset

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

0
Offline Offline
Sr. Member
****
Karma: 0
Posts: 360
Arduino rocks
View Profile
 Bigger Bigger  Smaller Smaller  Reset Reset

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: 
Code:
timer t ("readSensors");
Logged

Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

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:

Code:
void readSensors ()
  {
  ProfileTimer t (__PRETTY_FUNCTION__);

  //  do something lengthy here
  
  }

Output looks like:

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

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

Code:
#define PROFILE_FUNCTION  ProfileTimer t (__PRETTY_FUNCTION__)

And use it like this:

Code:
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.
« Last Edit: May 11, 2011, 04:16:19 pm by Nick Gammon » Logged


Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

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


Global Moderator
UK
Offline Offline
Brattain Member
*****
Karma: 302
Posts: 26293
I don't think you connected the grounds, Dave.
View Profile
 Bigger Bigger  Smaller Smaller  Reset Reset

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

"Pete, it's a fool looks for logic in the chambers of the human heart." Ulysses Everett McGill.
Do not send technical questions via personal messaging - they will be ignored.

Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

I didn't understand the question, sorry.

Or maybe ...

Did you mean change:

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

to:

Code:
// 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.
« Last Edit: May 11, 2011, 04:16:52 pm by Nick Gammon » Logged


Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

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


Seattle, WA USA
Offline Offline
Brattain Member
*****
Karma: 614
Posts: 49343
Seattle, WA USA
View Profile
 Bigger Bigger  Smaller Smaller  Reset Reset

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.
Logged

Global Moderator
Dallas
Offline Offline
Shannon Member
*****
Karma: 207
Posts: 12912
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset


I suggest "ProfileTimer".
Logged

Global Moderator
UK
Offline Offline
Brattain Member
*****
Karma: 302
Posts: 26293
I don't think you connected the grounds, Dave.
View Profile
 Bigger Bigger  Smaller Smaller  Reset Reset

Quote
I suggest "ProfileTimer".
[ + ]
« Last Edit: May 11, 2011, 02:45:55 pm by AWOL » Logged

"Pete, it's a fool looks for logic in the chambers of the human heart." Ulysses Everett McGill.
Do not send technical questions via personal messaging - they will be ignored.

0
Offline Offline
Full Member
***
Karma: 0
Posts: 183
View Profile
 Bigger Bigger  Smaller Smaller  Reset Reset

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!
Logged

Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

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:

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:

Code:
#undef PROFILE_FUNCTION
#define PROFILE_FUNCTION

That turns the profiling into a no-op.
Logged


Global Moderator
Online Online
Brattain Member
*****
Karma: 485
Posts: 18784
Lua rocks!
View Profile
WWW
 Bigger Bigger  Smaller Smaller  Reset Reset

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.
Logged


Pages: [1] 2   Go Up
Jump to: