Related Info: Time Manager

A High-Resolution Timer

A simple package for measuring small intervals of time for performance analysis

By Martin Minow, Arlington, Massachusetts

Introduction

Volume 6 of Inside Macintosh - which is to say late System 6.0 and System 7 - describes the extended TimeManager and a drift-free timer function that lets an application measure durations with a finer resolution than the 1/60 second system tick count.

In order to simplify measuring small intervals for performance analysis, I wrote a simple package that allows recording the “time of day” at its highest resolution. Using this as a base, you can record the start and end of an event of interest (such as a subroutine call) and, by using one of the subroutines in the package, determine the elapsed time.

For my particular purposes, elapsed times are recorded in integers with microsecond resolution, giving a maximum interval of just over 35 minutes, since 231 is greater than (35 * 60 * 1000000). If you need to record longer intervals, you need only redo the DeltaTime subroutine (as shown in the demo application) so it returns a floating-point (double-precision) value.

The demo program shows some of the calls and lets you get an idea of the amount of time needed to setup and call the timer service. On my Macintosh IIci with the THINK C debugger enabled, the average time is about 160µsec, which is not shabby at all. Of course, you should not assume that microsecond resolution means microsecond accuracy.

InitializeMicrosecondTimer will return an error if the drift-free timer is not supported on your system. Because of the way it calls Gestalt, you must compile it on a modern system (THINK C 5.0) as the “glue” that calls Gestalt now includes code to check for the Gestalt trap presence.

In order to ensure that the timer routine’s periodic task is removed when your application exits, InitializeMicrosecondTimer patches the ExitToShell trap for the removal function. Because of the way THINK C installs its own ExitToShell trap, be sure to call InitializeMicrosecondTimer before calling any THINK C routines from the standard I/O or THINK Class libraries.

Acknowledgments

This is a revision of a program I first wrote for the IBM 7090 in 1964. OK, maybe it was 1965. Some of the Macintosh specific code can be traced to a timing routine in the MacDTS “FracApp” demonstration program by Keith Rollin and Bo3b Johnson, while the exit handler is based on code in the atexit function in the THINK C library.

Listing:  MicrosecondTimer.h

/* MicrosecondTimer.h*/
/*
 * Time measurement.
 * Copyright © 1991 Martin Minow.  All Rights Reserved
 *
/*
 * Definitions for the Millisecond timer
 */
#ifndef _H_MsecTimer
#define _H_MsecTimer

#define MSEC_PER_TICK1

typedef struct MicrosecondEpoch {
 unsigned long time; /* Time of day*/
 signed longmicrosecond;  /* Residual*/
} MicrosecondEpoch, *MicrosecondEpochPtr;

/*
 * Initialize the clock - call once when your
 * application starts.
 */
OSErr   InitializeMicrosecondTimer(void);
/*
 * Cancel the clock - this is called automatically
 * when your application exits.
 */
void    CancelMicrosecondTimer(void);
/*
 * Return the current extended time value.
 */
void    GetEpoch(MicrosecondEpochPtr result);
/*
 * Compute the difference between two epoch’s. The
 * result is in deltaTime (in microseconds).
 * deltaTime is positive if epoch2 is later than epoch1.
 *
 * Returns TRUE if the time can be represented in
 * microseconds (less than 35 minutes difference). 
 * If it returns FALSE, deltaTime is likely to be garbage.
 */
Boolean DeltaTime(
 MicrosecondEpochPtr epoch1,
 MicrosecondEpochPtr epoch2,
 signed long*deltaTime
 );
/*
 * Compute the difference between two epoch’s. The
 * result is returned as a floating-point number
 * of seconds.
 */
double  DoubleDelta(
 MicrosecondEpoch*start,
 MicrosecondEpoch*finish
 );

/*
 * Format an epoch value as “hh:mm:ss.fraction”
 */
void EpochToString(
 MicrosecondEpochPtr epochPtr,
 StringPtrresult
 );
/*
 * Use an extended time value to adjust the
 * local clock.  Unfortunately, we can only adjust
 * the clock by an integral number of seconds.
 */
void AdjustClock(
 signed longadjustment
 );
#endif

Listing:  MicrosecondTimer.c

