Hang on iOS7 when app goes to the background #164

PiranhaTodd · 2013-10-21T02:38:37Z

We recently noticed an app backgrounding hang in our app, and the culprit appears to be CBL. I'm still gathering info from our QE and other developers who have done some more digging, but I wanted to share what I currently know, in the interest of getting the conversation started.

Some background info… We're primarily an iPad only app at the moment. We've committed to supporting iOS7 only in our initial release (submitting to Apple next month!). We support multiple CBL databases open at the same time, each with a replication to a Cloudant server. Our replications are continuous, bi-directional, and NON-persistent.

If we have a database open, and an active replication going on that database, hitting the home button on the iPad, and then switching back to our app, it will be hung in the main thread. Pausing the debugger yields the following backtrace:

* thread #1: tid = 0x7f9cb, 0x39572fa8 libsystem_kernel.dylib`__psynch_mutexwait + 24, queue = 'com.apple.main-thread, stop reason = signal SIGSTOP
    frame #0: 0x39572fa8 libsystem_kernel.dylib`__psynch_mutexwait + 24
    frame #1: 0x395d9f0e libsystem_pthread.dylib`_pthread_mutex_lock + 306
    frame #2: 0x39445656 libcache.dylib`cache_remove_all + 34
    frame #3: 0x39445792 libcache.dylib`cache_destroy + 50
    frame #4: 0x2e836560 CoreFoundation`-[NSCache dealloc] + 60
    frame #5: 0x38fbfb0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #6: 0x00b00740 Hammersmith`-[CBLCache .cxx_destruct](self=0x176cd3b0, _cmd=0x00000000) + 44 at CBLCache.m:22
    frame #7: 0x38fb3c18 libobjc.A.dylib`object_cxxDestructFromClass(objc_object*, objc_class*) + 128
    frame #8: 0x38fb0c36 libobjc.A.dylib`objc_destructInstance + 34
    frame #9: 0x38fb0e0a libobjc.A.dylib`object_dispose + 14
    frame #10: 0x38fbfb0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #11: 0x00affa38 Hammersmith`-[CBLDatabase .cxx_destruct](self=0x176cb1c0, _cmd=0x00000000) + 96 at CBLDatabase.m:38
    frame #12: 0x38fb3c18 libobjc.A.dylib`object_cxxDestructFromClass(objc_object*, objc_class*) + 128
    frame #13: 0x38fb0c36 libobjc.A.dylib`objc_destructInstance + 34
    frame #14: 0x38fb0e0a libobjc.A.dylib`object_dispose + 14
    frame #15: 0x00afd600 Hammersmith`-[CBLDatabase dealloc](self=0x176cb1c0, _cmd=0x31603ed4) + 224 at CBLDatabase.m:82
    frame #16: 0x38fbfb0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #17: 0x00afaf76 Hammersmith`-[CBLDocument .cxx_destruct](self=0x176cd390, _cmd=0x00000000) + 114 at CBLDocument.m:18
    frame #18: 0x38fb3c18 libobjc.A.dylib`object_cxxDestructFromClass(objc_object*, objc_class*) + 128
    frame #19: 0x38fb0c36 libobjc.A.dylib`objc_destructInstance + 34
    frame #20: 0x38fb0e0a libobjc.A.dylib`object_dispose + 14
    frame #21: 0x38fbfb0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #22: 0x2e7de714 CoreFoundation`CFRelease + 556
    frame #23: 0x394461ec libcache.dylib`_value_entry_remove + 140
    frame #24: 0x39445582 libcache.dylib`_entry_remove + 198
    frame #25: 0x39445730 libcache.dylib`cache_remove_with_block + 132
    frame #26: 0x2e7e6834 CoreFoundation`__CFNotificationCenterAddObserver_block_invoke + 124
    frame #27: 0x2e870120 CoreFoundation`__CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__ + 12
    frame #28: 0x2e7e4316 CoreFoundation`_CFXNotificationPost + 1718
    frame #29: 0x2f1c8dcc Foundation`-[NSNotificationCenter postNotificationName:object:userInfo:] + 76
    frame #30: 0x310a3040 UIKit`-[UIApplication _handleApplicationSuspend:eventInfo:] + 908
    frame #31: 0x31023d68 UIKit`-[UIApplication handleEvent:withNewEvent:] + 764
    frame #32: 0x310239a8 UIKit`-[UIApplication sendEvent:] + 72
    frame #33: 0x310894fc UIKit`_UIApplicationHandleEvent + 664
    frame #34: 0x334d070c GraphicsServices`_PurpleEventCallback + 608
    frame #35: 0x2e87918a CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 14
    frame #36: 0x2e87865a CoreFoundation`__CFRunLoopDoSources0 + 206
    frame #37: 0x2e876e4e CoreFoundation`__CFRunLoopRun + 622
    frame #38: 0x2e7e1ce6 CoreFoundation`CFRunLoopRunSpecific + 522
    frame #39: 0x2e7e1aca CoreFoundation`CFRunLoopRunInMode + 106
    frame #40: 0x334cf282 GraphicsServices`GSEventRunModal + 138
    frame #41: 0x31083a40 UIKit`UIApplicationMain + 1136
    frame #42: 0x000a70ea Hammersmith`main(argc=9, argv=0x27d6bbf8) + 46 at main.m:14
    frame #43: 0x0009d650 Hammersmith`start + 40

Note that CBLDatabase dealloc is called.

Our QE believes this issue occurs only on iOS7. It's not convenient for me to verify this wasn't a problem in iOS6, as all my devices are on iOS7 now.

I believe the issue started between July 30 and August 22. Note that during that time, most of our team was still using iOS6, so we would not have noticed this issue when it was first introduced. The most likely suspect commit was (submitted August 15):
89ec01d

I did some digging, and these GitHub issues were previously resolved, but seemed related:
#120
#96

And this one from TouchDB:
https://github.com/couchbaselabs/TouchDB-iOS/issues/216

Please let me know if you need more info.

Thanks,
-Todd

The text was updated successfully, but these errors were encountered:

snej · 2013-10-21T18:50:25Z

Ugh. Yes, this definitely seems like a similar situation to couchbaselabs/TouchDB-iOS#216, in which an NSCache is releasing content objects, one of which turns around and releases/deallocs the cache itself, causing a deadlock.

In this case, a CBLDocument is being released from a cache and dealloced, which causes its CBLDatabase to lose its last reference and be dealloced, which causes the CBLDatabase's cache to be dealloced.

snej · 2013-10-21T19:17:22Z

You should be able to work around this by keeping a reference to one of the objects that gets dealloced in the above scenario. The only database I can think of that wouldn't have any references to it is the _replicator database in your app's main context. It only gets instantiated implicitly by your accessing CBLReplication objects owned by it. Ordinarily you'd be keeping references to replication objects so you can get notifications from them, but maybe you dropped those references when the app went into the background? In that case the workaround would be to keep references to the CBLReplication objects even if you're not using them anymore.

If you can get this to reproduce while hooked up to Xcode, it would be very interesting to find out the identities of the CBLDocument and CBLDatabase appearing in the backtrace (frames 17 and 15).

xcvista · 2013-10-22T05:38:17Z

