Create a gist now

Instantly share code, notes, and snippets.

A class for logging excessive blocking on the main thread
/// Observes a run loop to detect any stalling or blocking that occurs.
///
/// This class is thread-safe.
@interface GHRunLoopWatchdog : NSObject
/// Initializes the receiver to watch the specified run loop, using a default
/// stalling threshold.
- (id)initWithRunLoop:(CFRunLoopRef)runLoop;
/// Initializes the receiver to detect when the specified run loop blocks for
/// more than `threshold` seconds.
///
/// This is the designated initializer for this class.
- (id)initWithRunLoop:(CFRunLoopRef)runLoop stallingThreshold:(NSTimeInterval)threshold;
/// Begins watching the receiver's run loop for stalling in the given mode.
///
/// The receiver will automatically stop watching the run loop upon deallocation.
///
/// mode - The mode in which to monitor the specified run loop. Use
/// kCFRunLoopCommonModes to watch all common run loop modes. This should
/// not be NULL.
- (void)startWatchingMode:(CFStringRef)mode;
/// Stops watching the receiver's run loop for stalling in the given mode.
///
/// There is generally no need to invoke this method explicitly.
///
/// mode - The mode in which to monitor the specified run loop. Use
/// kCFRunLoopCommonModes to watch all common run loop modes. This should
/// not be NULL.
- (void)stopWatchingMode:(CFStringRef)mode;
/// A block to invoke any time the run loop stalls.
///
/// duration - The number of seconds that elapsed in the run loop iteration.
@property (copy) void (^didStallWithDuration)(NSTimeInterval duration);
@end
#import "GHRunLoopWatchdog.h"
#include <mach/mach_time.h>
// The default number of seconds that must pass to consider a run loop stalled.
static const NSTimeInterval GHRunLoopWatchdogDefaultStallingThreshold = 0.2;
@interface GHRunLoopWatchdog ()
// The run loop to watch.
//
// Despite being marked `assign`, this property is retained.
@property (nonatomic, assign, readonly) CFRunLoopRef runLoop;
// The observer used to watch the run loop.
//
// Despite being marked `assign`, this property is retained.
@property (nonatomic, assign, readonly) CFRunLoopObserverRef observer;
// The number of seconds that must pass to consider the run loop stalled.
@property (nonatomic, assign, readonly) NSTimeInterval threshold;
// The mach_absolute_time() at which the current run loop iteration was started,
// or 0 if there is no current iteration in progress.
//
// This property is not thread-safe, and must only be accessed from the thread
// that the run loop is associated with.
@property (nonatomic, assign) uint64_t startTime;
// Invoked any time the run loop stalls.
//
// duration - The number of seconds that elapsed in the run loop iteration.
- (void)iterationStalledWithDuration:(NSTimeInterval)duration;
@end
@implementation GHRunLoopWatchdog
#pragma mark Lifecycle
- (id)initWithRunLoop:(CFRunLoopRef)runLoop {
return [self initWithRunLoop:runLoop stallingThreshold:GHRunLoopWatchdogDefaultStallingThreshold];
}
- (id)initWithRunLoop:(CFRunLoopRef)runLoop stallingThreshold:(NSTimeInterval)threshold {
NSParameterAssert(runLoop != NULL);
NSParameterAssert(threshold > 0);
self = [super init];
if (self == nil) return nil;
_runLoop = (CFRunLoopRef)CFRetain(runLoop);
_threshold = threshold;
// Precalculate timebase information.
mach_timebase_info_data_t timebase;
mach_timebase_info(&timebase);
NSTimeInterval secondsPerMachTime = timebase.numer / timebase.denom / 1e9;
@weakify(self);
// Observe at an extremely low order so that we can catch stalling even in
// high-priority operations (like UI redrawing or animation).
_observer = CFRunLoopObserverCreateWithHandler(NULL, kCFRunLoopAllActivities, YES, INT_MIN, ^(CFRunLoopObserverRef observer, CFRunLoopActivity activity) {
@strongify(self);
switch (activity) {
// What we consider one "iteration" might start with any one of
// these events.
case kCFRunLoopEntry:
case kCFRunLoopBeforeTimers:
case kCFRunLoopAfterWaiting:
case kCFRunLoopBeforeSources:
if (self.startTime == 0) self.startTime = mach_absolute_time();
break;
case kCFRunLoopBeforeWaiting:
case kCFRunLoopExit: {
uint64_t endTime = mach_absolute_time();
if (self.startTime <= 0) {
break;
}
uint64_t elapsed = endTime - self.startTime;
NSTimeInterval duration = elapsed * secondsPerMachTime;
if (duration > self.threshold) [self iterationStalledWithDuration:duration];
self.startTime = 0;
break;
}
default:
NSAssert(NO, @"Observer should not have been triggered for activity %i", (int)activity);
}
});
if (_observer == NULL) return nil;
return self;
}
- (void)dealloc {
if (_observer != NULL) {
CFRunLoopObserverInvalidate(_observer);
CFRelease(_observer);
_observer = NULL;
}
if (_runLoop != NULL) {
CFRelease(_runLoop);
_runLoop = NULL;
}
}
#pragma mark Starting and Stopping
- (void)startWatchingMode:(CFStringRef)mode {
NSParameterAssert(mode != NULL);
CFRunLoopAddObserver(self.runLoop, self.observer, mode);
}
- (void)stopWatchingMode:(CFStringRef)mode {
NSParameterAssert(mode != NULL);
CFRunLoopRemoveObserver(self.runLoop, self.observer, mode);
}
#pragma mark Timing
- (void)iterationStalledWithDuration:(NSTimeInterval)duration {
#if DEBUG
NSLog(@"%@: iteration of run loop %p took %.f ms to execute", self, self.runLoop, (double)duration * 1000);
#endif
void (^didStall)(NSTimeInterval) = self.didStallWithDuration;
if (didStall != nil) didStall(duration);
}
@end
@jspahrsummers
Owner

