[ios] How to log a method's execution time exactly in milliseconds?

Is there a way to determine how much time a method needs to execute (in milliseconds)?

You can get really fine timing (seconds.parts of seconds) using this StopWatch class. It uses the high-precision timer in the iPhone. Using NSDate will only get you second(s) accuracy. This version is designed specifically for autorelease and objective-c. I have a c++ version as well if needed. You can find the c++ version here.

StopWatch.h

#import <Foundation/Foundation.h>


@interface StopWatch : NSObject 
{
    uint64_t _start;
    uint64_t _stop;
    uint64_t _elapsed;
}

-(void) Start;
-(void) Stop;
-(void) StopWithContext:(NSString*) context;
-(double) seconds;
-(NSString*) description;
+(StopWatch*) stopWatch;
-(StopWatch*) init;
@end

StopWatch.m

#import "StopWatch.h"
#include <mach/mach_time.h>

@implementation StopWatch

-(void) Start
{
    _stop = 0;
    _elapsed = 0;
    _start = mach_absolute_time();
}
-(void) Stop
{
    _stop = mach_absolute_time();   
    if(_stop > _start)
    {
        _elapsed = _stop - _start;
    }
    else 
    {
        _elapsed = 0;
    }
    _start = mach_absolute_time();
}

-(void) StopWithContext:(NSString*) context
{
    _stop = mach_absolute_time();   
    if(_stop > _start)
    {
        _elapsed = _stop - _start;
    }
    else 
    {
        _elapsed = 0;
    }
    NSLog([NSString stringWithFormat:@"[%@] Stopped at %f",context,[self seconds]]);

    _start = mach_absolute_time();
}


-(double) seconds
{
    if(_elapsed > 0)
    {
        uint64_t elapsedTimeNano = 0;

        mach_timebase_info_data_t timeBaseInfo;
        mach_timebase_info(&timeBaseInfo);
        elapsedTimeNano = _elapsed * timeBaseInfo.numer / timeBaseInfo.denom;
        double elapsedSeconds = elapsedTimeNano * 1.0E-9;
        return elapsedSeconds;
    }
    return 0.0;
}
-(NSString*) description
{
    return [NSString stringWithFormat:@"%f secs.",[self seconds]];
}
+(StopWatch*) stopWatch
{
    StopWatch* obj = [[[StopWatch alloc] init] autorelease];
    return obj;
}
-(StopWatch*) init
{
    [super   init];
    return self;
}

@end

The class has a static stopWatch method that returns an autoreleased object.

Once you call start, use the seconds method to get the elapsed time. Call start again to restart it. Or stop to stop it. You can still read the time (call seconds) anytime after calling stop.

Example In A Function (Timing call of execution)

-(void)SomeFunc
{
   StopWatch* stopWatch = [StopWatch stopWatch];
   [stopWatch Start];

   ... do stuff

   [stopWatch StopWithContext:[NSString stringWithFormat:@"Created %d Records",[records count]]];
}

Here are two one-line macros that I use:

#define TICK   NSDate *startTime = [NSDate date]
#define TOCK   NSLog(@"Time: %f", -[startTime timeIntervalSinceNow])

Use it like this:

TICK;

/* ... Do Some Work Here ... */

TOCK;

Here is another way, in Swift, to do that using the defer keyword

func methodName() {
  let methodStart = Date()
  defer {
    let executionTime = Date().timeIntervalSince(methodStart)
    print("Execution time: \(executionTime)")
  }
  // do your stuff here
}

From Apple's docs: A defer statement is used for executing code just before transferring program control outside of the scope that the defer statement appears in.

This is similar to a try/finally block with the advantage of having the related code grouped.

Since you want to optimize time moving from one page to another in a UIWebView, does it not mean you really are looking to optimize the Javascript used in loading these pages?

To that end, I'd look at a WebKit profiler like that talked about here:

http://www.alertdebugging.com/2009/04/29/building-a-better-javascript-profiler-with-webkit/

Another approach would be to start at a high level, and think how you can design the web pages in question to minimize load times using AJAX style page loading instead of refreshing the whole webview each time.

In Swift, I'm using:

In my Macros.swift I just added

