Timing

MACSio’s timing package includes utilities to support the creation of a number of timers to time sections of code.

Timers are initialized/started with a user-defined label, and an optional group mask and iteration number. A hash of the timer is computed from its label and group mask combined with the source file name and line number. The resulting hash value is used to identify the timer and returned as the timer’s id when the timer is created/started.

Timers can be iterated and re-started. These are two different concepts. During iteration, the same timer can be used to time the same section of code as it gets executed multiple times. Each time represents a different iteration of the timer. The timer will keep track of the minimum time, maximum time, average time and variance of times over all iterations it is invoked. However, apart from these running statistics, a timer maintains no memory of past values. If a timer is iterated 10 times, it does not maintain knowledge of all 10 individual times. It maintains only knowledge of the running statistics; min, max, avg, var. The algorithm it uses to maintain these running statistics is the Welford Online algorithm.

Within any timer iteration, a timer can be stopped and restarted. If a timer is being used to time a block of code that involves some occasional and perhaps irrlevant alternative logic path, the timer can be stopped until execution returns from the alternative path. Then the timer can be restarted. This can only be done within a given iteration.

Timers can also be grouped into a small number (<64) of different groups. A timer group is created with a call to MACSIO_TIMING_GroupMask(). Timers are included in one or more groups by or’ing the associated group masks into the gmask argument to MACSIO_TIMING_StartTimer(). A timer can be a member of multiple groups For example, it is possible to maintain a set of timers for MIF file I/O apart from a set of timers being used to time a particular plugin’s operations to marshal a mesh or variable to/from persistent storage. Or, operations use to interact with filesystem metadata directly (e.g. mkdir, chdir, readir, etc.) can be maintained separately from timers used for entirely other purposes.

Finally, timers can be reduced parallel tasks thereby creating a statistical summary of timer information across tasks.

A timer is initialized/started by a call to MACSIO_TIMING_StartTimer() or the shorthand macro MT_StartTimer. This call returns the timer’s ID which is used in a subsequent call to MACSIO_TIMING_StopTimer() to stop the timer.

MACSIO_TIMING_TimerId_t tid = MT_StartTimer("my timer", MACSIO_TIMING_GROUP_NONE, MACSIO_TIMING_ITER_AUTO);

...do some work here...

MT_StopTimer(tid);

In the above code, the call to MT_StartTimer starts a timer for a new (automatic) iteration. In this simple examle, we do not worry about timer group masks.

By default, the timing package uses MPI_Wtime() but a caller can set MACSIO_TIMING_UseMPI_Wtime to zero to instead use gettimeofday().

Examples of the use of the logging package can be found in Example (tsttiming.c).

Timing API

group MACSIO_TIMING

Timing utilities.

Defines

MACSIO_TIMING_ITER_AUTO

Automatic iteration numbering Use for iter arg to MT_StartTimer() for automatic iteration numbering of the timer explicitly.

MACSIO_TIMING_ITER_IGNORE

What is this?

MACSIO_TIMING_INVALID_TIMER

May be returned from MT_StartTimer()

MACSIO_TIMING_NO_GROUP

Group mask when timer is not assigned to any group.

MACSIO_TIMING_ALL_GROUPS

Group mask representing all groups.

MT_Time

Shorthand for MACSIO_TIMING_GetCurrentTime()

__BASEFILE__

Same as basename(FILE) Used to strip unnecessary path terms from in messages.

MT_StartTimer(LAB, GMASK, ITER)

Shorthand for MACSIO_TIMING_StartTimer()

Parameters

  • [in] LAB: User defined timer label string

  • [in] GMASK: User defined group mask. Use MACSIO_TIMING_NO_GROUP if timer grouping is not needed.

  • [in] ITER: The iteration number. Use MACSIO_TIMING_ITER_IGNORE if timer iteration is not needed.

MT_StopTimer(ID)

Shorthand for MACSIO_TIMING_StopTimer()

Parameters

Typedefs

typedef unsigned int MACSIO_TIMING_TimerId_t
typedef unsigned long long MACSIO_TIMING_GroupMask_t

Functions

MACSIO_TIMING_GroupMask_t MACSIO_TIMING_GroupMask(char const *grpName)

Create a group name and mask.

Parameters

  • grpName: Name of the group for which group mask is needed

A small number of groups (less than 64) can be defined into which timers can be grouped Timers can be assigned to multiple groups by or’ing the resulting group masks.

MACSIO_TIMING_TimerId_t MACSIO_TIMING_StartTimer(char const *label, MACSIO_TIMING_GroupMask_t gmask, int iter_num, char const *file, int line)

Create/Start a timer.

Parameters

  • label: User defined label to be assigned to the timer

  • gmask: Mask to indicate the timer’s group membership

  • iter_num: Iteration number

  • file: The source file name

  • line: The source file line number

This call either creates a new timer and starts it or starts a new iteration of an existing timer.

Return

A hash derived from a string catenation the label, gmask, file and line.

double MACSIO_TIMING_StopTimer(MACSIO_TIMING_TimerId_t id)