/* MicrosecondTimer.c*/
/*
 * Time measurement.
 * Copyright © 1991 Martin Minow.  All Rights Reserved
 *
 * This function creates a high-resolution “time of day”
 * timer that is (or, at least, ought to be) synchronized
 * with the system time of day value.  It uses the
 * new time manager calls.
 *
 * In order to keep our timer in reasonable synchronization
 * with the system time of day, we shadow that value at
 * each time-of-day trap.
 * 
 * Usage:
 * InitializeMicrosecondTimer(void);
 * Call this - once - when your program starts. It
 * installs the timer interrupt routine. It returns
 * noErr if successful, or unimpErr if the Extended
 * Time Manager is not supported on this system.
 *
 * Important: if you are using the THINK C ANSI,
 * console, or class libraries, be sure to call
 * InitializeMicrosecondTimer before calling any
 * THINK C routines.  Otherwise, your program
 * may crash on exit under certain ill-defined
 * circumstances.
 *
 * CancelMicrosecondTimer(void)
 * This must be called before your application exits.
 * InitializeMSecTimer() establishes an exit handeler
 * to force its call, so you needn’t worry about it.
 *
 * GetEpoch(
 * MicrosecondEpoch *result
 * )
 * Call this to get the time of day. The result
 * consists of a time (seconds) value that is
 * intended to track GetTimeOfDay exactly, extended
 * by the number of microseconds past this second.
 *
 * DeltaTime(
 * MicrosecondEpoch*startTime,
 * MicrosecondEpoch*endTime
 * signed long   *difference
 * )
 * Compute the difference between two extended
 * time values, returning the result in the third
 * parameter (as a signed number of microseconds).
 * The result will be positive if time2 is later
 * than time1. DeltaTime returns TRUE if the
 * absolute value of the difference (in seconds)
 * is less than 35 minutes (a signed longword can
 * resolve a 34 minute interval). (You might want
 * to redo this to return a double-precision format
 * value, rather than a longword.)
 *
 * DoubleDelta(
 * MicrosecondEpoch*start,
 * MicrosecondEpoch*finish
 * )
 * Compute the difference between two extended
 * time values, returning the result as a double-
 * precision number of seconds.
 * 
 * EpochToString(
 * MicrosecondEpoch*epoch
 * Str255 result
 * )
 * Convert an extended time value to a fixed-width,
 * fixed-format Pascal string “hh:mm:ss.fraction”.
 *
 * Although the code has not been tested under MPW, it
 * ought to port easily: just re-do the asm stuff.
 *
 * Acknowledgements:
 * Parts of the time manager calls are based on a
 * timing module in the MacDTS FracApp demo program
 * by Keith Rollin an Bo3b Johnson.
 *
 * The exit handler is based on similar code in the
 * atexit() function in the THINK C support library.
 */

#include <GestaltEqu.h>
#ifndef THINK_C
#include <SysEqu.h>
#endif
#include <Timer.h>
#include <Traps.h>
#include “MicrosecondTimer.h”

/*
 * This is needed to establish an exit trap handler.
 */
typedef void(*MyProcPtr)(void);
typedef struct {
 short  jmp;
 MyProcPtrfunction;
} JumpVector;

static void *oldExitVector;
static JumpVector*jumpVector;
static void TimerExitHandler(void);

#define MILLION  (1000000L)

/*
 * This is a time manager record, extended to include a
 * shadow copy of the system time of day value that is
 * updated once a second.
 */
typedef struct TimeInfoRecord {
 TMTask TMTask;  /* The task record*/
 unsigned long epoch;/* Time of day info     */
} TimeInfoRecord, *TimeInfoPtr;

static TimeInfoRecordgTimeInfo;
#define TIME(gTimeInfo.TMTask)
static long gOverheadTime;
static pascal void TimeCounter(void);

static void Concat(StringPtr dst, StringPtr src);

/*
 * Install a timer interrupt procedure.
 */
