NSProgress strange behaviour

Question

I have one big task that consist of several subtasks. and I want to add progress reporting for that big task.
for that I want to use NSProgress, and according to the class documentation I can do this kind of subtask progress by using its child - parent mechanism.

So to simplify it, lets say I have big task that consist of one subtask (of course in real life there would be more subtasks). So this is what I have done:

#define kFractionCompletedKeyPath @"fractionCompleted"  

- (void)runBigTask {
    _progress = [NSProgress progressWithTotalUnitCount:100]; // 100 is arbitrary 

    [_progress addObserver:self
                forKeyPath:kFractionCompletedKeyPath
                   options:NSKeyValueObservingOptionNew
                   context:NULL];

    [_progress becomeCurrentWithPendingUnitCount:100]; 
    [self subTask];
    [_progress resignCurrent];
} 

- (void)subTask {
    NSManagedObjectContext *parentContext = self.managedObjectContext; // self is AppDelegate in this example
    NSManagedObjectContext *bgContext = [[NSManagedObjectContext alloc]initWithConcurrencyType:NSPrivateQueueConcurrencyType];
    [bgContext setParentContext:parentContext];

    [bgContext performBlockAndWait:^{
        NSInteger totalUnit = 1000;
        NSInteger completedUnits = 0;
        NSProgress *subProgress = [NSProgress progressWithTotalUnitCount:totalUnit];

        for (int i=0; i < totalUnit; i++) {   

            // run some Core Data related code...  

            completedUnits++;
            subProgress.completedUnitCount = completedUnits;
        }
    }];
}      

- (void)observeValueForKeyPath:(NSString *)keyPath ofObject:(id)object change:(NSDictionary *)change context:(void *)context {
    if ([keyPath isEqualToString:kFractionCompletedKeyPath]) {
        if ([object isKindOfClass:[NSProgress class]]) {
            NSProgress *progress = (NSProgress *)object;
            NSLog(@"progress… %f", progress.fractionCompleted);
        }
    } else {
        [super observeValueForKeyPath:keyPath ofObject:object change:change context:context];
    }
}

As you can see, the subtask uses background context to run some Core Data related code, and the background context uses the main context as his parent context.
This causes some weird KVO of the progress's "fractionCompleted" property.

this is the print:

progress… 1.000000 // why???
progress… 0.500000 // why?????
progress… 1.000000 // why???????
progress… 0.666650 // why???????????
progress… 0.666990
progress… 0.667320
progress… 0.667660
progress… 0.667990
progress… 0.668320
...  
progress… 1.000000  

As you can see the print starts with 1.0, 0.5 and 1.0 and then is goes to 0.66 ?!
from here it acts normal and goes to 1.0 like I expect.

I tried to understand why this is happening, and I noticed that if I remove the parent context from the background context, it works fine! I get progress from 0.0 to 1.0.

Any ideas why is this happening? and how can I fix that?

I added a very simple project to demonstrate this issue (you can remove the setParentContext: call to see that it works well without it)

Answer 1

The stack trace when this occurs looks like this:

(lldb) bt
* thread #1: tid = 0x81f2, 0x0000000105bffcda Foundation`-[NSProgress setTotalUnitCount:], queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
  * frame #0: 0x0000000105bffcda Foundation`-[NSProgress setTotalUnitCount:]
    frame #1: 0x0000000105bfeb1b Foundation`+[NSProgress progressWithTotalUnitCount:] + 87
    frame #2: 0x0000000105a31213 Foundation`_NSReadBytesFromFileWithExtendedAttributes + 287
    frame #3: 0x0000000105a3109d Foundation`-[NSData(NSData) initWithContentsOfFile:] + 89
    frame #4: 0x0000000105a30b40 Foundation`+[NSDictionary(NSDictionary) newWithContentsOf:immutable:] + 101
    frame #5: 0x0000000105a5622a Foundation`+[NSDictionary(NSDictionary) dictionaryWithContentsOfFile:] + 45
    frame #6: 0x00000001043c4560 CoreData`-[NSManagedObjectModelBundle initWithPath:] + 224
    frame #7: 0x00000001043c42ed CoreData`-[NSManagedObjectModel initWithContentsOfURL:] + 205
    frame #8: 0x00000001040f723f CDProgress`-[AppDelegate managedObjectModel](self=0x00007fbe48c21f90, _cmd=0x000000010459b37b) + 223 at AppDelegate.m:127
    frame #9: 0x00000001040f7384 CDProgress`-[AppDelegate persistentStoreCoordinator](self=0x00007fbe48c21f90, _cmd=0x000000010459c1cb) + 228 at AppDelegate.m:142
    frame #10: 0x00000001040f708c CDProgress`-[AppDelegate managedObjectContext](self=0x00007fbe48c21f90, _cmd=0x0000000104598f0d) + 92 at AppDelegate.m:111
    frame #11: 0x00000001040f6bdb CDProgress`-[AppDelegate subTask](self=0x00007fbe48c21f90, _cmd=0x00000001040f7997) + 43 at AppDelegate.m:45
    frame #12: 0x00000001040f6b89 CDProgress`-[AppDelegate runTask](self=0x00007fbe48c21f90, _cmd=0x00000001040f7928) + 233 at AppDelegate.m:40
    frame #13: 0x00000001040f6a4b CDProgress`-[AppDelegate application:didFinishLaunchingWithOptions:](self=0x00007fbe48c21f90, _cmd=0x0000000104f5dba9, application=0x00007fbe48f00fb0, launchOptions=0x0000000000000000) + 571 at AppDelegate.m:26
    frame #14: 0x000000010477c5a5 UIKit`-[UIApplication _handleDelegateCallbacksWithOptions:isSuspended:restoreState:] + 234
    frame #15: 0x000000010477d0ec UIKit`-[UIApplication _callInitializationDelegatesForMainScene:transitionContext:] + 2463
    frame #16: 0x000000010477fe5c UIKit`-[UIApplication _runWithMainScene:transitionContext:completion:] + 1350
    frame #17: 0x000000010477ed22 UIKit`-[UIApplication workspaceDidEndTransaction:] + 179
    frame #18: 0x00000001088092a3 FrontBoardServices`__31-[FBSSerialQueue performAsync:]_block_invoke + 16
    frame #19: 0x000000010615fabc CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_BLOCK__ + 12
    frame #20: 0x0000000106155805 CoreFoundation`__CFRunLoopDoBlocks + 341
    frame #21: 0x00000001061555c5 CoreFoundation`__CFRunLoopRun + 2389
    frame #22: 0x0000000106154a06 CoreFoundation`CFRunLoopRunSpecific + 470
    frame #23: 0x000000010477e799 UIKit`-[UIApplication _run] + 413
    frame #24: 0x0000000104781550 UIKit`UIApplicationMain + 1282
    frame #25: 0x00000001040f7793 CDProgress`main(argc=1, argv=0x00007fff5bb09308) + 115 at main.m:16
    frame #26: 0x000000010686f145 libdyld.dylib`start + 1
(lldb) 

What's happening here is that when the model is loaded, it is reading a plist file. Reading the plist file calls -[NSData initWithContentsOfFile:], which is invoking +[NSProgress progressWithTotalUnitCount:] on the main thread. As the release notes point out, this will create an NSProgress that is a child of the current progress. initWithContentsOfFile: is actually doing this, and creating a new child of the NSProgress you created:

<NSProgress: 0x7f9353596f80> : Parent: 0x0 / Fraction completed: 0.0000 / Completed: 0 of 1  
   <_NSProgressGroup: 0x7f935601a0d0> : Portion of parent: 100 Children: 1
      <NSProgress: 0x7f935600bf50> : Parent: 0x7f9353596f80 / Fraction completed: 0.0000 / Completed: 0 of 0 

What's happening here is that additional work is being added in front of yours. At this point, it doesn't know anything about the additional work you are about to add. The child added by initWithContentsOfFile: completes, is dropped from the tree, and then you start adding your work.

The current progress starts at 0, and goes to 100%. You see 100% because your KVO options do not include NSKeyValueObservingOptionInitial.

NSData adds a child progress that starts at 0, and goes to 100%.

Your Core Data task adds a child that starts at 0 and (eventually) goes to 100%.

A key point here however is that you are using performBlockAndWait:. While the block itself runs on a private queue, this method will block the calling thread, which will delay your KVO notifications. performBlockAndWait: will also reuse the calling thread, if possible, which is something to be aware of.

If you edit your subTask method to wrap itself with an NSProgress to serve as the parent for the whole unit of work, resigning current at the end, you will probably get behavior closer to what you are expecting:

- (void)subTask {
    NSProgress  *progress   = [NSProgress progressWithTotalUnitCount:1];
    NSManagedObjectContext *parentContext = self.managedObjectContext;
    NSManagedObjectContext *bgContext = [[NSManagedObjectContext alloc]initWithConcurrencyType:NSPrivateQueueConcurrencyType];
    [bgContext setParentContext:parentContext];

    [progress becomeCurrentWithPendingUnitCount:1];
    [bgContext performBlock:^{

    ... stuff

    [progress resignCurrent];
}

NSProgress can be a little difficult to wrap your head around, but with some experience it becomes easier. I promise!

Answer 2

It appears there must be an NSProgress counter inside of [NSManagedObjectModel initWithContentsOfURL:]. Before entering [self subTask], you set yourself up to receive notifications on any progress indicators (by setting _progress as current and registering self to observe changes). Then inside that routine you call the lazy getter self.managedObjectContext, which in turn calls [NSManagedObjectModel initWithContentsOfURL:], which apparently has a 2-unit progress counter. It seems you need to be very careful where you place the calls to [NSProgress becomeCurrentWithPendingUnitCount:] and [NSProgress resignCurrent].