var startTime = NSDate()
func TICK(){ startTime =  NSDate() }
func TOCK(function: String = __FUNCTION__, file: String = __FILE__, line: Int = __LINE__){
    println("\(function) Time: \(startTime.timeIntervalSinceNow)\nLine:\(line) File: \(file)")
}

you can now just call anywhere

TICK()

// your code to be tracked

TOCK()

Swift 5.0

   var startTime = NSDate()
func TICK(){ startTime =  NSDate() }
func TOCK(function: String = #function, file: String = #file, line: Int = #line){
    print("\(function) Time: \(startTime.timeIntervalSinceNow)\nLine:\(line) File: \(file)")
}

• this code is based on Ron's code translate to Swift, he has the credits
• I'm using start date at global level, any suggestion to improve are welcome

An example of fine-grained timing using mach_absolute_time() in Swift 4:

let start = mach_absolute_time()

// do something

let elapsedMTU = mach_absolute_time() - start
var timebase = mach_timebase_info()
if mach_timebase_info(&timebase) == 0 {
    let elapsed = Double(elapsedMTU) * Double(timebase.numer) / Double(timebase.denom)
    print("render took \(elapsed)")
}
else {
    print("timebase error")
}

I use very minimal, one page class implementation inspired by code from this blog post:

#import <mach/mach_time.h>

@interface DBGStopwatch : NSObject

+ (void)start:(NSString *)name;
+ (void)stop:(NSString *)name;

@end

@implementation DBGStopwatch

+ (NSMutableDictionary *)watches {
    static NSMutableDictionary *Watches = nil;
    static dispatch_once_t OnceToken;
    dispatch_once(&OnceToken, ^{
        Watches = @{}.mutableCopy;
    });
    return Watches;
}

+ (double)secondsFromMachTime:(uint64_t)time {
    mach_timebase_info_data_t timebase;
    mach_timebase_info(&timebase);
    return (double)time * (double)timebase.numer /
        (double)timebase.denom / 1e9;
}

+ (void)start:(NSString *)name {
    uint64_t begin = mach_absolute_time();
    self.watches[name] = @(begin);
}

+ (void)stop:(NSString *)name {
    uint64_t end = mach_absolute_time();
    uint64_t begin = [self.watches[name] unsignedLongLongValue];
    DDLogInfo(@"Time taken for %@ %g s",
              name, [self secondsFromMachTime:(end - begin)]);
    [self.watches removeObjectForKey:name];
}

@end

The usage of it is very simple:

• just call [DBGStopwatch start:@"slow-operation"]; at the beginning
• and then [DBGStopwatch stop:@"slow-operation"]; after the finish, to get the time

Here's a Swift 3 solution for bisecting code anywhere to find a long running process.

var increment: Int = 0

var incrementTime = NSDate()

struct Instrumentation {
    var title: String
    var point: Int
    var elapsedTime: Double

    init(_ title: String, _ point: Int, _ elapsedTime: Double) {
        self.title = title
        self.point = point
        self.elapsedTime = elapsedTime
    }
}

var elapsedTimes = [Instrumentation]()

func instrument(_ title: String) {
    increment += 1
    let incrementedTime = -incrementTime.timeIntervalSinceNow
    let newPoint = Instrumentation(title, increment, incrementedTime)
    elapsedTimes.append(newPoint)
    incrementTime = NSDate()
}

Usage: -

instrument("View Did Appear")

print("ELAPSED TIMES \(elapsedTimes)")

Sample output:-

ELAPSED TIMES [MyApp.SomeViewController.Instrumentation(title: "Start View Did Load", point: 1, elapsedTime: 0.040504038333892822), MyApp.SomeViewController.Instrumentation(title: "Finished Adding SubViews", point: 2, elapsedTime: 0.010585010051727295), MyApp.SomeViewController.Instrumentation(title: "View Did Appear", point: 3, elapsedTime: 0.56564098596572876)]

I use this code:

#import <mach/mach_time.h>

float TIME_BLOCK(NSString *key, void (^block)(void)) {
    mach_timebase_info_data_t info;
    if (mach_timebase_info(&info) != KERN_SUCCESS)
    {
        return -1.0;
    }

    uint64_t start = mach_absolute_time();
    block();
    uint64_t end = mach_absolute_time();
    uint64_t elapsed = end - start;

    uint64_t nanos = elapsed * info.numer / info.denom;
    float cost = (float)nanos / NSEC_PER_SEC;

    NSLog(@"key: %@ (%f ms)\n", key, cost * 1000);
    return cost;
}

I use this:

clock_t start, end;
double elapsed;
start = clock();

//Start code to time

//End code to time

end = clock();
elapsed = ((double) (end - start)) / CLOCKS_PER_SEC;
NSLog(@"Time: %f",elapsed);

But I'm not sure about CLOCKS_PER_SEC on the iPhone. You might want to leave it off.

There is a convenient wrapper for mach_absolute_time() – it's a CACurrentMediaTime() function.

Unlike NSDate or CFAbsoluteTimeGetCurrent() offsets, mach_absolute_time() and CACurrentMediaTime() are based on the internal host clock, a precise, monatomic measure, and not subject to changes in the external time reference, such as those caused by time zones, daylight savings, or leap seconds.

ObjC

CFTimeInterval startTime = CACurrentMediaTime();
// Do your stuff here
CFTimeInterval endTime = CACurrentMediaTime();
NSLog(@"Total Runtime: %g s", endTime - startTime);

Swift

let startTime = CACurrentMediaTime()
// Do your stuff here
let endTime = CACurrentMediaTime()
print("Total Runtime: \(endTime - startTime) s")

I know this is an old one but even I found myself wandering past it again, so I thought I'd submit my own option here.

Best bet is to check out my blog post on this: Timing things in Objective-C: A stopwatch

Basically, I wrote a class that does stop watching in a very basic way but is encapsulated so that you only need to do the following:

[MMStopwatchARC start:@"My Timer"];
// your work here ...
[MMStopwatchARC stop:@"My Timer"];

And you end up with:

MyApp[4090:15203]  -> Stopwatch: [My Timer] runtime: [0.029]

in the log...

Again, check out my post for a little more or download it here: MMStopwatch.zip

For fine-grained timing on OS X, you should use mach_absolute_time( ) declared in <mach/mach_time.h>:

#include <mach/mach_time.h>
#include <stdint.h>

// Do some stuff to setup for timing
const uint64_t startTime = mach_absolute_time();
// Do some stuff that you want to time
const uint64_t endTime = mach_absolute_time();

// Time elapsed in Mach time units.
const uint64_t elapsedMTU = endTime - startTime;

// Get information for converting from MTU to nanoseconds
mach_timebase_info_data_t info;
if (mach_timebase_info(&info))
   handleErrorConditionIfYoureBeingCareful();

// Get elapsed time in nanoseconds:
const double elapsedNS = (double)elapsedMTU * (double)info.numer / (double)info.denom;

Of course the usual caveats about fine-grained measurements apply; you're probably best off invoking the routine under test many times, and averaging/taking a minimum/some other form of processing.

Additionally, please note that you may find it more useful to profile your application running using a tool like Shark. This won't give you exact timing information, but it will tell you what percentage of the application's time is being spent where, which is often more useful (but not always).

OK, if your objective is to find out what you can fix to make it faster, that's a little different goal. Measuring the time that functions take is a good way to find out if what you did made a difference, but to find out what to do you need a different technique. This is what I recommend, and I know you can do it on iPhones.

Edit: Reviewers suggested I elaborate the answer, so I'm trying to think of a brief way to say it.
Your overall program takes enough clock time to bother you. Suppose that's N seconds.
You're assuming you can speed it up. The only way you can do that is by making it not do something it's doing in that time, accounting for m seconds.
You don't initially know what that thing is. You can guess, as all programmers do, but it could easily be something else. Whatever it is, here's how you can find it:

Since that thing, whatever it is, accounts for fraction m/N of the time, that means if you pause it at random the probability is m/N that you will catch it in the act of doing that thing. Of course it might be doing something else, but pause it and see what it's doing.
Now do it again. If you see it doing that same thing again, you can be more suspicious.