OSErr
InitializeMicrosecondTimer()
{
 long   timeOfDay;
 long   gestaltResult;
 OSErr  status;
 
 if (TIME.tmAddr != NULL)
 status = noErr; /* Already installed*/
 else {
 status = Gestalt(
 gestaltTimeMgrVersion,
 &gestaltResult
 );
 if (status == noErr
  && gestaltResult < gestaltExtendedTimeMgr)
 status = unimpErr;
 if (status == noErr) {
 /*
  * Install a trap handler for ExitToShell
  */
 oldExitVector =
 (void *) GetTrapAddress(_ExitToShell);
 if (ROM85 >= 0) {
 SetTrapAddress(
 (long) TimerExitHandler,
 _ExitToShell
 );
 }
 else {
 /*
  * Install a trap handler
  * in the system heap.
  */
 jumpVector = (JumpVector *)
 NewPtrSys(sizeof (JumpVector));
 if (jumpVector == NULL) {
 status = memFullErr;
 goto exit;
 }
 else {
 jumpVector->jmp = 0x4EF9;
 jumpVector->function =
 TimerExitHandler;
 SetTrapAddress(
 (long) jumpVector,
 _ExitToShell
 );
 }

 }
 /*
  * Install the time manager task and
  * start it rolling.
  */
 TIME.tmAddr = (ProcPtr) TimeCounter;
 InsXTime(&TIME);
 /*
  * Align our timer to the system’s
  */
 timeOfDay = Time;
 do {
 gTimeInfo.epoch = Time;
 } while (timeOfDay == gTimeInfo.epoch);
 /*
  * We should really do this a bunch
  * of times and take the minimum.
  * gOverheadTime measures the amount
  * of time the PrimeTime/RmvTime sequence
  * requires, See the discussion in IM-VI.
  */
 PrimeTime(&TIME, -MILLION);
 RmvTime(&TIME);
 gOverheadTime = MILLION + TIME.tmCount;
 /*
  * Restart the timer
  */
 InsXTime(&TIME);
 PrimeTime(&TIME, 0);
 }
 }
exit: return (status);
}

/*
 * GetEpoch returns the current extended time of day.
 * It requires the drift-free time manager. See the
 * Time Manager discussion in Inside Mac VI for details
 * of the procedure.
 */
void
GetEpoch(
 MicrosecondEpochPtr result
 )
{
 RmvTime(&TIME); /* Stop Clock*/
 result->time = gTimeInfo.epoch; /* Get seconds    */
 /*
  * TIME.tmCount contains the residual number of
  * microseconds. This is a negative number (see
  * IM-VI). The following, then, computes the
  * number of microseconds that have elapsed in
  * the current second.
  */
 result->microsecond = 
 (MILLION + TIME.tmCount) /* Offset “now”    */
 - gOverheadTime;/* - call cost  */
 if (result->microsecond < 0) {  /* New second?    */
 result->time -= 1;/* Correct it.  */
 result->microsecond += MILLION;
 }
 InsXTime(&TIME);/* Drift-free*/
 PrimeTime(&TIME, 0);/* Timer start*/
}

/*
 * Return the difference between two (nearby) epochs.
 * The result is in microseconds and has a range of
 * up to about 35 minutes.
 *
 * DeltaTime returns TRUE if deltaTime is valid.
 */
Boolean
DeltaTime(
 MicrosecondEpochPtr epoch1,
 MicrosecondEpochPtr epoch2,
 signed long*deltaTime
 )
{
 long   seconds;
 long   microseconds;
 
 seconds = epoch2->time - epoch1->time;
 microseconds =
 epoch2->microsecond - epoch1->microsecond;
 *deltaTime = (seconds * MILLION) + microseconds;
 /*
  * The result is valid only if the
  * absolute value of the difference is
  * less than about 35 minutes.  I.e.
  *2^31 <= (35 * 60 * 10^6)
  */
 if (seconds < 0)
 seconds = (-seconds);
 return (seconds <= (34 * 60));
}

/*
 * Return the time difference as a double-precision
 * number of seconds.
 */
double
DoubleDelta(
 MicrosecondEpoch*start,
 MicrosecondEpoch*finish
 )
{
 double seconds;
 double microseconds;
 double result;
 
 seconds = finish->time - start->time;
 microseconds =
 finish->microsecond - start->microsecond;
 result = seconds
    + (microseconds / (double) MILLION);
 return (result);
}


/*
 * This local function formats hour:minute:second.
 */
static void
FormatTimeString(
 StringPtrresult,
 long   what,
 BooleanneedColon
 )
{
 Str255 value;
 
 if (needColon)
 result[++result[0]] = ‘:’;
 NumToString(what, value);
 if (value[0] == 1)
 result[++result[0]] = ‘0’;
 Concat(result, value);
}

