search

GrahamDennis / GDCoreDataConcurrencyDebugging

GDCoreDataConcurrencyDebugging helps you find cases where NSManagedObject's are being called on the wrong thread or dispatch queue.
MIT License
171 stars 23 forks source link

(false) positives with MagicalRecord? #20

Closed haemi closed 8 years ago

haemi commented 8 years ago

I'm using it together with MagicalRecord and do get lots and lots of the following log messages:

2015-11-06 07:41:49.959 ...[31123:10196439] Invalid concurrent access to managed object calling 'release'; Stacktrace: (
    0   ...                            0x000000010f324c64 ValidateConcurrency + 212
    1   ...                            0x000000010f3248ed CustomSubclassRelease + 29
    2   CoreFoundation                      0x0000000113156b6d -[__NSArrayM dealloc] + 157
    3   libobjc.A.dylib                     0x000000011419bafe _ZN11objc_object17sidetable_releaseEb + 232
    4   CoreData                            0x000000010fd2c718 -[NSInPredicateOperator(_NSCoreDataSQLPredicateCategories) minimalFormInContext:ofPredicate:] + 1000
    5   CoreData                            0x000000010fe36df6 -[NSSQLGenerator initializeContextForRequest:ignoreInheritance:nestingLevel:] + 486
    6   CoreData                            0x000000010fe36f94 -[NSSQLGenerator initializeContextForFetchRequest:ignoreInheritance:nestingLevel:nestIsWhereScoped:] + 36
    7   CoreData                            0x000000010fe37262 -[NSSQLGenerator newSQLStatementForRequest:ignoreInheritance:countOnly:nestingLevel:nestIsWhereScoped:] + 98

The code which produces this e.g. is the following:

        MagicalRecord.saveWithBlockAndWait({ (localContext) -> Void in
            MyCoreDataClass.MR_truncateAllInContext(localContext)
        })

This should be perfectly fine, right?

I include GDCoreDataConcurrencyDebugging with CococaPods:

pod "GDCoreDataConcurrencyDebugging", :git => 'git@github.com:GrahamDennis/GDCoreDataConcurrencyDebugging.git', :tag => '0.2', :configurations => ['Debug'], :submodules => true
GrahamDennis commented 8 years ago

Can you provide more of the stacktrace? I can't see from what you've provided what the issue is

GrahamDennis commented 8 years ago

Found the issue. It's a bug in MagicalRecord. NSManagedObjectContext+MagicalRecord.m's MR_executeFetchReqest:inContext: is fundamentally unsafe.

+ (NSArray *) MR_executeFetchRequest:(NSFetchRequest *)request inContext:(NSManagedObjectContext *)context
{
    __block NSArray *results = nil;
    [context performBlockAndWait:^{

        NSError *error = nil;

        results = [context executeFetchRequest:request error:&error];

        if (results == nil) 
        {
            [MagicalRecord handleErrors:error];
        }

    }];
    return results;  // you're holding on to references to objects that should only be accessed within performBlockAndWait.
}
GrahamDennis commented 8 years ago

Please file an issue against MagicalRecord.

GrahamDennis commented 8 years ago

Actually, maybe I spoke too soon. MR_executeFetchRequest:inContext: is unsafe unless it is called within [localContext performBlockAndWait:], which it is in this case.

inlined and in pseudocode it looks like:

NSManagedObjectContext *context;

[context performBlockAndWait:^{
    __block NSArray *objects;
    [context performBlockAndWait:^{
        objects = fetchObjectsFromContext(context);
   ];
   [context deleteObjects:objects];
];

which looks safe to me. It's possible GDCoreDataConcurrencyDebugging isn't picking up on the fact that there's a common dispatch queue between the two [context performBlockAndWait:] calls.

GrahamDennis commented 8 years ago

If that's the case, then the stack trace should be during the [context deleteObjects:objects]; operation.

Can you provide a more complete stacktrace please?

haemi commented 8 years ago

a complete stacktrace looks like this for example:

2015-11-06 13:45:24.931 testproj[62827:11662152] Invalid concurrent access to managed object calling 'release'; Stacktrace: (
    0   testproj                            0x0000000103121c64 ValidateConcurrency + 212
    1   testproj                            0x00000001031218ed CustomSubclassRelease + 29
    2   CoreFoundation                      0x0000000106f6fdad -[__NSDictionaryM dealloc] + 157
    3   libobjc.A.dylib                     0x0000000107f98afe _ZN11objc_object17sidetable_releaseEb + 232
    4   CoreData                            0x0000000103b6363f -[NSSQLCore obtainPermanentIDsForObjects:error:] + 2223
    5   CoreData                            0x0000000103c0ebe8 __87-[NSPersistentStoreCoordinator(_NSInternalMethods) obtainPermanentIDsForObjects:error:]_block_invoke + 888
    6   CoreData                            0x0000000103c14cad gutsOfBlockToNSPersistentStoreCoordinatorPerform + 189
    7   libdispatch.dylib                   0x0000000108aaa49b _dispatch_client_callout + 8
    8   libdispatch.dylib                   0x0000000108a8efb5 _dispatch_barrier_sync_f_invoke + 393
    9   CoreData                            0x0000000103c05da5 _perform + 197
    10  CoreData                            0x0000000103b620bd -[NSPersistentStoreCoordinator(_NSInternalMethods) obtainPermanentIDsForObjects:error:] + 653
    11  CoreData                            0x0000000103be675b __99-[NSManagedObjectContext(_NestedContextSupport) _parentObtainPermanentIDsForObjects:context:error:]_block_invoke + 987
    12  CoreData                            0x0000000103b6be94 internalBlockToNSManagedObjectContextPerform + 84
    13  libdispatch.dylib                   0x0000000108aaa49b _dispatch_client_callout + 8
    14  libdispatch.dylib                   0x0000000108a8efb5 _dispatch_barrier_sync_f_invoke + 393
    15  CoreData                            0x0000000103b6bd9f _perform + 223
    16  CoreData                            0x0000000103be61f6 -[NSManagedObjectContext(_NestedContextSupport) _parentObtainPermanentIDsForObjects:context:error:] + 454
    17  CoreData                            0x0000000103b61c6f -[NSManagedObjectContext obtainPermanentIDsForObjects:error:] + 895
    18  testproj                            0x0000000103171af6 -[NSManagedObjectContext(MagicalRecord) MR_contextWillSave:] + 390
    19  CoreFoundation                      0x000000010703c77c __CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__ + 12
    20  CoreFoundation                      0x000000010703c4bb _CFXRegistrationPost + 427
    21  CoreFoundation                      0x000000010703c222 ___CFXNotificationPost_block_invoke + 50
    22  CoreFoundation                      0x0000000107081a52 -[_CFXNotificationRegistrar find:object:observer:enumerator:] + 1986
    23  CoreFoundation                      0x0000000106f37859 _CFXNotificationPost + 633
    24  Foundation                          0x000000010429e1e9 -[NSNotificationCenter postNotificationName:object:userInfo:] + 66
    25  CoreData                            0x0000000103b4ff39 -[NSManagedObjectContext save:] + 217
    26  testproj                            0x000000010317248d __70-[NSManagedObjectContext(MagicalSaves) MR_saveWithOptions:completion:]_block_invoke21 + 77
    27  CoreData                            0x0000000103b6b937 developerSubmittedBlockToNSManagedObjectContextPerform + 199
    28  CoreData                            0x0000000103b6b7fe -[NSManagedObjectContext performBlockAndWait:] + 222
    29  testproj                            0x0000000103172334 -[NSManagedObjectContext(MagicalSaves) MR_saveWithOptions:completion:] + 1252
    30  testproj                            0x0000000103162459 __47+[MagicalRecord(Actions) saveWithBlockAndWait:]_block_invoke + 89
    31  CoreData                            0x0000000103b6b937 developerSubmittedBlockToNSManagedObjectContextPerform + 199
    32  libdispatch.dylib                   0x0000000108aaa49b _dispatch_client_callout + 8
    33  libdispatch.dylib                   0x0000000108a8efb5 _dispatch_barrier_sync_f_invoke + 393
    34  CoreData                            0x0000000103b6b81c -[NSManagedObjectContext performBlockAndWait:] + 252
    35  testproj                            0x0000000103162394 +[MagicalRecord(Actions) saveWithBlockAndWait:] + 244
    36  testproj                            0x0000000102fec81f _TZFC8testproj15MYJSONImporter20importCategoryModelsfMS0_FGSaCSo12NSDictionary_T_ + 479
    37  testproj                            0x0000000102e8089f _TFFZFC8testproj10MYBackend15getCategoryListFMS0_FT_T_U_FT_T_U_FTGSQCSo22AFHTTPRequestOperation_GSQPSs9AnyObject___T_ + 559
    38  testproj                            0x0000000102e7d423 _TTRXFo_oGSQCSo22AFHTTPRequestOperation_oGSQPSs9AnyObject___dT__XFo_iTGSQS__GSQPS0_____iT__ + 35
    39  testproj                            0x0000000102e7b1e1 _TPA__TTRXFo_oGSQCSo22AFHTTPRequestOperation_oGSQPSs9AnyObject___dT__XFo_iTGSQS__GSQPS0_____iT__1093 + 81
    40  testproj                            0x0000000102e7d457 _TTRXFo_iTGSQCSo22AFHTTPRequestOperation_GSQPSs9AnyObject____iT__XFo_oGSQS__oGSQPS0____dT__ + 39
    41  testproj                            0x0000000102e7d4a9 _TTRXFo_oGSQCSo22AFHTTPRequestOperation_oGSQPSs9AnyObject___dT__XFdCb_dGSQS__dGSQPS0____dT__ + 73
    42  testproj                            0x000000010302b648 __64-[AFHTTPRequestOperation setCompletionBlockWithSuccess:failure:]_block_invoke49 + 40
    43  libdispatch.dylib                   0x0000000108a89e5d _dispatch_call_block_and_release + 12
    44  libdispatch.dylib                   0x0000000108aaa49b _dispatch_client_callout + 8
    45  libdispatch.dylib                   0x0000000108a922af _dispatch_main_queue_callback_4CF + 1738
    46  CoreFoundation                      0x0000000106fd02e9 __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 9
    47  CoreFoundation                      0x0000000106f918a9 __CFRunLoopRun + 2073
    48  CoreFoundation                      0x0000000106f90e08 CFRunLoopRunSpecific + 488
    49  GraphicsServices                    0x000000010aed1ad2 GSEventRunModal + 161
    50  UIKit                               0x000000010525530d UIApplicationMain + 171
    51  testproj                            0x0000000102de9007 main + 119
    52  libdyld.dylib                       0x0000000108ade92d start + 1
)
GrahamDennis commented 8 years ago

Looking at the stack trace, it appears that symbol rebinding may have failed. Before the calls to dispatch_barrier_sync_f_invoke there should be calls to wrapper_dispatch_barrier_sync_f. Please try using the latest master branch of GDCoreDataConcurrencyDebugging. If symbol rebinding fails, it will fail an NSAssert check.

haemi commented 8 years ago

I do get an error there: (latest Xcode).

image

GrahamDennis commented 8 years ago

Whoops, my mistake. I've fixed this in the latest commit.

Can you share your test project?

haemi commented 8 years ago

I uploaded an example project to https://github.com/haemi/ConcurrencyDebugging

pronebird commented 8 years ago

Same goes for obtainPermanentIDsForObjects. I get bunch of errors but they do not seem like errors. Besides, if I understand it correctly, the message suggests that release was called... 

2015-11-08 15:24:35.651 MyApp[19057:2209074] Context 'My Context' is about to save: obtaining permanent IDs for 31 new inserted object(s).
2015-11-08 15:24:35.652 MyApp[19057:2209110] Invalid concurrent access to managed object calling 'release'; Stacktrace: (
    0   GDCoreDataConcurrencyDebugging      0x000000010e3c6604 ValidateConcurrency + 212
    1   GDCoreDataConcurrencyDebugging      0x000000010e3c628d CustomSubclassRelease + 29
    2   CoreFoundation                      0x0000000111c72ea8 -[__NSArrayI dealloc] + 72
    3   libobjc.A.dylib                     0x0000000111811afe _ZN11objc_object17sidetable_releaseEb + 232
    4   CoreData                            0x00000001112fe60e -[NSSQLCore obtainPermanentIDsForObjects:error:] + 2174
    5   CoreData                            0x00000001113a9be8 __87-[NSPersistentStoreCoordinator(_NSInternalMethods) obtainPermanentIDsForObjects:error:]_block_invoke + 888
    6   CoreData                            0x00000001113afcad gutsOfBlockToNSPersistentStoreCoordinatorPerform + 189
    7   libdispatch.dylib                   0x000000011256349b _dispatch_client_callout + 8
    8   libdispatch.dylib                   0x0000000112547fb5 _dispatch_barrier_sync_f_invoke + 393
    9   CoreData                            0x00000001113a0da5 _perform + 197
    10  CoreData                            0x00000001112fd0bd -[NSPersistentStoreCoordinator(_NSInternalMethods) obtainPermanentIDsForObjects:error:] + 653
    11  CoreData                            0x000000011138175b __99-[NSManagedObjectContext(_NestedContextSupport) _parentObtainPermanentIDsForObjects:context:error:]_block_invoke + 987
    12  CoreData                            0x0000000111306e94 internalBlockToNSManagedObjectContextPerform + 84
    13  libdispatch.dylib                   0x000000011256349b _dispatch_client_callout + 8
    14  libdispatch.dylib                   0x0000000112547fb5 _dispatch_barrier_sync_f_invoke + 393
    15  CoreData                            0x0000000111306d9f _perform + 223
    16  CoreData                            0x00000001113811f6 -[NSManagedObjectContext(_NestedContextSupport) _parentObtainPermanentIDsForObjects:context:error:] + 454
    17  CoreData                            0x00000001112fcc6f -[NSManagedObjectContext obtainPermanentIDsForObjects:error:] + 895
    18  MagicalRecord                       0x000000010e817d17 -[NSManagedObjectContext(MagicalRecord) MR_contextWillSave:] + 359

[...]
GrahamDennis commented 8 years ago

@haemi: That project is just a template Xcode project. Have you pushed all of your commits?

haemi commented 8 years ago

@GrahamDennis sorry, I hadn't - but now I pushed all the commits!

GrahamDennis commented 8 years ago

@haemi: Thanks for the test project. I've now fixed GDCoreDataConcurrencyDebugging and fixed the real concurrency bug in your project. Try removing the @autoreleasepool from my PR to see the error you get. It tracks it down pretty well.

haemi commented 8 years ago

hey, thanks a lot, looks much better now!

two questions regarding your changes to my test project:

GrahamDennis commented 8 years ago

I'll answer both by walking through the steps to diagnose this.

First, start with the state of your ConcurrencyDebugging project with the latest version of GDCoreDataConcurrencyDebugging, but without my PR adding the @autoreleasepool and GDCoreDataConcurrencyDebugging[Begin|End]TrackingAutorelease() calls.

1. Run the project.

You'll notice an invalid concurrent access with a stacktrace of:

2015-11-10 06:40:21.724 ConcurrencyDebugging[98721:5709601] If you want to break on invalid concurrent access, add a breakpoint on symbol BreakOnInvalidConcurrentAccess
2015-11-10 06:40:21.728 ConcurrencyDebugging[98721:5709601] Invalid concurrent access to managed object calling 'release'; Stacktrace: (
    0   ConcurrencyDebugging                0x0000000107fc4084 ValidateConcurrency + 212
    1   ConcurrencyDebugging                0x0000000107fc3d0d CustomSubclassRelease + 29
    2   libobjc.A.dylib                     0x00000001088a60b8 _ZN12_GLOBAL__N_119AutoreleasePoolPage3popEPv + 488
    3   FrontBoardServices                  0x000000010bb9278c -[FBSSerialQueue _performNext] + 200
    4   FrontBoardServices                  0x000000010bb92af2 -[FBSSerialQueue _performNextFromRunLoopSource] + 45
    5   CoreFoundation                      0x0000000108d44011 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17
    6   CoreFoundation                      0x0000000108d39f3c __CFRunLoopDoSources0 + 556
    7   CoreFoundation                      0x0000000108d393f3 __CFRunLoopRun + 867
    8   CoreFoundation                      0x0000000108d38e08 CFRunLoopRunSpecific + 488
    9   UIKit                               0x00000001091bf4f5 -[UIApplication _run] + 402
    10  UIKit                               0x00000001091c430d UIApplicationMain + 171
    11  ConcurrencyDebugging                0x0000000107fc215f main + 111
    12  libdyld.dylib                       0x000000010b66b92d start + 1
)

This is saying that an NSManagedObject was released by an autorelease pool outside of a [NSManagedObjectContext perform...:] call. This just means that when autorelease was called on the NSManagedObject, the closest autorelease pool was outside the perform...: call. 90%+ of the time this is benign (but still technically bad). Provided the NSManagedObjectContext retains a reference to the NSManagedObject, when the autorelease pool calls release, it won't trigger dealloc, and a dealloc running outside of a perform...: call would be bad. See http://www.grahamdennis.me/blog/2013/09/09/debugging-concurrency-with-core-data/ for a description of the other < 10% of times where this can lead to badness.

2. Finding the original autorelease message call.

The original autorelease message call is actually going to be a valid concurrent access. I can't figure out a way to identify live that the autorelease message will result in the object being placed on a pool that is outside of a perform...: call, so instead you can opt-in to tracking of all autorelease messages sent to NSManagedObjects. You don't want to enable this always because this feature carries a heavy performance penalty.

So if you now add GDCoreDataConcurrencyDebuggingBeginTrackingAutorelease() and GDCoreDataConcurrencyDebuggingEndTrackingAutorelease() around the suspicious code, we can track down the original autorelease message.

Run the project and you'll see a new error:

2015-11-10 06:50:54.143 ConcurrencyDebugging[98778:5729641] If you want to break on invalid concurrent access, add a breakpoint on symbol BreakOnInvalidConcurrentAccessOnRelease
2015-11-10 06:50:54.143 ConcurrencyDebugging[98778:5729641] Invalid concurrent access to object of class 'MyEntity_GDCoreDataConcurrencyDebugging_MyEntity_' caused by earlier autorelease.  The autorelease pool was drained outside of the appropriate context for some managed objects.  You need to add an @autoreleasepool{} directive to ensure this object is released within the NSManagedObject's queue.
Original autorelease backtrace: (
    "0   ConcurrencyDebugging                0x0000000103bc4c91 -[NSObject(AutoreleaseTracking) gd_autorelease] + 161",
    "1   ConcurrencyDebugging                0x0000000103bc4d9c CustomSubclassAutorelease + 76",
    "2   CoreData                            0x0000000103cd94ec -[NSManagedObjectContext existingObjectWithID:error:] + 252",
    "3   ConcurrencyDebugging                0x0000000103bd52f8 -[NSManagedObject(MagicalRecord) MR_deleteEntityInContext:] + 120",
    "4   ConcurrencyDebugging                0x0000000103bd59f2 +[NSManagedObject(MagicalRecord) MR_truncateAllInContext:] + 498",
    "5   ConcurrencyDebugging                0x0000000103bc2e16 __29-[ViewController viewDidLoad]_block_invoke_2 + 70",
    "6   ConcurrencyDebugging                0x0000000103bc7574 __47+[MagicalRecord(Actions) saveWithBlockAndWait:]_block_invoke + 132",
    "7   CoreData                            0x0000000103cf6937 developerSubmittedBlockToNSManagedObjectContextPerform + 199",
    "8   ConcurrencyDebugging                0x0000000103bc5e22 DispatchTargetFunctionWrapper + 210",
    "9   libdispatch.dylib                   0x000000010723849b _dispatch_client_callout + 8",
    "10  libdispatch.dylib                   0x000000010721cfb5 _dispatch_barrier_sync_f_invoke + 393",
    "11  ConcurrencyDebugging                0x0000000103bc5c9d DispatchSyncWrapper + 333",
    "12  ConcurrencyDebugging                0x0000000103bc5a50 wrapper_dispatch_sync_f + 48",
    "13  CoreData                            0x0000000103cf681c -[NSManagedObjectContext performBlockAndWait:] + 252",
    "14  ConcurrencyDebugging                0x0000000103bc7487 +[MagicalRecord(Actions) saveWithBlockAndWait:] + 263",
    "15  ConcurrencyDebugging                0x0000000103bc2d22 -[ViewController viewDidLoad] + 130",
    "16  UIKit                               0x0000000104f57cc4 -[UIViewController loadViewIfRequired] + 1198",
    "17  UIKit                               0x0000000104f58013 -[UIViewController view] + 27",
    "18  UIKit                               0x0000000104e3151c -[UIWindow addRootViewControllerViewIfPossible] + 61",
    "19  UIKit                               0x0000000104e31c05 -[UIWindow _setHidden:forced:] + 282",
    "20  UIKit                               0x0000000104e434a5 -[UIWindow makeKeyAndVisible] + 42",
    "21  UIKit                               0x0000000104dbd396 -[UIApplication _callInitializationDelegatesForMainScene:transitionContext:] + 4131",
    "22  UIKit                               0x0000000104dc39c3 -[UIApplication _runWithMainScene:transitionContext:completion:] + 1750",
    "23  UIKit                               0x0000000104dc0ba3 -[UIApplication workspaceDidEndTransaction:] + 188",
    "24  FrontBoardServices                  0x0000000107793784 -[FBSSerialQueue _performNext] + 192",
    "25  FrontBoardServices                  0x0000000107793af2 -[FBSSerialQueue _performNextFromRunLoopSource] + 45",
    "26  CoreFoundation                      0x0000000104945011 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17",
    "27  CoreFoundation                      0x000000010493af3c __CFRunLoopDoSources0 + 556",
    "28  CoreFoundation                      0x000000010493a3f3 __CFRunLoopRun + 867",
    "29  CoreFoundation                      0x0000000104939e08 CFRunLoopRunSpecific + 488",
    "30  UIKit                               0x0000000104dc04f5 -[UIApplication _run] + 402",
    "31  UIKit                               0x0000000104dc530d UIApplicationMain + 171",
    "32  ConcurrencyDebugging                0x0000000103bc315f main + 111",
    "33  libdyld.dylib                       0x000000010726c92d start + 1"
); Invalidly accessed objects: {(
    <MyEntity: 0x7f85ab43ad20> (entity: MyEntity; id: 0xd000000000300000 <x-coredata://5D4BAC8A-691F-4CC6-949E-B6F17860E62E/MyEntity/p12> ; data: <fault>)
)}

What we see here is that -[NSManagedObjectContext existingObjectWithID:error:] calls autorelease on the NSManagedObject that it returns. So we need to add an @autoreleasepool inside the performBlock...: method in -[ViewController viewDidLoad].

And this is the content of the pull request. Now run the code again and verify that the concurrent accesses are gone.

Now you can remove the calls to GDCoreDataConcurrencyDebugging[Begin|End]TrackingAutorelease() to make everything run faster again.

Summary

Really, it would be great if Apple added @autoreleasepools within CoreData performBlock... method calls. Failing that, it would be helpful if MagicalRecord did this so that its users don't need to think / worry about these kinds of issues.

tonyarnold commented 8 years ago

Failing that, it would be helpful if MagicalRecord did this so that its users don't need to think / worry about these kinds of issues

Happy to have a look at doing that if you think it will help, but I'd be concerned about doing this every time. Are there specific scenarios where you think an autorelease pool would be of benefit?