A class for logging excessive blocking on the main thread

GHRunLoopWatchdog.h

/// 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

GHRunLoopWatchdog.m

#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

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.

@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.

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

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

@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.

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

@dbachrach did you solve the problem?

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

@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.

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

@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);
    });

(doh) Thanks @johnboiles

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.

@johnboiles thanks

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

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?