1

I am trying to see how long a method takes to execute in Xcode 7 for an app compiling for iOS versions 7-8-9.

Is saw this Question, Getting the time elapsed (Objective-c). Answers warn not to rely on NSDate for such brief timing. Instead this Answer recommends:

CFTimeInterval startTime = CACurrentMediaTime();
// perform some action
CFTimeInterval elapsedTime = CACurrentMediaTime() - startTime;

Even after importing #import <QuartzCore/QuartzCore.h>, this code does not compile. Reports a linker failure:

Undefined symbols for architecture armv7:

"_CACurrentMediaTime", referenced from:

Is there some other way to track a brief moment in milliseconds or nanoseconds?

Please do not warn about the inherent vagaries that render microbenchmarking unreliable. I'm just trying to get a rough idea of the timing.

Perhaps Objective-C or Swift has something akin to the JMH, Java Micro-benchmarking Harness for building, running, and analysing nano/micro/milli/macro benchmarks written in Java and other languages targetting the Java Virtual Machine.

Community
  • 1
  • 1
Basil Bourque
  • 303,325
  • 100
  • 852
  • 1,154
  • I think the xcode unit test has a performance testing method. No sure if you can view the time in nanoseconds. Probably calling the method many times then divide the total time? – Surely Sep 03 '16 at 02:23
  • @Surely Thanks, but I'm not unit-testing. I just want to capture a start and stop time to calculate elapsed time near top and bottom of a single method. – Basil Bourque Sep 03 '16 at 03:03
  • It's not just lack of precision that's the problem; out-of-order execution can make the results worse than just noisy. e.g. the end-time could be sampled while the result from the code you're trying to measure is still waiting on a cache miss, or even a short chain of dependent loads that will all miss in cache. Of course, this is usually only a problem for time-sources that don't require a system call (like x86's RDTSC instruction, and doesn't (on its own) serialize out-of-order execution.) Making a system call serializes the pipeline on most CPU designs. – Peter Cordes Sep 03 '16 at 05:31

1 Answers1

0

NSDate

Others have warned that NSDate can shimmy a bit when used for micro-benchmarking. But for casual use it works just fine.

NSDate *start = [NSDate date];
// …
NSTimeInterval timeInterval = [start timeIntervalSinceNow];
NSLog(@"elapsedTime after Check call: %f" , timeInterval );

There may well be better ways, but this does work. For example, I timed a method call on an iPod touch 5th generation where it consistently took 0.21 to 0.25 seconds over several runs. Switching to an iPad Air the same method consistently took 0.11 to 0.13 seconds over several runs. Granted, that is a 10-20% variance approximately on both devices. But the casual observing, this may suffice for your needs. Just be sure to make multiple runs of your test.

Example run with Receigen code

Example run, executing some code that harnesses source code generated by the Receigen Mac app for App Receipt Validation. NSDate seems to be tracking microseconds well.

I am not including source code, but you can get the main idea with this description of the sequence of events.

  • A block of code is defined and populated. No business logic executed, just creating the Objective-C block (a closure).
  • My implementation of SKRequestDelegate is instantiated. No real code, just some logging via NSLog.
  • The generated Receigen code is executed. This is a bunch of obfuscated C code that does some decryption work by invoking OpenSSL to parse through Apple’s App Receipt.
  • After the decrypting and parsing, Receigen reports its results by invoking our block that we defined up top. This block is called once for each of our three In-App Purchase products.
  • One final capture of elapsed time, after the Receigen-generated code returns.

You can see below that the block definition is a mere 22 microseconds. The instantiation of of our SKRequestDelegate is much more, around 1,500 microseconds. The Receigen decryption & parsing takes the vast majority of time, about 0.1 seconds to execute. Then around a hundred microseconds to report its findings by invoking the block each of three times.

2016-09-03 17:13:57.883 XXApp[231:7509] elapsedTime after declare & populate a block: -0.000022

2016-09-03 17:13:57.884 XXApp[231:7509] elapsedTime after instantiating implementation of SKRequestDelegate: -0.001579

2016-09-03 17:13:57.995 XXApp[231:7509] elapsedTime after Receigen code called the block: -0.112392

2016-09-03 17:13:57.995 XXApp[231:7509] elapsedTime after Receigen code called the block: -0.112482

2016-09-03 17:13:57.995 XXApp[231:7509] elapsedTime after Receigen code called the block: -0.112556

2016-09-03 17:13:57.997 XXApp[231:7509] elapsedTime after Receigen code done: -0.115133

After running this several times with consistent results, I conclude that NSDate is indeed useful for casual benchmarking in the millisecond-microsecond range.

Community
  • 1
  • 1
Basil Bourque
  • 303,325
  • 100
  • 852
  • 1,154
  • 1
    Tenths of a second is almost certainly ok. When people talk about microbenchmarking a single action, it's usually in the hundreds to thousands of clock cycles, where clock precision, and measurement overhead, and even out-of-order execution of the CPU sampling the clock are huge factors. You're about 4 orders of magnitude away from those problems. Unless NSDate is *really* imprecise, the noise in your results is not a measurement artifact and is probably real (i.e. your procedure really does take a variable amount of time). Variations in cache misses, or interrupts, or whatever are factors. – Peter Cordes Sep 03 '16 at 22:02