Stop a timer.

Parameters

This call stops a currently running timer.

Return

Returns the time for the current iteration of the timer

double MACSIO_TIMING_GetTimerDatum(MACSIO_TIMING_TimerId_t tid, char const *field)

Get specific data field from a timer.

Parameters

Possible field names are…

  • “start_time” time last iteration was started

  • ”iter_count” number of times the timer has been triggered (iterated)

  • ”iter_time” total time over all iterations

  • ”min_iter” iteration at which minimum time was observed

  • ”max_iter” iteration at which maximum time was observed

  • ”min_rank” task rank where minimum time occurred (only valid on reduced timers)

  • ”max_rank” task rank where maximum time occurred (only valid on reduced timers)

  • ”depth” how deeply this timer is nested within other timers

  • ”total_time” total time spent in this timer

  • ”min_time” minimum time observed for this timer

  • ”max_time” maximum time observed for this timer

  • ”running_mean” current average time for this timer

  • ”running_var” current variance for this timer

Where applicable, returned values are over either

  • all iterations (when using non-reduced timers) or

  • all iterations and ranks (when using reduced timers).

double MACSIO_TIMING_GetReducedTimerDatum(MACSIO_TIMING_TimerId_t tid, char const *field)

Get data field a specific reduced timer.

Parameters

For field names, see MACSIO_TIMING_GetTimerDatum()

void MACSIO_TIMING_DumpTimersToStrings(MACSIO_TIMING_GroupMask_t gmask, char ***strs, int *nstrs, int *maxlen)

Dump timers to ascii strings.

Parameters

  • gmask: Group mask to filter only timers belonging to specific groups

  • strs: Array of strings, one for each timer, returned to caller. Caller must free.

  • nstrs: Number of strings returned to caller

  • maxlen: The maximum length of all strings

This call will find all used timers in the hash table matching the specified gmask group mask and dumps each timer to a string. For convenience, the maximum length of the strings is also returned. This is to facilitate dumping the strings to a MACSIO_LOG. Pass MACSIO_TIMING_ALL_GROUPS if you don’t care about timer groups.

Each timer is dumped to a string with the following informational fields catenated together and separated by colons…

  • TOT=%10.5f summed total time spent in this timer over all iterations (and over all ranks when reduced)

  • CNT=%04d summed total total number of iterations in this timer (and over all ranks when reduced)

  • MIN=%8.5f(%4.2f):%06d

    • minimum time recorded for this timer over all iterations (and ranks when reduced)

    • (%4.2f) the number of standard deviations of the min from the mean time

    • :%06d task rank where the minimum was observed (only valid when reduced)

  • AVG=%8.5f the mean time of this timer over all iterations (and ranks when reduced)

  • MAX=%8.5f(%4.2f):%06d,

    • maximum time recorded for this timer over all iterations (and ranks when reduced)

    • (%4.2f) the number of standard deviations of the max from the mean time

    • :%06d task rank where the maximum was observed. (only valid when reduced)

  • DEV=%8.8f standard deviation observed for all iterations of this timer

  • FILE=%s the source file where this timer is triggered

  • LINE=%d the source line number where this timer is triggered

  • LAB=%s the user-defined label for this timer

void MACSIO_TIMING_ReduceTimers(MPI_Comm comm, int root)

Reduce timers across MPI tasks.

Parameters

  • comm: The MPI communicator to use for the reduction

  • root: The MPI rank of the root task to be used for the reduction

Computes a parallel reduction across MPI tasks of all timers.

void MACSIO_TIMING_DumpReducedTimersToStrings(MACSIO_TIMING_GroupMask_t gmask, char ***strs, int *nstrs, int *maxlen)

Dump reduced timers to ascii strings.

Parameters

  • gmask: Group mask to filter only timers belonging to specific groups

  • strs: Array of strings, one for each timer, returned to caller. Caller must free

  • nstrs: Number of strings returned to caller

  • maxlen: The maximum length of all strings

Similar to DumpTimersToStrings except this call dumps reduced timers

void MACSIO_TIMING_ClearTimers(MACSIO_TIMING_GroupMask_t gmask)

Clear a group of timers.

Parameters

  • gmask: Group mask to filter only timers belonging to specific groups

Clears and resets timers of specified group. Pass MACSIO_TIMING_ALL_GROUPS to clear all timers.

double MACSIO_TIMING_GetCurrentTime(void)

Get current time.

Depending on current value of MACSIO_TIMING_UseMPI_Wtime, uses either MPI_WTime() or gettimeofday().

Variables

int MACSIO_TIMING_UseMPI_Wtime

Integer variable to control function used to get timer values.

A non-zero value indicates that MACSIO_TIMING should use MPI_Wtime(). Otherwise, it will use gettimeofday().

Example (tsttiming.c)

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156

#include <math.h>
#include <stdlib.h>
#include <time.h>
#include <unistd.h>

#ifdef HAVE_MPI
#include <mpi.h>
#endif

#include <macsio_log.h>
#include <macsio_timing.h>

