TBTK
Timer

Profiling

In a typical program most of the execution time is spent in a small fraction of the code. It is therefore a good coding practice to first focus on writing a functional program and to then profile it to find eventual bottlenecks. Optimization effort can then be spent on those parts of the code where it really matters. Doing so allows for a high level of abstraction to be maintained, which reduces development time and makes the code more readable and thereby less error prone. To help with profiling code, TBTK has a simple to use Timer class which can be used either as a timestamp stack or as an accumulators. It is also possible to mix the two modes, using the timestamp stack for some measurements while simultaneously using the accumulators for other.

Timestamp stack

To time a section, all that is required is to enclose it between a Timer::tick() and a Timer::tock() call

Timer::tick("A custom tag");
//Some code that is being timed.
//...
Timer::tock();

The tag string passed to Timer::tick() is optional, but is useful when multiple sections are timed since it will be printed together with the actual time when Timer::tock() is called.

When used as above, the Timer acts as a stack. When a call is made to Timer::tick(), a new timestamp and tag is pushed onto the stack, and the Timer::tock() call pops the latest call and prints the corresponding time and tag. It is therefore possible to nest Timer calls as follows

Timer::tick("Full loop");
for(unsigned int m = 0; m < 10; m++){
Timer::tock("Inner loop");
for(unsigned int n = 0; n < 100; n++){
//Do something
//...
}
Timer::tock();
}
Timer::tock();

This will result in the Timer timing the inner loop ten times, each time printing the execution time together with the tag 'Inner loop'. After the ten individual timing event have been completed, the Timer will also print the time it took for the full nested loop to execute together with the tag 'Full loop'.

Accumulators

Sometimes it is useful to measure the accumulated time taken by one or several pieces of code that are not necessarily executed without other code being executed in between. For example, consider the following loop

for(unsigned int n = 0; n < 1000000; n++){
task1();
task2();
}

This piece of code may have been identified as a bottleneck in the program, but it is not clear which of the two tasks that is responsible for it. Moreover, the time taken for each task may vary from call to call and therefore it is only useful to know the accumulated time taken for all 1,000,000 iterations. For cases like this the Timer provides the possibility to create accumulators as follows

unsigned int accumulatorID1 = Timer::createAccumulator("Task 1");
unsigned int accumulatorID2 = Timer::createAccumulator("Task 2");

The IDs returned by these functions can then be passed to the Timer::tick() and Timer::tock() calls to make it use these accumulators instead of the stack. For the loop above we can now write

for(unsigned int n = 0; n < 1000000; n++){
Timer::tick(accumulatorID1);
task1();
Timer::tock(accumulatorID1);
Timer::tick(accumulatorID2);
task2();
Timer::tock(accumulatorID2);
}

Since the accumulators are meant to accumulate time over multiple calls, there is no reason for Timer::tock() to print the time each time it is called. Instead the Timer has a special function for printing information about the accumulators, which will print the accumulated time and tags for all the currently created accumulators.

Timer::printAccumulators();