Open Radar

 
30-Oct-2008 09:32 AM Michael Ash:
Summary:

When enqueueing an NSOperation from inside the action of another NSOperation, while many concurrent NSOperationQueues are executing, the following exception is sometimes thrown:

*** -[NSInvocationOperation start]: receiver has already started or finished

Steps to Reproduce:

Compile and run the following program:

#import <Foundation/Foundation.h>


@interface Tester : NSObject
{
    NSOperationQueue *_queue;
}

- (void)test;

@end

@implementation Tester

- (id)init
{
    if((self = [super init]))
    {
        _queue = [[NSOperationQueue alloc] init];
        [_queue setMaxConcurrentOperationCount:1];
    }
    return self;
}

- (void)test
{
    NSInvocationOperation *op = [[NSInvocationOperation alloc] initWithTarget:self selector:_cmd object:nil];
    [_queue addOperation:op];
    [op release];
}

@end

int main(int argc, char **argv)
{
    [NSAutoreleasePool new];
    
    NSMutableArray *testers = [NSMutableArray array];
    int i;
    for(i = 0; i < 10; i++)
        [testers addObject:[[[Tester alloc] init] autorelease]];
    
    for(Tester *tester in testers)
        [tester test];
    
    while(1) sleep(1000);
}

Expected Results:

The given program should run indefinitely with no errors.

Actual results:

After a few seconds on my four-core first generation Mac Pro, it throws the above exception with this backtrace:

#0  0x96480ff4 in ___TERMINATING_DUE_TO_UNCAUGHT_EXCEPTION___ ()
#1  0x9207ee3b in objc_exception_throw ()
#2  0x92db74de in -[NSOperation start] ()
#3  0x92db7112 in __runop ()
#4  0x902ae1f7 in _pthread_wqthread ()
#5  0x902ae0aa in start_wqthread ()

And this is the backtrace of all threads in the program from one example run:

(gdb) t a a bt

Thread 13 (process 28827 thread 0x3003):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db7366 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 12 (process 28827 thread 0x2f03):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db7366 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 11 (process 28827 thread 0x2e03):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db7366 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 10 (process 28827 thread 0x2d03):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db7260 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 9 (process 28827 thread 0x2c03):
#0  0x96480ff4 in ___TERMINATING_DUE_TO_UNCAUGHT_EXCEPTION___ ()
#1  0x9207ee3b in objc_exception_throw ()
#2  0x92db74de in -[NSOperation start] ()
#3  0x92db7112 in __runop ()
#4  0x902ae1f7 in _pthread_wqthread ()
#5  0x902ae0aa in start_wqthread ()

Thread 8 (process 28827 thread 0x2b03):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db74b5 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 7 (process 28827 thread 0x2a03):
#0  0x902ae07a in __workq_ops ()
#1  0x902af772 in workqueue_exit ()
#2  0x902ae0aa in start_wqthread ()

Thread 6 (process 28827 thread 0x2903):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db74b5 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 5 (process 28827 thread 0x1303):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db7260 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 4 (process 28827 thread 0x1203):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db74b5 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 3 (process 28827 thread 0x1103):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db7502 in -[NSOperation _implicitObservationInfo] ()
#3  0x92d22bbb in -[NSObject(NSKeyValueObserverNotification) willChangeValueForKey:] ()
#4  0x92db7366 in -[NSOperation start] ()
#5  0x92db7112 in __runop ()
#6  0x902ae1f7 in _pthread_wqthread ()
#7  0x902ae0aa in start_wqthread ()

Thread 2 (process 28827 thread 0x1003):
#0  0x902444ee in semaphore_wait_signal_trap ()
#1  0x9024bfc5 in pthread_mutex_lock ()
#2  0x92db5f40 in -[NSOperation init] ()
#3  0x92e757ac in -[NSInvocationOperation initWithInvocation:] ()
#4  0x92e756d7 in -[NSInvocationOperation initWithTarget:selector:object:] ()
#5  0x00001c7e in -[Tester test] (self=0x105d20, _cmd=0x9209a260) at nsoptest.m:27
#6  0x96486a7d in __invoking___ ()
#7  0x96486468 in -[NSInvocation invoke] ()
#8  0x92e75988 in -[NSInvocationOperation main] ()
#9  0x92db7424 in -[NSOperation start] ()
#10 0x92db7112 in __runop ()
#11 0x902ae1f7 in _pthread_wqthread ()
#12 0x902ae0aa in start_wqthread ()

Thread 1 (process 28827 local thread 0x2d03):
#0  0x9024b68e in __semwait_signal ()
#1  0x9024b50f in nanosleep$UNIX2003 ()
#2  0x902a1c59 in sleep$UNIX2003 ()
#3  0x00001ec5 in main (argc=1, argv=0xbffff818) at nsoptest.m:46
(gdb) 

Regression:

This problem was reproduced on two MacBook Pros and another Mac Pro. It happens 100% reliably on my Mac pro, the reliability was not tested on the others but is presumed to also be reliable. The test program was also run on a G5 and a MacBook with no problem.

Notes:

N/A

01-Feb-2009 01:30 PM Michael Ash:
I have now come up with a greatly simplified test case which still demonstrates the problem:

#import <Foundation/Foundation.h>

@interface MyOperation : NSOperation {} @end
@implementation MyOperation
- (void)main
{
    usleep(10000);
}
@end

int main(int argc, char **argv)
{
    NSAutoreleasePool *outerPool = [[NSAutoreleasePool alloc] init];
    
    NSOperationQueue *queue = [[NSOperationQueue alloc] init];
    unsigned count = 0;
    while(1)
    {
        NSAutoreleasePool *innerPool = [[NSAutoreleasePool alloc] init];
        
        MyOperation *op = [[MyOperation alloc] init];
        [queue addOperation:op];
        [op release];
        
        if(++count % 50000 == 0)
            NSLog(@"%u operations", count);
        
        [innerPool release];
    }
    
    [outerPool release];
    return 0;
}

On my Mac Pro, this crashes with the same NSInvalidArgumentException with great reliability, and often after only a few seconds of execution, although some runs can take much longer.