Function/method-level profiling on iOS

Question

Is there any solution to do function/method-level profiling on iOS with recent Xcode (7.x)?

What I mean by that is an equivalent to GCC's -pg which makes the compiler inject performance logging into your code. Back when Apple was still using GCC, I did successfully use -pg and gprof on iOS, but there doesn't seem to be an equivalent with clang.

I need to find out who is micro-blocking my main thread in a certain scenario (the app still reacts, but the blocking makes scrolling jittery). Unfortunately, Instruments' tools are not up to the task: sampling (stopping the app and recording the stack trace) is too coarse/imprecise here for my needs.

So I need a way to find out which method ran at what time and for how long, precisely. The only real way to do that is to either have the compiler inject the necessary code (which is what -pg is doing) or maybe some creative hacking of the Objective-C runtime. Are there any solutions for this already?

-pg and gprof never did that. All they did was count calls, and sample the PC (which is blind to blocking). [*More.*](http://stackoverflow.com/a/1779343/23771) You don't need precision. What you need is stack samples *at the right time* - i.e. when the process is blocked. Most stack-sampling profilers don't sample when blocked, so that's no good. (Zoom might work?) I would try [*my favorite method*](http://stackoverflow.com/a/378024/23771). It might require a fair number of samples, but you'll recognize the right one when you see it. — Mike Dunlavey, Mar 10 '16 at 13:14
@MikeDunlavey: Thanks for clearing up about `gprof`, it's been a few years since I've last used it. Your manual interruption method is interesting, I'll try it even though I _am_ skeptical due to the nature of the problem (I _expect_ to break on the main thread very often; the problem is when a method on the main thread takes too long; don't yet see how your method will help me with that). I am already using Instruments which samples ever 1ms, but it can't tell me whether this is a new runloop iteration (which is the essential information I need, actually). — DarkDust, Mar 10 '16 at 13:42
Sometimes game programmers have a similar problem, where very seldom something runs over the time budget. So it's not an overall performance problem - rather it's an annoyance. What I suggested in that case is setting a timer at the start of a "frame", set to expire after the frame normally finishes. Then reset it after the frame finishes. So it only interrupts when the frame code takes too long. Then you put a breakpoint in the interrupt handler. Maybe something along those lines would be needed in your case? Not simple, but no profiler can find such a problem. — Mike Dunlavey, Mar 10 '16 at 14:18
@MikeDunlavey: That is actually a very useful idea! I have to find the best way to do this with NSRunLoop, but I can surely make this work. Thanks a lot! — DarkDust, Mar 10 '16 at 14:24

score 0 · Accepted Answer · answered Mar 14 '16 at 10:00

The suggestion of @MikeDunlavey to set up a timer was the right solution for me. A real timer wouldn't work in my case, so I used a background thread with a high priority and a NSCondition (a lower level mechanism like pthread_cond_timedwait would work as well). With each runloop iteration, the condition is triggered. If the main thread takes too long, the condition aborts.

Here's the very crude code I've used. Since my problem was in the very busy startup, this was sufficient for me to detect my issues; if you want to use this to detect issues during "normal" runtime you need to enhance it to handle the waiting part of the runloop.

I wasn't able to catch all problems with this solution, though; scrolling is still a bit jittery but it's way better than before.

- (void)startWatchdog
{
    static NSDate * lastIteration;
    static BOOL hasHandled = NO;
    NSCondition * condition = [[NSCondition alloc] init];

    lastIteration = [NSDate date];

    CFRunLoopObserverRef observer = CFRunLoopObserverCreateWithHandler(NULL,
        kCFRunLoopBeforeTimers | kCFRunLoopBeforeWaiting, true, 0,
        ^(CFRunLoopObserverRef observer, CFRunLoopActivity activity) {
            NSDate * now = [NSDate date];

            if (activity == kCFRunLoopBeforeTimers) {
                if (!hasHandled) {
                    [condition lock];
                    [condition signal];
                    [condition unlock];
                }

                lastIteration = now;
                hasHandled = NO;

            } else {
                // About to wait for events. We might want tell the watchdog method
                // that it's OK that there's going to be a timeout.
                [condition lock];
                [condition signal];
                [condition unlock];
                hasHandled = YES;
            }
        }
    );

    NSThread * watchdog = [[NSThread alloc] initWithTarget:self selector:@selector(watchdog:) object:condition];
    [watchdog setThreadPriority:1];
    [watchdog start];

    CFRunLoopRef runloop = [[NSRunLoop currentRunLoop] getCFRunLoop];
    CFRunLoopAddObserver(runloop, observer, kCFRunLoopCommonModes);
    CFRunLoopAddObserver(runloop, observer, (CFStringRef)UITrackingRunLoopMode);
}

- (void)watchdog:(NSCondition *)condition
{
    @autoreleasepool {
        while (1) {
            BOOL wasHandled;
            NSDate * start = [NSDate date];

            [condition lock];
            wasHandled = [condition waitUntilDate:[start dateByAddingTimeInterval:0.2]];
            [condition unlock];

            if (!wasHandled) {
                NSLog(@"-- Timeout: %f", [[NSDate date] timeIntervalSinceDate:start]);
            }
        }
    }
}

Function/method-level profiling on iOS

1 Answers1