[Objective-C + Cocoa] Runtime Performance Profiling

The iPhone SDK and XCode provide some very useful tools for application profiling, particularly with respect to tracking memory consumption and pinpointing memory leaks and other similar issues, but one thing which I have found lacking in the default toolset is the ability to track the execution time of this-or-that specific bit of code, be it a function call, a loop within a function, or some arbitrary series of API calls made in quick succession.

Typically I would deal with such cases by adding some one-off code around the section that I was interested in profiling to measure and log its execution time. But this approach quickly becomes unwieldy when there are several different places that you are interested in profiling, and particularly when it comes time to track down and remove all of these bits of code so that they stop spamming the log with timing data that is no longer needed.

In any case, here is my solution to this minor annoyance, patterned after a similar utility I implemented in ActionScript some time ago:

//PerformanceTimer.h
#import <Foundation/Foundation.h>


@interface PerformanceTimer : NSObject {
    NSMutableArray* startTimes;
    NSMutableArray* names;
}

+ (void) startTimerWithName: (NSString*) name;
+ (clock_t) stopLastTimer;
+ (clock_t) stopTimerWithName: (NSString*) name;

@end


//PerformanceTimer.m
#import "PerformanceTimer.h"

static PerformanceTimer* timerInstance = nil;

@implementation PerformanceTimer

- (id) init {
    self = [super init];
    if (self) {
        startTimes = [[NSMutableArray alloc] initWithCapacity:16];
        names = [[NSMutableArray alloc] initWithCapacity:16];
    }
    
    return self;
}

- (void) dealloc {
    [startTimes release];
    startTimes = nil;
    
    [names release];
    names = nil;
    
    [super dealloc];
}

- (void) startTimer: (NSString*) name {
    @synchronized(startTimes) {
        clock_t start = clock();
        NSNumber* startNum = [NSNumber numberWithUnsignedLong:start];
        [startTimes addObject:startNum];
        [names addObject:name];
    }
}

- (clock_t) stopTimerNamed: (NSString*) name {
    @synchronized(startTimes) {
        int index = 0;
        for (NSString* timerName in names) {
            if ([timerName isEqualToString:name]) {
                break;
            }
            index++;
        }
        if (index >= [names count]) {
            //couldn't find it
            return 0;
        }
        clock_t start = [[startTimes objectAtIndex:index] unsignedLongValue];
        clock_t end = (clock() - start) / (CLOCKS_PER_SEC / 1000.0);
        
        #ifdef DEBUG
        //if debugging, always print, otherwise let the caller decide what to do
        NSLog(@"PerformanceTimer:  Total execution time for task named '%@':  %lu ms", name, end);
        #endif
        
        [startTimes removeObjectAtIndex:index];
        [names removeObjectAtIndex:index];
        
        return end;
    }
}

- (clock_t) stopTimer {
    @synchronized(startTimes) {
        if ([names count] < 1) {
            //no timer is running
            return 0;
        }
        
        NSString* name = [names objectAtIndex:[names count] - 1];
        return [self stopTimerNamed:name];
    }
}

+ (void) startTimerWithName: (NSString*) name {
    if (! timerInstance) {
        timerInstance = [[PerformanceTimer alloc] init];
    }
    [timerInstance startTimer:name];
}

+ (clock_t) stopLastTimer {
    if (! timerInstance) {
        timerInstance = [[PerformanceTimer alloc] init];
    }
    return [timerInstance stopTimer];
}

+ (clock_t) stopTimerWithName: (NSString*) name {
    if (! timerInstance) {
        timerInstance = [[PerformanceTimer alloc] init];
    }
    return [timerInstance stopTimerNamed:name];
}

@end

This adds a static utility class that can be used to spawn multiple independent named timers. It is used like:

[PerformanceTimer startTimer:@"myTimerName"];
//do some things that you want to time
clock_t elapsedTimeMillis = [PerformanceTimer stopTimerWithName: @"myTimerName"];
//print or log the elapsed time

The default behavior of this class when run in debug mode is to print out the elapsed time automatically when ‘stopTimer’ is called, so it’s not generally necessary to capture or inspect the value returned from ‘stopTimer’ unless you are either running in release mode or if you want to do something more involved than simply logging the timing data to the console.

Note that although a ‘stopLastTimer’ method is provided for convenience, its use is generally not recommended unless you are absolutely sure that nobody else has started a timer somewhere else in the code. Otherwise you can end up inadvertently stopping the wrong timer. Inside of a small, simple, single-threaded application there is little to worry about. But for any more complex/multi-threaded projects it is much safer to always specify a timer by name.