Created pull request (bug #165) to try to fix this, by postponing releasing of the NSCache object, hopefully breaking the mux loop.

PiranhaTodd · 2013-10-22T20:29:07Z

@snej
I'm having a difficult time repro'ing this issue today (of course). But I can answer some of your questions.

You're right that we don't do anything explicitly with the _replicator database. When a replication is active, that is to say that when we create and start a replication, we hold a reference to it until it is explicitly stopped by us, which is to say that we no longer need that database to be replicated. And when the app goes to the background, we are not explicitly stopping our replications. So, I am confident that references to CBLReplication's are not being dropped in this case.

One other note: When handling applicationDidEnterBackground, we do a flush of any changes to our data model, forcing a putProperties on the corresponding CBLDocument(s). I think I mentioned in the past that we don't use CBLModel. But that is all we do when our app goes to the background. Not sure if that could be causing an issue.

Once I'm able to repro, I'll try to determine which document and database are hanging.

PiranhaTodd · 2013-10-22T20:31:04Z

@xcvista
We tried your fix (a different dev on our team, since I can't seem to repro today), and the issue persists. The backtrace is slightly different though:

* thread #1: tid = 0x284c99, 0x3bb44fa8 libsystem_kernel.dylib`__psynch_mutexwait + 24, queue = 'com.apple.main-thread, stop reason = signal SIGSTOP
    frame #0: 0x3bb44fa8 libsystem_kernel.dylib`__psynch_mutexwait + 24
    frame #1: 0x3bbabf0e libsystem_pthread.dylib`_pthread_mutex_lock + 306
    frame #2: 0x3ba17656 libcache.dylib`cache_remove_all + 34
    frame #3: 0x3ba17792 libcache.dylib`cache_destroy + 50
    frame #4: 0x30d00560 CoreFoundation`-[NSCache dealloc] + 60
    frame #5: 0x3b591b0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #6: 0x00af517c Hammersmith`-[CBLCache .cxx_destruct](self=0x146f8770, _cmd=0x00000000) + 44 at CBLCache.m:29
    frame #7: 0x3b585c18 libobjc.A.dylib`object_cxxDestructFromClass(objc_object*, objc_class*) + 128
    frame #8: 0x3b582c36 libobjc.A.dylib`objc_destructInstance + 34
    frame #9: 0x3b582e0a libobjc.A.dylib`object_dispose + 14
    frame #10: 0x00af4bac Hammersmith`-[CBLCache dealloc](self=0x146f8770, _cmd=0x33acded4) + 116 at CBLCache.m:73
    frame #11: 0x3b591b0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #12: 0x00af43fc Hammersmith`-[CBLDatabase .cxx_destruct](self=0x145d23b0, _cmd=0x00000000) + 96 at CBLDatabase.m:38
    frame #13: 0x3b585c18 libobjc.A.dylib`object_cxxDestructFromClass(objc_object*, objc_class*) + 128
    frame #14: 0x3b582c36 libobjc.A.dylib`objc_destructInstance + 34
    frame #15: 0x3b582e0a libobjc.A.dylib`object_dispose + 14
    frame #16: 0x00af2160 Hammersmith`-[CBLDatabase dealloc](self=0x145d23b0, _cmd=0x33acded4) + 224 at CBLDatabase.m:82
    frame #17: 0x3b591b0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #18: 0x00aefb6a Hammersmith`-[CBLDocument .cxx_destruct](self=0x146f8750, _cmd=0x00000000) + 114 at CBLDocument.m:18
    frame #19: 0x3b585c18 libobjc.A.dylib`object_cxxDestructFromClass(objc_object*, objc_class*) + 128
    frame #20: 0x3b582c36 libobjc.A.dylib`objc_destructInstance + 34
    frame #21: 0x3b582e0a libobjc.A.dylib`object_dispose + 14
    frame #22: 0x3b591b0a libobjc.A.dylib`objc_object::sidetable_release(bool) + 174
    frame #23: 0x30ca8714 CoreFoundation`CFRelease + 556
    frame #24: 0x3ba181ec libcache.dylib`_value_entry_remove + 140
    frame #25: 0x3ba17582 libcache.dylib`_entry_remove + 198
    frame #26: 0x3ba17730 libcache.dylib`cache_remove_with_block + 132
    frame #27: 0x30cb0834 CoreFoundation`__CFNotificationCenterAddObserver_block_invoke + 124
    frame #28: 0x30d3a120 CoreFoundation`__CFNOTIFICATIONCENTER_IS_CALLING_OUT_TO_AN_OBSERVER__ + 12
    frame #29: 0x30cae316 CoreFoundation`_CFXNotificationPost + 1718
    frame #30: 0x31692dcc Foundation`-[NSNotificationCenter postNotificationName:object:userInfo:] + 76
    frame #31: 0x3356cf22 UIKit`-[UIApplication _handleApplicationSuspend:eventInfo:] + 622
    frame #32: 0x334edd68 UIKit`-[UIApplication handleEvent:withNewEvent:] + 764
    frame #33: 0x334ed9a8 UIKit`-[UIApplication sendEvent:] + 72
    frame #34: 0x335534fc UIKit`_UIApplicationHandleEvent + 664
    frame #35: 0x359a770c GraphicsServices`_PurpleEventCallback + 608
    frame #36: 0x359a72f6 GraphicsServices`PurpleEventCallback + 34
    frame #37: 0x30d429e6 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE1_PERFORM_FUNCTION__ + 34
    frame #38: 0x30d42982 CoreFoundation`__CFRunLoopDoSource1 + 346
    frame #39: 0x30d41156 CoreFoundation`__CFRunLoopRun + 1398
    frame #40: 0x30cabce6 CoreFoundation`CFRunLoopRunSpecific + 522
    frame #41: 0x30cabaca CoreFoundation`CFRunLoopRunInMode + 106
    frame #42: 0x359a6282 GraphicsServices`GSEventRunModal + 138
    frame #43: 0x3354da40 UIKit`UIApplicationMain + 1136
    frame #44: 0x0008d3f6 Hammersmith`main(argc=1, argv=0x27d87c64) + 46 at main.m:14
    frame #45: 0x00083960 Hammersmith`start + 40

xcvista · 2013-10-23T02:52:34Z

Modified my pull request zeroing out the _cache variable. Try again please.

PiranhaTodd · 2013-10-23T17:01:04Z

@xcvista
We tried again, but still not fixed with your latest change.

@snej
I think we've narrowed this issue down to the following circumstances. In short, if you delete a database locally on the device, and then attempt to pull replicate a database from a remote server to the device, with the same database name, things will appear rosy at first, but there is a high probability that when the app goes into the background, it will hang.

I can give you the long version, if you want it. But figured I'd start there. You should be able to repro this now.

snej · 2013-10-23T19:08:14Z

Thanks, that helped. There's some stuff that's not getting torn down properly when a CBLDatabase is deleted, and so it stays around in memory until the app's cache-purging breaks some link cycles. If I fix that, this situation won't occur so you won't hang. Working on it right now.

PiranhaTodd · 2013-10-28T04:06:21Z

Just to follow up, Jens' fix indeed fixed this issue.

-Todd

snej closed this as completed in a62f2d6 Oct 23, 2013

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Hang on iOS7 when app goes to the background #164

Hang on iOS7 when app goes to the background #164

PiranhaTodd commented Oct 21, 2013

snej commented Oct 21, 2013

snej commented Oct 21, 2013

xcvista commented Oct 22, 2013

PiranhaTodd commented Oct 22, 2013

PiranhaTodd commented Oct 22, 2013

xcvista commented Oct 23, 2013

PiranhaTodd commented Oct 23, 2013

snej commented Oct 23, 2013

PiranhaTodd commented Oct 28, 2013

Hang on iOS7 when app goes to the background #164

Hang on iOS7 when app goes to the background #164

Comments

PiranhaTodd commented Oct 21, 2013

snej commented Oct 21, 2013

snej commented Oct 21, 2013

xcvista commented Oct 22, 2013

PiranhaTodd commented Oct 22, 2013

PiranhaTodd commented Oct 22, 2013

xcvista commented Oct 23, 2013

PiranhaTodd commented Oct 23, 2013

snej commented Oct 23, 2013

PiranhaTodd commented Oct 28, 2013