Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP

Loading…

CouchUITableSource table scrolling locks up during sync #182

Closed
tleyden opened this Issue · 14 comments

2 participants

@tleyden
Owner

When our app is doing a large sync with the CouchDB server we are seeing the scrolling on the table repeatedly lock up for up to 5 to 10 seconds while the sync is in progress. Once the sync finishes, the table scrolling goes back to normal. In our case "doing a large sync" means touching the 1000 objects that it's displaying in the table view.

We are using a CouchUITableSource with fairly large json objects (approx 20-50K each). There is a two way persistent / continuous replication setup with our upstream Couch Server.

If I pause the app while its locked up, the most common place I see the main thread blocked is on -[RESTOperation wait] + 296 at RESTOperation.m:186

Here is the full backtrace:

(lldb) bt
* thread #1: tid = 0x1c03, 0x986837d2 libsystem_kernel.dylib`mach_msg_trap + 10, stop reason = signal SIGSTOP
frame #0: 0x986837d2 libsystem_kernel.dylib`mach_msg_trap + 10
frame #1: 0x98682cb0 libsystem_kernel.dylib`mach_msg + 68
frame #2: 0x03afaa49 CoreFoundation`__CFRunLoopServiceMachPort + 185
frame #3: 0x03aff8d4 CoreFoundation`__CFRunLoopRun + 1380
frame #4: 0x03afef44 CoreFoundation`CFRunLoopRunSpecific + 276
frame #5: 0x03afee1b CoreFoundation`CFRunLoopRunInMode + 123
frame #6: 0x02284c7c Foundation`-[NSRunLoop(NSRunLoop) runMode:beforeDate:] + 298
frame #7: 0x001e7b18 Associate`-[RESTOperation wait] + 296 at RESTOperation.m:186
frame #8: 0x001dc054 Associate`-[CouchRevision properties] + 116 at CouchRevision.m:132
frame #9: 0x001dc5d7 Associate`-[CouchRevision propertyForKey:] + 55 at CouchRevision.m:164
frame #10: 0x001da113 Associate`-[CouchDocument propertyForKey:] + 83 at CouchDocument.m:244
frame #11: 0x001fad5f Associate`-[CouchModel getValueOfProperty:] + 207 at CouchModel.m:324
frame #12: 0x001f6cd7 Associate`__53+[CouchDynamicObject impForGetterOfProperty:ofClass:]_block_invoke_0 + 55 at CouchDynamicObject.m:237
frame #13: 0x000534fe Associate`-[SGCustomersViewController couchTableSource:cellForRowAtIndexPath:] + 398 at SGCustomersViewController.m:197
frame #14: 0x03950705 libobjc.A.dylib`-[NSObject performSelector:withObject:withObject:] + 77
frame #15: 0x001f271f Associate`-[CouchUITableSource tellDelegate:withObject:] + 159 at CouchUITableSource.m:80
frame #16: 0x001f2cc0 Associate`-[CouchUITableSource tableView:cellForRowAtIndexPath:] + 80 at CouchUITableSource.m:165
frame #17: 0x0271df4b UIKit`-[UITableView(UITableViewInternal) _createPreparedCellForGlobalRow:withIndexPath:] + 412
frame #18: 0x0271e01f UIKit`-[UITableView(UITableViewInternal) _createPreparedCellForGlobalRow:] + 69
frame #19: 0x0270680b UIKit`-[UITableView(_UITableViewPrivate) _updateVisibleCellsNow:] + 1863
frame #20: 0x0271719b UIKit`-[UITableView layoutSubviews] + 241
frame #21: 0x026b392d UIKit`-[UIView(CALayerDelegate) layoutSublayersOfLayer:] + 279
frame #22: 0x039506b0 libobjc.A.dylib`-[NSObject performSelector:withObject:] + 70
frame #23: 0x0069dfc0 QuartzCore`-[CALayer layoutSublayers] + 240
frame #24: 0x0069233c QuartzCore`CA::Layer::layout_if_needed(CA::Transaction*) + 468
frame #25: 0x00692150 QuartzCore`CA::Layer::layout_and_display_if_needed(CA::Transaction*) + 26
frame #26: 0x006100bc QuartzCore`CA::Context::commit_transaction(CA::Transaction*) + 324
frame #27: 0x00611227 QuartzCore`CA::Transaction::commit() + 395
frame #28: 0x006bb333 QuartzCore`CA::Display::DisplayLink::dispatch(unsigned long long, unsigned long long) + 207
frame #29: 0x006bb75f QuartzCore`CA::Display::TimerDisplayLink::callback(__CFRunLoopTimer*, void*) + 161
frame #30: 0x03b18376 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_TIMER_CALLBACK_FUNCTION__ + 22
frame #31: 0x03b17e06 CoreFoundation`__CFRunLoopDoTimer + 534
frame #32: 0x03affa82 CoreFoundation`__CFRunLoopRun + 1810
frame #33: 0x03afef44 CoreFoundation`CFRunLoopRunSpecific + 276
frame #34: 0x03afee1b CoreFoundation`CFRunLoopRunInMode + 123
frame #35: 0x053b77e3 GraphicsServices`GSEventRunModal + 88
frame #36: 0x053b7668 GraphicsServices`GSEventRun + 104
frame #37: 0x0266365c UIKit`UIApplicationMain + 1211
frame #38: 0x00003049 Associate`main + 169 at main.m:16

