Core Data poor performance on save: and [UITableView endUpdates]

Question

I am having some performance issues with Core Data and I was hoping someone could give me some tips on how to improve it. When calling save: for my NSManagedObjectContext, I am experiencing save times of over 1 second for a single entity. I am performing the save on the main thread, so it is locking up the GUI during that time, which is unacceptable. Here is my code that is doing the save; this code is initiated after modifying a 'description' field for a WTSRecord:

- (void)saveRecord:(WTSRecord *)record
           success:(void (^)(WTSRecord *record))success
           failure:(void (^)(NSError *error))failure {
    DDLogVerbose(@"saveRecord: %@", record.objectID);

    if (record.recordId != nil) {
        //mark this record as a pending modify if it has a database id
        record.pendingModify = [NSNumber numberWithBool:YES];
    }
    NSError *error;
    NSManagedObjectContext *context = record.managedObjectContext;
    NSTimeInterval startTime = [[NSDate date] timeIntervalSince1970];
    if (![context saveToPersistentStore:&error]) {
        failure(error);
    } else {
        NSLog(@"time to persist record: %f", ([[NSDate date] timeIntervalSince1970] - startTime));

        ...do other stuff here...

    }
}

I turned on SQL debug, and Core Data is just updating one record and doesn't appear to be doing anything out of the ordinary:

2014-08-13 11:25:32.528 Identify[5395:60b] CoreData: sql: BEGIN EXCLUSIVE
2014-08-13 11:25:32.530 Identify[5395:60b] CoreData: sql: UPDATE ZWTSRECORD SET ZDESC = ?, Z_OPT = ?  WHERE Z_PK = ? AND Z_OPT = ?
2014-08-13 11:25:32.531 Identify[5395:60b] CoreData: details: SQLite bind[0] = "ffffffffffffuuuuiiiiuu"
2014-08-13 11:25:32.532 Identify[5395:60b] CoreData: details: SQLite bind[1] = (int64)48
2014-08-13 11:25:32.533 Identify[5395:60b] CoreData: details: SQLite bind[2] = (int64)306
2014-08-13 11:25:32.534 Identify[5395:60b] CoreData: details: SQLite bind[3] = (int64)47
2014-08-13 11:25:32.535 Identify[5395:60b] CoreData: sql: COMMIT
2014-08-13 11:25:32.538 Identify[5395:60b] time to persist record: 1.376321

This seems like a very simple update and really shouldn't take that long. There are around 40 WTSRecords in the sqllite database in this scenario. If I delete the sqllite store and am just modifying one WTSRecord, the time to persist is less than a 1/20th of a second.

I saw this post on cocoanetics about asynchronous saving, but I just want to know first if I am doing something fundamentally wrong before I go down that route. Thanks in advance!

EDIT 1:

Attached is a screenshot of the Time Profiler. It looks like a 1.3 seconds is dedicated to running the controllerDidChangeContent: in my UITableViewController, which is drawing table view cells. Why would this be taking that long??

Time Profiler

EDIT 2

Here are my NSFetchedResultsControllerDelegate methods. They didn't really change from the boilerplate Apple code:

- (void)controllerWillChangeContent:(NSFetchedResultsController *)controller
{
    DDLogVerbose(@"FRC calling beginUpdates in controllerWillChangeContent");
    [self.tableView beginUpdates];
    DDLogVerbose(@"FRC done calling beginUpdates in controllerWillChangeContent");
}

- (void)controller:(NSFetchedResultsController *)controller didChangeSection:(id <NSFetchedResultsSectionInfo>)sectionInfo
           atIndex:(NSUInteger)sectionIndex forChangeType:(NSFetchedResultsChangeType)type
{
    switch(type) {
        case NSFetchedResultsChangeInsert:
            DDLogVerbose(@"FRC inserted section");
            [self.tableView insertSections:[NSIndexSet indexSetWithIndex:sectionIndex] withRowAnimation:UITableViewRowAnimationFade];
            break;

        case NSFetchedResultsChangeDelete:
            DDLogVerbose(@"FRC deleted section");
            [self.tableView deleteSections:[NSIndexSet indexSetWithIndex:sectionIndex] withRowAnimation:UITableViewRowAnimationFade];
            break;
    }
}

- (void)controller:(NSFetchedResultsController *)controller didChangeObject:(id)anObject
       atIndexPath:(NSIndexPath *)indexPath forChangeType:(NSFetchedResultsChangeType)type
      newIndexPath:(NSIndexPath *)newIndexPath
{
    UITableView *tableView = self.tableView;

    switch(type) {
        case NSFetchedResultsChangeInsert:
            DDLogVerbose(@"FRC inserted object");
            [tableView insertRowsAtIndexPaths:@[newIndexPath] withRowAnimation:UITableViewRowAnimationFade];
            break;

        case NSFetchedResultsChangeDelete:
            DDLogVerbose(@"FRC deleted object");
            [tableView deleteRowsAtIndexPaths:@[indexPath] withRowAnimation:UITableViewRowAnimationFade];
            break;

        case NSFetchedResultsChangeUpdate:
            DDLogVerbose(@"FRC updated object");
            [self configureCell:[tableView cellForRowAtIndexPath:indexPath] atIndexPath:indexPath];
            break;

        case NSFetchedResultsChangeMove:
            DDLogVerbose(@"FRC moved objects");
            [tableView deleteRowsAtIndexPaths:@[indexPath] withRowAnimation:UITableViewRowAnimationFade];
            [tableView insertRowsAtIndexPaths:@[newIndexPath] withRowAnimation:UITableViewRowAnimationFade];
            break;
    }
}

- (void)controllerDidChangeContent:(NSFetchedResultsController *)controller
{
    DDLogVerbose(@"FRC calling endUpdates in controllerDidChangeContent");
    [self.tableView endUpdates];
    DDLogVerbose(@"FRC done calling endUpdates in controllerDidChangeContent");
}

I added in some printouts and found that the vast majority of the time is spent in [self.tableView endUpdates]. Here is a printout of my logs:

2014-08-14 10:44:39:663 Identify[5718:60b] Saving to context(<NSManagedObjectContext: 0x145b82c0>)
2014-08-14 10:44:39:666 Identify[5718:60b] FRC calling beginUpdates in controllerWillChangeContent
2014-08-14 10:44:39:666 Identify[5718:60b] FRC done calling beginUpdates in controllerWillChangeContent
2014-08-14 10:44:39:668 Identify[5718:60b] FRC updated object
**2014-08-14 10:44:39:671 Identify[5718:60b] FRC calling endUpdates in controllerDidChangeContent
**2014-08-14 10:44:40:889 Identify[5718:60b] FRC done calling endUpdates in controllerDidChangeContent
2014-08-14 10:44:41:018 Identify[5718:60b] Time to save in context(<NSManagedObjectContext: 0x145b82c0>): 1.355229

What does Instruments Time Profiler show? That is the first step to seeing what is taking up the time. I would suspect it is a UI reaction to the save. — Marcus S. Zarra, Aug 13 '14 at 18:12
Thanks for the suggestion Marcus. Please see EDIT 1. Apparently all of the time is spent drawing/animating table view cells in my list view controller... — Dan, Aug 14 '14 at 14:14
@Dan Do you want to update the question title, add the relevant code, etc. ? — A-Live, Aug 14 '14 at 14:54
Added FRC delegate code and printlns from it. All of the time is spent in `[UITableView endUpdates]` — Dan, Aug 14 '14 at 15:04

score 2 · Answer 1 · answered Aug 14 '14 at 16:06

Now that you have determined that your issue is not with your save but with your drawing code there are some options.

Dig into your cell code and see what is taking so long. Calculating something? Drawing alpha?
Move your save off the main queue.

Option 2 does not solve your re-draw problem but it will reduce your save time. You can do this by putting a private MOC between your main MOC and the PSC. Then the saves are off the main queue. However your drawing code is still going to block.

I would drill into each cell and see what is going on. Use instruments to open up the source code and find out what lines of code are expensive then explore why. Alpha drawing is a common problem. Image loading, etc. can also be a hit.

score 2 · Accepted Answer · edited May 23 '17 at 10:26

OK, I think I figured it out. The solution involved two parts:

This post on stackoverflow helped me out a lot. Apparently there is a performance problem with auto layout and drawing offscreen. My UITableViewController that was having the performance problems with [tableView endUpdates] was offscreen when the FRC was being fired. I added the following code to viewWillAppear and the NSFetchedResultsControllerDelegate methods. I used BOOL properties to flag when the table view needs refreshing or the fetched results controller needs to be executed (which I found needs to happen on deletes):

- (void)viewWillAppear:(BOOL)animated {
    [super viewWillAppear:animated];
    if (self.needsFetch) {
        self.needsFetch = NO;
        [self.fetchedResultsController performFetch:nil];
    }
    if (self.needsReload) {
        self.needsReload = NO;
        [self.tableView reloadData];
    }
}

- (void)controllerWillChangeContent:(NSFetchedResultsController *)controller
{
    //don't update the table view if it isn't being displayed
    if (!self.tableView.window) {
        self.needsReload = YES;
        return;
    }

    DDLogVerbose(@"FRC calling beginUpdates in controllerWillChangeContent.  results list controller type: %i", self.type);
    [self.tableView beginUpdates];
    DDLogVerbose(@"FRC done calling beginUpdates in controllerWillChangeContent");
}

- (void)controller:(NSFetchedResultsController *)controller didChangeObject:(id)anObject
       atIndexPath:(NSIndexPath *)indexPath forChangeType:(NSFetchedResultsChangeType)type
      newIndexPath:(NSIndexPath *)newIndexPath
{
    //don't update the table view if it isn't being displayed
    if (!self.tableView.window) {
        if (type == NSFetchedResultsChangeDelete) {
            NSLog(@"setting needs fetch");
            self.needsFetch = YES;
        }
        return;
    }

    UITableView *tableView = self.tableView;
    ...same as before...
}


OTHER FRC DELEGATE FUNCTIONS NEED WINDOW NULL CHECK ALSO

I also improved the way I was calling [NSManagedObjectContext saveToPersistentStore]. That method is part of RestKit's NSManagedObjectContext category, and in it I saw that they were performing the save operations in their own block and waiting, regardless if a NSManagedObjectContext is running in it's own private queue (RestKit by default sets up parent/child contexts with the one writing to the persistent store of type NSPrivateQueueConcurrencyType) After carefully reading through this post, I constructed this method in my own NSManagedObjectContext category that will perform the Core Data saves asynchronously with a block callback:

- (void)saveToPersistentStoreAsync:(void (^)(NSError *error))block {
    [self performBlock:^{
        DDLogVerbose(@"Saving to context(%@)", self);
        NSTimeInterval startTime = [[NSDate date] timeIntervalSince1970];
        NSError *error;
        if (![self save:&error]) {
            if (block) {
                dispatch_async(dispatch_get_main_queue(), ^{
                    block(error);
                });
            }
        } else {
            DDLogVerbose(@"Time to save in context(%@): %f", self, ([[NSDate date] timeIntervalSince1970] - startTime));
            if (self.parentContext) {
                [self.parentContext saveToPersistentStoreAsync:block];
            } else {
                if (block) {
                    dispatch_async(dispatch_get_main_queue(), ^{
                        block(nil);
                    });
                }
            }
        }
    }];
}

All in all, my UI is MUCH more responsive after both of these changes. I'm hoping I didn't do anything that'll cause some sort of a race condition in the future, but here's hoping this will work for me!

This is a great solution, but for some reason when I implement it the tableview reloadData is animated... do you find the same thing or is this a problem specific to my code? — SAHM, Oct 11 '14 at 19:29

Core Data poor performance on save: and [UITableView endUpdates]

2 Answers2