/*
 * Convert the time of day to a consistent, fixed-width
 * format of hh:mm:ss.microseconds. This is always in
 * 24 hour format.
 */
void
EpochToString(
 MicrosecondEpochPtr epochPtr,
 StringPtrresult
 )
{
 unsigned int    i;
 DateTimeRecnow;
 Str255 value;

 Secs2Date(epochPtr->time, &now);
 result[0] = 0;
 FormatTimeString(result, now.hour,   FALSE);
 FormatTimeString(result, now.minute, TRUE);
 FormatTimeString(result, now.second, TRUE);
 NumToString(
 epochPtr->microsecond + MILLION,
 value
 );
 value[1] = ‘.’;
 Concat(result, value);
}

/*
 * String concatenator for Pascal strings.
 */
static void
Concat(
 StringPtrdst,
 StringPtrsrc
 )
{
 short  copySize;
 
 copySize = src[0];
 if ((copySize + dst[0]) > 255)
 copySize = 255 - dst[0];
 BlockMove(
 &src[1],
 &dst[dst[0] + 1],
 (long) copySize
 );
 dst[0] += copySize;
}

/*
 * Adjust the clock by adding the adjustment to the
 * current clock.  There is a built-in delay to
 * make sure our timer task gets to do its thing.
 *
 * Note: the right way to do this is to change the system
 * clock tick base from 1000000 and continually adjust
 * the clock a bit every second until it’s right.
 * Unfortunately, we don’t have access to the system
 * clock time manager record.
 */
void
AdjustClock(
 long   adjustment
 )
{
 MicrosecondEpochourEpoch;
 long   timeOfDay;

 GetEpoch(&ourEpoch);
 ourEpoch.time += (adjustment / MILLION);
 adjustment %= MILLION;
 if (ourEpoch.microsecond >= (MILLION / 2))
 ourEpoch.time += 1;
 else if (ourEpoch.microsecond <= (-(MILLION / 2)))
 ourEpoch.time -= 1;
 SetDateTime(ourEpoch.time);
 /*
  * Vamp until our shadow clock has a chance to
  * update the local value.
  */
 GetEpoch(&ourEpoch);
 timeOfDay = ourEpoch.time;
 do {
 GetEpoch(&ourEpoch);
 } while (timeOfDay == ourEpoch.time);
}

/*
 * This will be called automatically by the
 * ExitToShell trap.
 */
void
CancelMicrosecondTimer()
{

#if 0 /* Enable this to put a debug trap here                  */
 asm {
 nop
 }
#endif
 if (TIME.tmAddr != NULL) {
 RmvTime(&TIME);
 TIME.tmAddr = NULL;
 }
 if (oldExitVector != NULL) {
 SetTrapAddress(
 (long) oldExitVector,
 _ExitToShell
 );
 oldExitVector = NULL;
 if (jumpVector != NULL) {
 DisposPtr(jumpVector);
 jumpVector = NULL;
 }
 }
}

/*
 * This is called by the ExitToShell trap.
 * It cancels the timer service and removes
 * itself from the trap process, then re-calls
 * ExitToShell to allow other trap handlers to
 * execute.
 */
static void
TimerExitHandler()
{
 long   oldA5 = SetCurrentA5();

 CancelMicrosecondTimer();
 SetA5(oldA5);
 ExitToShell();  /* Call next exit handler   */
}

/*
 * This private routine is called by the TimeManager at
 * every clock tick. There is blood on every line of this
 * function - and on a number of lines of code that aren’t
 * here any more. This function will need to be rewritten
 * for MPW-C, as that compiler lacks an asm statement.
 */
static pascal void
TimeCounter()
{
 asm {
 /*
  * When we are called, A1 -> the time info
  * record which we have extended with our
  * “time of day” shadow. Update it with the
  * current system time-of-day value (so that
  * we remain coordinated with any changes
  * caused by SetDateTime or Control Panel
  * calls). This may mean that we are up to
  * one second out of step from the system, but
  * this probably can’t be helped.  TimeLM is
  * the system global “time of day” variable.
  * This variable has a different name in MPW-C.
  */
 move.l TimeLM,  \
 OFFSET(TimeInfoRecord,epoch)(a1)
 move.l a1,a0    ;; a0 = TmTaskPtr 
 move.l #-MILLION,d0 ;; d0 = count
 dc.w 0xA05A;; _PrimeTime
 }
}

