NSProgress strange behavior

Question

I have one big task, consisting of several subtasks. and I want to add a progress report for this big task.
for this I want to use NSProgress , and according to the class documentation I can do this kind of sub-tasking using its child mechanism.

So, to simplify it, let's say I have a big task consisting of one subtask (of course, in real life there would be more subtasks). So here is what I did:

 #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 the background context to run some code related to the master data, and the background context uses the main context as the parent context.
This leads to some strange KVO "fractionCompleted" progress.

this is 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, printing starts at 1.0, 0.5 and 1.0, and then goes to 0.66 ?!
from here it acts normally and goes to 1.0, as 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 this is happening? and how can i fix it?

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

Answer 1

The stack trace when this happens is as follows:

 (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 happens here when the model loads, it reads the plist file. Reading the plist file calls -[NSData initWithContentsOfFile:] , which calls +[NSProgress progressWithTotalUnitCount:] in the main thread. As the release notes indicate , this will create NSProgress, which is a child of the current progress. initWithContentsOfFile: actually does this and creates a new NSProgress child that 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 happens here, so that extra work is added to you. At the moment, he does not know anything about the extra work that you are going to add. Added child element added by initWithContentsOfFile: is removed from the tree and then you start adding your work.

Current progress starts at 0 and goes 100%. You see 100% because your KVO options do not include NSKeyValueObservingOptionInitial .

NSData adds a child’s progress that starts at 0 and goes 100%.

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

However, the key point is that you are using performBlockAndWait: Although the block itself runs in a private queue, this method blocks the calling thread, which delays your KVO notifications. performBlockAndWait: will also reuse the calling thread, if possible, to be aware of.

If you edit your subTask method to wrap yourself with NSProgress, which will serve as the parent for the entire unit of work, yielding the current value at the end, you will probably come closer to what you expect:

 - (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 harder to wrap around you, but with some experience it gets easier. I promise!

Answer 2

It seems that inside [NSManagedObjectModel initWithContentsOfURL:] should be an NSProgress counter. Before logging in to [self subTask] , you will be configured to receive notifications of any progress indicators (setting _progress as current and registering yourself to observe the changes). Then, inside this procedure, 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 when placing calls to [NSProgress becomeCurrentWithPendingUnitCount:] and [NSProgress resignCurrent] .