How do I profile how long a piece of code takes to execute in Objective-C/Cocoa for optimization purposes

Question

Lets say I've got two interchangeable pieces of code and I want to figure out which one of them takes less processor time to execute. How would I do this?

To get a very rough estimation I could just put NSLog() calls on either side of the code I wanted to profile, but it seems like the processor being otherwise very busy could skew the results.

Answer 1

Unless one of these two pieces of code is already in your app, and you've already profiled your app's overall performance to determine that the existing code is a major bottleneck, then what you're doing is called "premature optimization."

Xcode includes an excellent profiler tool called "Shark." For some versions, it's found in /Developer/Applications; for others, it's in a "Performance Tools" subdirectory.

Shark will tell you exactly how much time, as a percentage of overall execution time, your app is spending in each part of your code. The idea of using a tool like Shark is to follow the "80/20 rule" - your app will spend 80% of its time running 20% of its code, so for the best results you should spend 80% of your time optimizing that same 20%.

So, to answer your question directly, assuming that you have run Shark, and you're looking to optimize the topmost bottleneck, simply replace it with your optimized code and run your app under Shark again. Then, compare the percentage of the overall time being spent in the replacement code to that of the original.

Answer 2

Woo shark, yay. See also Shark Remote Control. Basically, choose Sampling > Programmatic (Remote) from the menu in shark, then call chudStartRemotePerfMonitor and chudStopRemotePerfMonitor() bracketing the specific code you want to profile.

That aside, here's a chunk of code I keep around for timing.

First the usage

uint64_t startTime, stopTime;
startTime = mach_absolute_time();

< work to time goes here >

stopTime = mach_absolute_time();
logMachTime_withIdentifier_(stopTime - startTime, @"10000000 class messages");

and here's the helper function, logMachTime_withIdentifier_.

#import <mach/mach_time.h>
void logMachTime_withIdentifier_(uint64_t machTime, NSString *identifier) {
    static double timeScaleSeconds = 0.0;
    if (timeScaleSeconds == 0.0) {
        mach_timebase_info_data_t timebaseInfo;
        if (mach_timebase_info(&timebaseInfo) == KERN_SUCCESS) {    // returns scale factor for ns
            double timeScaleMicroSeconds = ((double) timebaseInfo.numer / (double) timebaseInfo.denom) / 1000;
            timeScaleSeconds = timeScaleMicroSeconds / 1000000;
        }
    }

    NSLog(@"%@: %g seconds", identifier, timeScaleSeconds*machTime);
}

Answer 3

Assuming you want to profile a whole app (not just a snippet of code), and that your app is written in C/C++/Objective-C (not, e.g. Ruby), and that you're using Xcode 3.0 or higher, you should also check out the Instruments application. The "Sampler" instrument will give you very similar information to Shark (though without Shark's sometimes very helpful tips on improving performance). In addition, you can track other resource utilization (GC, Core Data, network, disk I/O, etc.) that may be more important determinants of your app's performance than code efficiency (again, depending on the application). Instruments can also make use of the DTrace support in OS X 10.5 (man dtrace). You can write your own instruments using DTrace to monitory your application more specifically (e.g. calls to one or more methods).

Using NSLog is a bad idea, as you suspect, because it likely makes use of the Apple System Logging system. There's a non-deterministic delay in writting a log to the asl and it showing up in the console. I'm not sure when the timestamp is set.