int MACSIO_MAIN_Rank;
int MACSIO_MAIN_Size;
int MACSIO_MAIN_Comm;

static void dsleep(double delay)
{
    double dsec = floor(delay);
    long nsec = (long) ((delay - dsec) * 1e+9);
    time_t sec = (time_t) dsec;
    struct timespec ts = {sec, nsec};
    nanosleep(&ts, 0);
}

void func2();

void func4()
{
    static int iter = 0;
    double delay = (random() % 1000) / (double) 10000; /* random up to 1/10th second of sleep */
    MACSIO_TIMING_TimerId_t tid = MT_StartTimer("func4", MACSIO_TIMING_ALL_GROUPS, iter++);
    dsleep(delay);
    MT_StopTimer(tid);
}

void func3()
{
    static int iter = 0;
    MACSIO_TIMING_TimerId_t tid = MT_StartTimer("func3", MACSIO_TIMING_ALL_GROUPS, iter++);
    func4();
    func2();
    MT_StopTimer(tid);
}

void func2()
{
    static int iter = 0;
    MACSIO_TIMING_TimerId_t tid = MT_StartTimer("func2", MACSIO_TIMING_ALL_GROUPS, iter++);
    dsleep(0.02);
    MT_StopTimer(tid);
}

void func1()
{
    static int iter = 0;
    MACSIO_TIMING_TimerId_t tid = MT_StartTimer("func1", MACSIO_TIMING_ALL_GROUPS, iter);
    MACSIO_TIMING_TimerId_t tid2;

    func2();
    dsleep(0.01);
    tid2 = MT_StartTimer("call to func3 from func1", MACSIO_TIMING_ALL_GROUPS, iter++);
    func3();
    MT_StopTimer(tid2);
    func2();

    MT_StopTimer(tid);
}

int main(int argc, char **argv)
{
    int i, rank = 0, size = 1;
    MACSIO_TIMING_TimerId_t a, b;
    char **timer_strs;
    int ntimer_strs, maxstrlen;

#ifdef HAVE_MPI
    MPI_Init(&argc, &argv);
    MPI_Comm_size(MPI_COMM_WORLD, &size);
    MPI_Comm_rank(MPI_COMM_WORLD, &rank);
#endif

    MACSIO_LOG_DebugLevel = 1; /* should only see debug messages level 1 and 2 */
    srandom(0xDeadBeef); /* used to vary length of some timers */

    if (size > 8)
    {
        if (!rank)
            fprintf(stderr, "This test only appropriate for 8 or fewer processors\n");
#ifdef HAVE_MPI
        MPI_Abort(MPI_COMM_WORLD, 1);
#endif
        exit(1);
    }

    a = MT_StartTimer("main", MACSIO_TIMING_ALL_GROUPS, 0);

    func1();

    if (rank > 2)
        func4();

    b = MT_StartTimer("call to func3 from main", MACSIO_TIMING_ALL_GROUPS, 0);
    func3();
    MT_StopTimer(b);

    if (rank < 2)
        func1();

    MT_StopTimer(a);

    MACSIO_TIMING_DumpTimersToStrings(MACSIO_TIMING_ALL_GROUPS, &timer_strs, &ntimer_strs, &maxstrlen);

#ifdef HAVE_MPI
    {
        int rbuf[2], sbuf[2] = {ntimer_strs, maxstrlen};
        MPI_Allreduce(sbuf, rbuf, 2, MPI_INT, MPI_MAX, MPI_COMM_WORLD);
        MACSIO_LOG_MainLog = MACSIO_LOG_LogInit(MPI_COMM_WORLD, "tsttiming.log", rbuf[1]+32, 2*rbuf[0]+4,0);
    }
#else
    MACSIO_LOG_MainLog = MACSIO_LOG_LogInit(0, "tsttiming.log", maxstrlen+4, ntimer_strs+4, 0);
#endif

    for (i = 0; i < ntimer_strs; i++)
    {
        MACSIO_LOG_MSG(Dbg1, (timer_strs[i]));
        free(timer_strs[i]);
    }
    free(timer_strs);

#ifdef HAVE_MPI
    MACSIO_TIMING_ReduceTimers(MPI_COMM_WORLD, 0);
    if (!rank)
    {
        MACSIO_TIMING_DumpReducedTimersToStrings(MACSIO_TIMING_ALL_GROUPS, &timer_strs, &ntimer_strs, &maxstrlen);
        MACSIO_LOG_MSG(Dbg1, ("#####################Reduced Timer Values######################"));
        for (i = 0; i < ntimer_strs; i++)
        {
            MACSIO_LOG_MSG(Dbg1, (timer_strs[i]));
            free(timer_strs[i]);
        }
        free(timer_strs);
    }
#endif

    MACSIO_LOG_LogFinalize(MACSIO_LOG_MainLog);

    MACSIO_TIMING_ClearTimers(MACSIO_TIMING_ALL_GROUPS);

#ifdef HAVE_MPI
    MPI_Finalize();
#endif

    return 0;
}