When I test on the device pointed to a remote server, and grep the logs, I can see that RESTOperations are being blocked by as much as 4 seconds.

2012-11-07 10:36:04.698 Associate[1280:907] REST: Blocked for 4404.8 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc107ac?rev=4-3baeb4ababf6f82dbeefacf9dd6b36f1]
2012-11-07 10:36:15.802 Associate[1280:907] REST: Blocked for 4276.3 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc102af?rev=4-82777dd597cbff9d882526507cb6673d]
2012-11-07 10:36:23.011 Associate[1280:907] REST: Blocked for 3910.8 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc097b4?rev=4-0e1e4732b7200c6de29606d2f7f0d3d2]
2012-11-07 10:36:23.283 Associate[1280:907] REST: Blocked for 264.8 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc089a7?rev=4-850420ccc76ac74428a1f190c71d1db8]
2012-11-07 10:36:23.306 Associate[1280:907] REST: Blocked for 17.8 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc08807?rev=4-9750b1e7616b1754cca49304cf0cc1c4]
2012-11-07 10:36:23.329 Associate[1280:907] REST: Blocked for 17.5 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc081af?rev=4-052e0f3897ad89cc2559a44edcd8b9c0]
2012-11-07 10:36:23.351 Associate[1280:907] REST: Blocked for 17.1 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc072b7?rev=4-2d5974aeb7a3c2556c5a25b62b9535ad]
2012-11-07 10:36:23.373 Associate[1280:907] REST: Blocked for 17.4 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc071d1?rev=4-b1fb1c512cc791a2331dafc2b8053264]
2012-11-07 10:36:23.395 Associate[1280:907] REST: Blocked for 16.8 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc0635b?rev=4-b0d0ec67e4c06d2151b696f921d70967]
2012-11-07 10:36:31.864 Associate[1280:907] REST: Blocked for 4111.9 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc03486?rev=4-1b093af5dbc3ebec98ea647ebcee68db]
2012-11-07 10:36:32.111 Associate[1280:907] REST: Blocked for 241.0 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc02c0a?rev=4-dce79a98f88a3265376667e1aafadecf]
2012-11-07 10:36:32.146 Associate[1280:907] REST: Blocked for 29.0 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc01e7b?rev=4-f50b2e0cf82d37a4b1cadd7b5a96e7ea]
2012-11-07 10:36:32.176 Associate[1280:907] REST: Blocked for 24.7 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc00fb4?rev=4-292096b85f5afdef363be8185677bf83]
2012-11-07 10:36:32.204 Associate[1280:907] REST: Blocked for 22.5 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc00ca9?rev=4-0c7a811da0d04f7a0227c8c9060a07ff]
2012-11-07 10:36:32.227 Associate[1280:907] REST: Blocked for 17.3 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc00470?rev=4-2ec8c4e8921cbf7985ef9f290c4b6036]
2012-11-07 10:36:32.253 Associate[1280:907] REST: Blocked for 19.2 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dc002f0?rev=4-82ee1545b6c8c5bdec81a9c8f0bbf1ee]
2012-11-07 10:37:00.425 Associate[1280:907] REST: Blocked for 4346.6 ms in RESTOperation[loaded  GET touchdb:///signature/1ce006786f92f2a77b53b6cd9dbffef6?rev=4-99663571e5c7fced81626a9423e861a6]

Full logs: http://filebin.ca/Lp3wOfC3zOL/slow_scrolling_logs5.txt

TouchDB Version being tested:

  • TouchDB 1.0, commit e81b50c
  • CouchCocoa commit ca6f0eb8 on our fork (essentially identical to d445e6 save for one commit related to a workaround for Issue #164). I also tested with d445e6 and observed identical behavior.
@tleyden
Owner

Also here is the gist of our couchTableSource:cellForRowAtIndexPath: method:

- (UITableViewCell *)couchTableSource:(CouchUITableSource*)source
                cellForRowAtIndexPath:(NSIndexPath *)indexPath {

    CouchDocument *document;
    SGContact *contact;  // CouchModel subclass

    document  = [source documentAtIndexPath:indexPath];
    contact   = [SGContact modelForDocument:document];

    // etc ..

 }
@tleyden
Owner

I tried making the following change as a workaround attempt:

- (UITableViewCell *)couchTableSource:(CouchUITableSource*)source
        cellForRowAtIndexPath:(NSIndexPath *)indexPath {

        CouchQueryRow *row = [source rowAtIndex:[indexPath row]];
        NSDictionary* properties = row.value;

        // set cell label based on value in properties, etc ..

 }

and it seemed to improve things a bit, however I'm still seeing long table scroll lockups (just happening slightly less frequently). When I pause and look at the backtrace:

lldb) bt
* thread #1: tid = 0x2403, 0x3469fc08 Foundation`skipJSONWhitespace, stop reason = signal SIGSTOP
frame #0: 0x3469fc08 Foundation`skipJSONWhitespace
frame #1: 0x346a019a Foundation`newJSONValue + 1354
frame #2: 0x3469ff0c Foundation`newJSONValue + 700
frame #3: 0x346a021c Foundation`newJSONValue + 1484
frame #4: 0x346a021c Foundation`newJSONValue + 1484
frame #5: 0x3469ff0c Foundation`newJSONValue + 700
frame #6: 0x346a021c Foundation`newJSONValue + 1484
frame #7: 0x3469fb92 Foundation`-[_NSJSONReader parseUTF8JSONData:skipBytes:options:] + 170
frame #8: 0x3469f9ac Foundation`-[_NSJSONReader parseData:options:] + 264
frame #9: 0x3469f820 Foundation`+[NSJSONSerialization JSONObjectWithData:options:error:] + 152
frame #10: 0x001c21c4 Associate`+[RESTBody(JSON) JSONObjectWithData:] + 52 at RESTBody.m:316
frame #11: 0x001c1bae Associate`-[RESTBody fromJSON] + 118 at RESTBody.m:140
frame #12: 0x001b902e Associate`-[CouchQuery operation:willCompleteWithError:] + 306 at CouchQuery.m:161
frame #13: 0x001b9e48 Associate`-[CouchLiveQuery operation:willCompleteWithError:] + 72 at CouchQuery.m:278
frame #14: 0x001c00ac Associate`-[RESTOperation completedWithError:] + 808 at RESTOperation.m:335
frame #15: 0x001c0b04 Associate`-[RESTOperation connectionDidFinishLoading:] + 632 at RESTOperation.m:450
frame #16: 0x34722ef4 Foundation`__65-[NSURLConnectionInternal _withConnectionAndDelegate:onlyActive:]_block_invoke_0 + 16
frame #17: 0x346629f0 Foundation`-[NSURLConnectionInternal _withConnectionAndDelegate:onlyActive:] + 200
frame #18: 0x3466290c Foundation`-[NSURLConnectionInternal _withActiveConnectionAndDelegate:] + 60
frame #19: 0x32b345de CFNetwork`___delegate_didFinishLoading_block_invoke_0 + 26
frame #20: 0x32b33cca CFNetwork`___withDelegateAsync_block_invoke_0 + 54
frame #21: 0x32b5c132 CFNetwork`___performAsync_block_invoke_068 + 18
frame #22: 0x36b8174c CoreFoundation`CFArrayApplyFunction + 176
frame #23: 0x32b5c592 CFNetwork`RunloopBlockContext::perform() + 74
frame #24: 0x32ac015c CFNetwork`MultiplexerSource::perform() + 188
frame #25: 0x36c10682 CoreFoundation`__CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 14
frame #26: 0x36c0fee8 CoreFoundation`__CFRunLoopDoSources0 + 212
frame #27: 0x36c0ecb6 CoreFoundation`__CFRunLoopRun + 646
frame #28: 0x36b81ebc CoreFoundation`CFRunLoopRunSpecific + 356
frame #29: 0x36b81d48 CoreFoundation`CFRunLoopRunInMode + 104
frame #30: 0x370be2ea GraphicsServices`GSEventRunModal + 74
frame #31: 0x37f60300 UIKit`UIApplicationMain + 1120
frame #32: 0x0004c1ea Associate`main + 150 at main.m:16

I'm curious why this is even running on the main thread? Does it look like we are misusing TouchDB in our app or is this normal behavior when using a CouchUITableSource? I'm guessing the latter, and that it usually doesn't pose a problem .. but maybe our rather large JSON docs are causing issues. I can post more code snippets if need be.

Would switching from CouchUITableSource and just doing KVO on the CouchLiveQuery be likely to work around blocking the main thread when the CouchLiveQuery is parsing JSON?

@tleyden
Owner

I did an experiment to switch away from CouchUITableSource and instead do KVO on the CouchLiveQuery, and the backtrace on the main thread looked the same as posted in the previous comment. So it doesn't seem to be related to using CouchUITableSource.

@tleyden
Owner

I was able to reproduce the issue with GrocerySync using the steps below:

  • Clone our fork of GrocerySync: https://github.com/signaturelabs/iOS-Couchbase-Demo

  • Install script dependencies (documented in Scripts/StressTestData/README.md file)

    $ sudo gem install couchrest

  • Edit DemoAppDelegate.h kDefaultSyncDbURL to set GrocerySync to point to https://foo:bar@baz.iriscouch.com/grocery-sync

  • Run GrocerySync on an ios device (more pronounced behavior than on simulator). I'm tesing on a 4s.

  • Add 1000 heavyweight test docs with

    $ ruby stressdata.rb --server https://foo:bar@baz.iriscouch.com/grocery-sync -a 1000 -v

  • While it's syncing, scroll up and down continously .. the scrolling will periodically lock up for a few seconds.

  • Update all 1000 test docs with

    $ ruby stressdata.rb --server https://foo:bar@baz.iriscouch.com/grocery-sync -t -v

  • While it's syncing, scroll up and down continously .. the scrolling will periodically lock up for a few seconds.

@snej
Owner

I suspect that the lockups happen when TouchDB is busy re-indexing a view so it can't respond to requests, and then the main thread, as you saw, is blocked waiting for a request. The fix is probably to move the view indexing to a separate thread, which is somewhat tricky but doable.

The single snapshots of the main thread that you've gotten are interesting but less useful than continuous samples of all threads. Could you run the same scenario in Instruments using the time profiler? (I know that thanks to your steps-to-reproduce above I could do this myself, but I don't know if I can get to this right away.)