Listing:  MicrosecondTimerDemo.c

/* MicrosecondTimerDemo.c */
/*
 * This is a totally useless demo program that scribbles
 * the time of day as quickly as it can, then it tries
 * to determine the cost of calling the time routines.
 * Click on the mouse whenever you get bored.
 */
#include <stdio.h>
#include <console.h>
#include <limits.h>
#include <math.h>
#include “MicrosecondTimer.h”
#define MILLION  (1000000L)
#define HIST_MAX 100
#define HIST_SIZE(100L) /* 100 microseconds per bin      */
double  histogram[HIST_MAX];
double  overflow;

main(
 int    argc,
 char   **argv
 )
{
 MicrosecondEpochthen;
 MicrosecondEpochnow;
 MicrosecondEpochstart;
 MicrosecondEpochfinish;
 long   elapsed;
 long   smallest;
 long   biggest;
 double trials;
 double sum, sumSq;
 double mean, variance, sd;
 double seconds;
 double trialTime;
 register short  i,top;
 Str255 message;

 /*
  * Be sure to initialize the timer before calling
  * any THINK C stdio or THINK Class Library
  * routines.
  */
 InitializeMicrosecondTimer();
 argc = ccommand(&argv);
 printf(“Hit the mouse to stop\n”);
 GetEpoch(&then);
 while (Button() == FALSE) {
 SystemTask();
 GetEpoch(&now);
 EpochToString(&now, message);
 DeltaTime(&then, &now, &elapsed);
 printf(
 “%#s - %ld.%06ld\n”,
 message,
 elapsed / MILLION,
 elapsed % MILLION
 );
 then = now;
 }
 while (Button())
 ;
 printf(“Beginning timer resolution test.\n”);
 printf(“Hit the mouse to stop\n”);
 smallest = LONG_MAX;
 biggest = 0;
 trials = 0;
 sum = sumSq = 0;
 i = 0;
 GetEpoch(&start);
 while (Button() == FALSE) {
 if ((++i % 1000) == 0)
 SystemTask();
 GetEpoch(&then);
 GetEpoch(&now);
 DeltaTime(&then, &now, &elapsed);
 if (elapsed < smallest)
 smallest = elapsed;
 if (elapsed > biggest)
 biggest = elapsed;
 sum += elapsed;
 sumSq += (elapsed * elapsed);
 trials++;
 i = elapsed / HIST_SIZE;
 if (i >= HIST_MAX)
 ++overflow;
 else {
 ++histogram[i];
 }
 }
 while (Button())
 ;
 GetEpoch(&finish);
 top = HIST_MAX;
 if (overflow == 0) {
 while (top > 0 && histogram[top - 1] == 0)
 top -= 1;
 }
 printf(“Each histogram bucket contains %ld µsec.\n”,
 HIST_SIZE);
 for (i = 0; i < top; i++) {
 printf(“%5ld: %.0f\n”,
 i * HIST_SIZE, histogram[i]);
 }
 if (overflow > 0)
 printf(“%.0f overflow\n”);
 printf(“Timer minimum = %ld.%06ld,”,
 smallest / MILLION,
 smallest % MILLION
 );
 printf(“ maximum = %ld.%06ld\n”,
 biggest / MILLION,
 biggest % MILLION
 );
 printf(“%.0f trials”, trials);
 if (trials > 0) {
 mean = sum / trials;
 printf(“: mean %.2f µsec.”, mean);
 if (trials > 1.0)  {
 /*
  * No, this is not the proper way to
  * calculate the variance.
  */
 variance = (sumSq * trials) - (sum * sum);
 variance /= (trials * trials);
 sd = sqrt(variance);/* Std. deviation */
 printf(“, variance %0.2f,”, variance);
 printf(“ standard deviation %0.2f”, sd);
 }
 }
 printf(“\n”);
 seconds = DoubleDelta(&start, &finish);
 printf(“%0.3f seconds”, seconds);
 if (seconds > 0.0)
 printf(“, %0.2f trials/sec.”, trials / seconds);
 if (trials > 0.0) {
 trialTime = (seconds * (double) MILLION) / trials;
 printf(“, %.2f µsec./trial\n”, trialTime);
 printf(“%.2f µsec. mean test overhead”,
 trialTime - mean
 );
 }
 printf(“\n”);
}