digital wave / Reiner Pittinger: iOS, Web Technologies, Interaction DesignSoftware Development in Berlin: iOS, Web Technologies, Interaction Design

KISS Time Profiling

In the final stage of development for my current project, I wanted to track down some performance issues in the app.

The Macro Way

First I have been looking for a really simple solution, something like my former colleague Markus once implemented, and which worked like this:

1
2
3
4
5
6
    - (void)myMethod
  {
      PROFILING_START(@"myMethod");
      // do stuff…
      PROFILING_END(@"myMethod"); // Output: "myMethod took 1.2345s"
  }

Unfortunately I could not find anything similar, just a “Quick-And-Dirty”-Profiler using Objective-C++ (hey, I took that adjective from the header-file!) and a macro that required you to wrap the code you want to profile into a block.

I did not want to use the latter one because by wrapping your code into a profiling block, you cannot simply strip out the profiling code for production.

So I came up with a really simple solution that fits into a few lines of code:

1
2
3
4
5
6
7
8
    #if DEBUG
        #define PROFILING_START(__message) NSDate* rpProfiling_startDate = [NSDate date]; NSString* rpProfiling_logMessage = __message;
        #define PROFILING_STOP() NSTimeInterval rpProfiling_timeDiff = [rpProfiling_startDate timeIntervalSinceNow]; NSLog(@"%@ took %1.5fs", rpProfiling_logMessage, rpProfiling_timeDiff * -1.0);
    #else
        #define PROFILING_START(__message)
        #define PROFILING_STOP()
    #endif
  

Although you can argue that creating an NSDate instance and calling methods on it costs some time and could “falsify”, I think these effects are minor compared to the simplicity that gets the job done.

As you can see, the profiling code is replaced with nothing if the DEBUG directive is not true, so your ad-hoc and release builds are not slowed down.

However, this solution does have caveats:

  • You cannot wrap profiling calls.
  • PROFILING_START and PROFILING_STOP must be called in the same method.

To fix these problems you could write a small utility class that manages a profiling registry and logs time consumption for different profiling jobs, although you should avoid to try putting all that functionality into the macro, as it would become as awful to read it like it would be to write it.

Instead, Instruments already comes with a nice tool: the Time Profiler instrument.

Instruments and Time Profiler

At first I did not quite catch how to correctly reason about the tools output, but – as often – is actually quite easy.

Instruments Time Profiler

  1. Before starting profiling, make sure that you temporarily use your development provisioning profile for code signing, otherwise you just get desymbolized output (pointer adresses instead of method names) in the profilier.
  2. Do not profile the simulator ;-)
  3. Start profiling your app by pressing and holding the Run-Button in Xcode and selecting the “Profilie” entry.
  4. In Instruments, select the Time Profiler instrument.
  5. Start performing the actions that you think are lagging/slow and have a “non-optimal user responsiveness”, to employ Apple wording.
    • You should add a flag at the start of your action by hitting COMMAND + ARROW-DOWN (or selecting it from the Edit menu) to later easily narrow the relevant time range.
  6. When you are finished, stop your profiling run by hitting the record button.
  7. Narrow down the inspected time range with the Inspection Range buttons.
  8. The list in Call Tree tells you how much time was spent in each function. To narrow the results down to your code, you can check the following options:
    • Hide System Libraries
    • Show Obj-C Only

In the screenshot above I ran time profiler with Ole’s DocSets application. As you can see there is not much to discover as the interface is quite simple, but you can see the time and percentage spent in each method.

In my project at work I was able to track down the method call that caused the UI to lag - so it is a usefull utility indeed!

A related WWDC session with insights into debugging performance is Session 238 - iOS App Performance_ Graphics and Animations.