Do it 10 times, or 20. Now if you see it doing some particular thing (no matter how you describe it) on multiple pauses, that you can get rid of, you know two things. You know very roughly what fraction of time it takes, but you know very exactly what to fix.
If you also want to know very exactly how much time will be saved, that's easy. Measure it before, fix it, and measure it after. If you're really disappointed, back out the fix.

Do you see how this is different from measuring? It's finding, not measuring. Most profiling is based on measuring as exactly as possible how much time is taken, as if that's important, and hand-waves the problem of identifying what needs to be fixed. Profiling does not find every problem, but this method does find every problem, and it's the problems you don't find that hurt you.

I use this in my utils library (Swift 4.2):

public class PrintTimer {
    let start = Date()
    let name: String

    public init(file: String=#file, line: Int=#line, function: String=#function, name: String?=nil) {
        let file = file.split(separator: "/").last!
        self.name = name ?? "\(file):\(line) - \(function)"
    }

    public func done() {
        let end = Date()
        print("\(self.name) took \((end.timeIntervalSinceReferenceDate - self.start.timeIntervalSinceReferenceDate).roundToSigFigs(5)) s.")
    }
}

... then call in a method like:

func myFunctionCall() {
    let timer = PrintTimer()
    // ...
    timer.done()
}

... which in turn looks like this in the console after running:

MyFile.swift:225 - myFunctionCall() took 1.8623 s.

Not as concise as TICK/TOCK above, but it is clear enough to see what it is doing and automatically includes what is being timed (by file, line at the start of the method, and function name). Obviously if I wanted more detail (ex, if I'm not just timing a method call as is the usual case but instead am timing a block within that method) I can add the "name="Foo"" parameter on the PrintTimer init to name it something besides the defaults.

struct TIME {

    static var ti = mach_timebase_info()
    static var k: Double = 1
    static var mach_stamp: Double {

        if ti.denom == 0 {
            mach_timebase_info(&ti)
            k = Double(ti.numer) / Double(ti.denom) * 1e-6
        }
        return Double(mach_absolute_time()) * k
    }
    static var stamp: Double { return NSDate.timeIntervalSinceReferenceDate() * 1000 }
}

do {
    let mach_start = TIME.mach_stamp
    usleep(200000)
    let mach_diff = TIME.mach_stamp - mach_start

    let start = TIME.stamp
    usleep(200000)
    let diff = TIME.stamp - start

    print(mach_diff, diff)
}

many answers are weird and don't really give result in milliseconds (but in seconds or anything else):

here what I use to get MS (MILLISECONDS):

Swift:

let startTime = NSDate().timeIntervalSince1970 * 1000

// your Swift code

let endTimeMinusStartTime = NSDate().timeIntervalSince1970 * 1000 - startTime
print("time code execution \(endTimeMinStartTime) ms")

Objective-C:

double startTime = [[NSDate date] timeIntervalSince1970] * 1000.0;

// your Objective-C code

double endTimeMinusStartTime = [[NSDate date] timeIntervalSince1970] * 1000.0 - startTime;
printf("time code execution %f ms\n", endTimeMinusStartTime );

I use macros based on Ron's solution.

#define TICK(XXX) NSDate *XXX = [NSDate date]
#define TOCK(XXX) NSLog(@"%s: %f", #XXX, -[XXX timeIntervalSinceNow])

For lines of code:

TICK(TIME1);
/// do job here
TOCK(TIME1);

we'll see in console something like: TIME1: 0.096618

For Swift 4, add as a Delegate to your class:

public protocol TimingDelegate: class {
    var _TICK: Date?{ get set }
}

extension TimingDelegate {
    var TICK: Date {
        _TICK = Date()
        return(_TICK)!
     }

    func TOCK(message: String)  {

        if (_TICK == nil){
            print("Call 'TICK' first!")
        }

        if (message == ""){
            print("\(Date().timeIntervalSince(_TICK!))")
        }
        else{
            print("\(message): \(Date().timeIntervalSince(_TICK!))")
        }
    }
}

Add to our class:

class MyViewcontroller: UIViewController, TimingDelegate

Then add to your class:

var _TICK: Date?

When you want to time something, start with:

TICK

And end with:

TOCK("Timing the XXX routine")