@tleyden
Owner

Sure no problem, will check it out.

@tleyden
Owner

Here are two profiling traces taken on the device while it was doing some sync'ing and I was scrolling the UI: http://filebin.ca/Lx5maKRv5mb/Instruments1.trace.zip
http://filebin.ca/Lx74pD9bEZ6/Instruments2.trace.zip

@tleyden
Owner

Were those helpful? If not let me know what other instrumentation data I can collect..

Also I wanted to clarify the issues as I perceive them:

Backtrace #1) While a background sync is going on, calls to [CouchModel getValueOfProperty:] may block. Since these calls are made from the main thread, this ends up blocking the main thread and the UI locks up. This can be "worked around" to some extent by following the example in GrocerySync, and just grab the value property in the CouchQueryRow, which will contain the document as a dictionary which can be used to populate the UI elements. (and thereby circumvent the extra hit to TouchDb which may block)

Backtrace #2) While a background sync is going on which involves large (20K+) JSON docs, the CouchLiveQuery object may block the main thread while the json is being parsed. No known workaround, other than the application avoiding using such large JSON docs. A "fix" for this would involve moving the JSON parsing to the TouchDB background thread rather than it happening on the main thread.

@snej
Owner

I'll take a look at these now, thanks!

@snej
Owner

Looking at the first trace, it's all JSON all the time — the good news is that's a simpler problem than what I thought before. The new 'public-api' branch should help a lot with this, as the more direct connection between the public API and the internals means a lot less JSON generation and parsing, especially of large view results.

I guess the corresponding bad news is that to get improvement you're probably going to need to move to the bleeding edge of development, i.e. the 'public-api' branch. That means you'll definitely run into bugs, as there's been a lot of change on that branch and it's only been tested well enough to run Grocery Sync.

@tleyden tleyden closed this
@tleyden tleyden reopened this
@tleyden
Owner

Woops! Wrong button.

Going to check out the public-api branch and let you know how it goes.

@tleyden
Owner

I did some testing against the public-api branch using grocery-sync + stress test data, and it is much improved! I would say the scrolling behavior has gone from a 6/10 to a 9.8/10 while replication is happening.

I still can reproduce the locked scrolling, but it happens very infrequently now.

@snej
Owner

Cool! How recent is your public-api checkout? This morning's commit 7292a5 should speed queries up even further, if you don't already have it.

@tleyden
Owner

Yep the version I'm testing has that commit.

@snej snej closed this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.