Multiple Performance Timer

• Download MultiTimer.h - 4.93 Kb
• Download demo project - 149 Kb

Introduction

This article contains one file MultiTimer.h which allows you to easily time parts of your code. It accumulates times on multiple calls and produces an output summary with all the totals and number of calls for each timer. There are many similar articles here and elsewhere, I thought it worthwhile to add this article though, as I think my timer class adds a few extra features and is very easy to use.

Example

void testfun()
{
    printf("Hello World!\n");
}

int main(int argc, char* argv[])
{
    for (int i = 0; i < 10; i++)
        testfun();

    return 0;
}

This isn't the best example of code to time, but it is a good example to show how the timing code is used. See the usage guidelines below for ideas on how to time your code.

Adding timing code

The following steps are needed to add timing code:

• Add #include "MultiTimer.h"
• Add timing macros to the code you want to time
• Call TIMER_DUMP or similar macros to display the results

After adding some test timing code, the above example looks like this:

#include "MultiTimer.h"


void testfun()
{
    TIME_LINE(printf("Hello World!\n");)
}

int main(int argc, char* argv[])
{
    {
    TIME_SCOPE("total test")
    for (int i = 0; i < 10; i++)
        TIME_FUN(testfun())
    }
    TIMER_DUMP("c:\\times.txt", SORT_CALLORDER)
    
    return 0;
}

This produces the following output file:

-----------------------------------------------------------------
Timings at 10:41:56 Friday, January 03, 2003
-----------------------------------------------------------------
total test took 606.80 micro secs (called 1 time)
testfun() took 591.42 micro secs (called 10 times)
printf("Hello World!\n"); took 561.52 micro secs (called 10 times)

The results are pretty straightforward. If you download the demo code, you will see further code which breaks down the times for the testfun() calls. Here is a sample output from this code:

Total: 668.20 micro secs
Minimum: 39.39 micro secs
Maximum: 302.55 micro secs
Average: 66.82 micro secs

-----------------------------------------------------------------
testfun() at 10:22:06 Friday, January 03, 2003
-----------------------------------------------------------------
Sample  1 = 302.55 micro secs
Sample  2 = 58.11 micro secs
Sample  3 = 55.87 micro secs
Sample  4 = 41.63 micro secs
Sample  5 = 42.46 micro secs
Sample  6 = 41.07 micro secs
Sample  7 = 42.46 micro secs
Sample  8 = 39.39 micro secs
Sample  9 = 50.29 micro secs
Sample 10 = 43.02 micro secs

You can see from this that the first printf takes a lot longer on Windows 2000, I guess some initialization is going on.

Macros

From the above example, you can see that this timing code is largely macro driven, here is a list of the macros used:-

TIMER_SETUP

This needs to be included in one of the .cpp files in a project, at a global scope. It sets up the storage for the timing code.

TIME_SCOPE(name)

Place this in your code to time from that point to the end of the current scope. name is a string, which is used in the output to identify these times.

TIME_FUN(fun())

Replace a function call, fun(), with this macro to time the call.

TIME_LINE(line)

Wrap any line with this macro to time it. Avoid declaring any variables in the line, as this macro puts the line in a separate scope.

TIMER_START(name) and TIMER_STOP(name)

These macros allow you to start and stop timers manually. See the demo for an example.

TIMER_DUMP(dest, sort)

Dump the current times. If dest is a file name, then the output is written to this file. Otherwise it can be:

• OUT_MSGBOX - Display output in a message box
• OUT_TRACE - Send the output to the trace window
• OUT_CONSOLE - Send the output to stdout

The output can be sorted in 3 ways:

• SORT_TIMES - The longest time is displayed first, down to the smallest
• SORT_CALLORDER - The times are displayed in the order the timers were called
• SORT_NAMES - The output is sorted alphabetically

TIMER_DUMP_FILE(dest, sort, mode)

This allows 3 extra mode values:

• FILE_NEW - Create a new file each time
• FILE_APPEND - Add each output to the end of the file
• FILE_PREPEND - Add each output to the start of the file

This is useful if you want to compare several test runs.

TIMER_DUMP_CSV(dest, sort, mode)

This is the same as TIMER_DUMP_FILE but the output is in comma separated format.

TIMER_DUMP_SAMPLES*(timer, ...)

The TIMER_DUMP_SAMPLES macros dump all the samples for a specified timer, this can be it's name or a CHiFreqTimer object. See the demo for an example.

There are 3 TIMER_DUMP_SAMPLES macros which correspond to the TIMER_DUMP macros, except there is no sort argument - the samples are dumped in ascending order.

GET_TIMER(name)

Return a CHiFreqTimer object for timer name. Further statistics can then be used, see the demo for an example.

T2S(time)

Converts a time returned from a CHiFreqTimer call to a meaningful string, see the demo for examples.

CLEAR_TIMERS

Removes all timers.

Disabling timing code

At the top of MultiTimer.h is a #define USE_TIMERS. Commenting this out will compile out any timing code you may have added.

Timing multiple files

You can put timing code in more than one file. Every file needs to include multitimer.h and all but the first must put the following line before the #include:

#define ANOTHER_TIMER_FILE

Clock ticks

It is sometimes useful to know how many clock ticks a piece of code took. I've added some macros which convert the time taken to clock cycles, first you must uncomment the #define _CLOCKTICKS line at the top of multitimer.h file. They are:-

T2C(time)

Converts a time to a string containing the number of clock cycles taken.

T2S_WITHCYCLES(time)

Converts a time to a string containing the time and the number of cycles.

CLOCK_SPEED

This is an int which represents your machine speed, e.g.. 733. This figure is accurate to 1 or 2 of your specific machine speed.

Usage guidelines

The idea of this type of code is to identify slow parts of your projects. If a part of your project is slow, it should help you to narrow down which bit of your code is causing the problem. You should avoid timing very quick statements - the timings are likely to be inaccurate. Also don't time all of your code, focus on areas that are slow and need to be sped up. It can also be helpful to know how many times a particular line or function is called, as this is often difficult to find out from the code alone.

Ideally release code should always be used to get accurate timings, the extra checking and lack of optimizations in debug code can cause misleading results. Other running processes can also affect times, for example virus scanners can skew file access times.

Accuracy and timing overheads

Any code added to time a file will itself take some time. This code tries to compensate for this but with very large number of timers and/or timing calls, a small loss of accuracy may result.

The QueryPerformanceCounter() call is used to time things. This is only supported on Pentiums. If you're running on an older machine, upgrading will probably speed things up...

Change History

• 6/11/02
  • General improvements to MultiTimer.h file
  • TIMER_DUMP_FILE macro added
• 7/11/02
  • Added TIMER_START + TIMER_STOP macros
  • Added USE_TIMERS #define
• 3/1/03
  • Sorted out TIMER_START and TIMER_STOP manual timers
  • Added TIMER_DUMP_CSV macro
  • Added TIMER_DUMP_SAMPLES, TIMER_DUMP_SAMPLES_FILE and TIMER_DUMP_SAMPLES_CSV macros
  • Added clock tick macros
  • Removed TIMER_SETUP macro