This was written before CFTypes got managed correctly by ARC, so that's why the property attributes are weird. If it were updated today, it'd use strong properties.

@dbachrach

@jspahrsummers what is the intended way to initialize this. I have done:

GHRunLoopWatchdog* watchdog = [[GHRunLoopWatchdog alloc] initWithRunLoop:CFRunLoopGetMain()];
[watchdog startWatchingMode:kCFRunLoopCommonModes];

I put a breakpoint inside the observer and it never is executed. Let me know if you need more info. Thanks.

@yaozhuoyu

At 94 line,NSAssert can retain self, so this is a retain cycle.

@derpoliuk

@yaozhuoyu How NSAssert(NO, @"Observer should not have been triggered for activity %i", (int)activity); will retain self?

@fabb
fabb commented Jan 31, 2015

@derpoliuk NSAssert really captures self, just look at the macro definition. I searched for hours to find that retain cycle in one of my projects.

@derpoliuk

@fabb Thank you for response. I should've check NSAssert definition before asking.

@hossein1448

@dbachrach did you solve the problem?

@dbachrach

@hossein1448 no not yet. Will take a look again tomorrow.

@hossein1448

@jspahrsummers:
i try to use and initial GHRunLoopWatchdog in AppDelegate like @dbachrach use it
do i use this right?
I put a breakpoint inside the observer and it never is executed.

@fabb
fabb commented Feb 3, 2015

@hossein1448 I put a breakpoint under case kCFRunLoopExit and it breaks fine.

@johnboiles

@dbachrach, @hossein1448: don't forget to retain the GHRunLoopWatchdog somewhere or it will get released when it goes out of scope. If you initialize your watchdog in application:didFinishLaunchingWithOptions:, then you might want to create a property on your AppDelegate @property GHRunLoopWatchdog *runLoopWatchdog then initialize it like this:

    self.runLoopWatchdog = [[GHRunLoopWatchdog alloc] initWithRunLoop:CFRunLoopGetMain()];
    [self.runLoopWatchdog startWatchingMode:kCFRunLoopCommonModes];

You can then do this to test that it fires:

    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(1.0 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
        sleep(3);
    });
@dbachrach

(doh) Thanks @johnboiles

@openaphid

I'm wondering if there's a lightweight way to log what methods are stalling in UI thread. It would be very helpful for occasional stalling issues.

@wisonlin

You may observe kCFRunLoopAfterWaiting and kCFRunLoopBeforeWaiting but not kCFRunLoopBeforeSources and kCFRunLoopExit to detect the blocking.

@YogevSitton

This is a great idea - thank you.
I added this to my app and from time to time I see something like:
"<GHRunLoopWatchdog: 0x7faf6343d340>: iteration of run loop 0x7faf6394d230 took 1866 ms to execute"

There are a lot of things going on with the app.
How can I tell which chunk of code (or object) causes this delay?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment