Issue in pull replication with iOS/MacOS Couchbase Lite v1.3.1

Just updated to v1.3.1 library, and we’re seeing very poor performance with initial data sync. In a small test database that takes less than a minute to sync with 1.2.1, it’s taking more than five minutes to sync with v1.3.1. We see this in both the iOS and MacOS libraries. This is with the same backend, and same client code, the only difference is the Couchbase library 1.2.1 was swapped for 1.3.1. It looks like bulk fetching is not working.

Using iOS Couchbase Lite v1.2.1 the beginning of an initial sync operation looks like:

08:59:32.734‖ Sync: CBLRestPusher[https://redacted.hostname.com/pg/data/pm]: Attempted to connect: online
08:59:33.350‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm]: Server is Couchbase Sync Gateway/1.1.1
08:59:33.352‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 100
08:59:33.352‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=12:11 (100 in bulk, 0 individually)
08:59:33.352‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...
08:59:33.355‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 200
08:59:33.356‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=953 (100 in bulk, 0 individually)
08:59:33.356‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...
08:59:33.358‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 300
08:59:33.359‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=1481 (100 in bulk, 0 individually)
08:59:33.359‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...
08:59:33.361‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 400
08:59:33.361‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60463 (100 in bulk, 0 individually)
08:59:33.362‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...

However, with iOS Couchbase Lite v1.3.1 we have a very different log, this is where it appears bulk fetching is not being used:

09:01:45.044‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm]: Server is Apache-Coyote/1.1
09:01:45.044‖ WARNING: JSON error parsing _changes feed: lexical error: invalid char in json text.
 {at -[CBLChangeTracker parseBytes:length:]:351}
09:01:45.045‖ CBLSocketChangeTracker[0x7fb2f3c973a0 pm]: Connection error #1, retrying in 2.0 sec: CBLHTTP[587, "JSON error parsing _changes feed: lexical error: invalid char in json text.
", <https://redacted.hostname.com/pg/data/pm/_changes?feed=normal&heartbeat=59000&style=all_docs&active_only=true>]
09:01:48.213‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 100
09:01:48.214‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=12:11 (2 in bulk, 98 individually)
09:01:48.214‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 2 remote revisions...
09:01:48.217‖ Sync: CBLReplication[from https://redacted.hostname.com/pg/data/pm]: active, progress = 0 / 143, err: (null)
09:01:48.269‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 200
09:01:48.270‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=953 (0 in bulk, 100 individually)
09:01:48.272‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 300
09:01:48.272‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=1481 (1 in bulk, 99 individually)
09:01:48.274‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 400
09:01:48.275‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60463 (0 in bulk, 100 individually)
09:01:48.276‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 500
09:01:48.277‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60563 (0 in bulk, 100 individually)
09:01:48.278‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 600
09:01:48.278‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60663 (0 in bulk, 100 individually)
09:01:48.279‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 700
09:01:48.280‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60763 (0 in bulk, 100 individually)
09:01:48.281‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 800
09:01:48.282‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60863 (0 in bulk, 100 individually)
09:01:48.283‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 900
09:01:48.284‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60963 (0 in bulk, 100 individually)
09:01:48.285‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1000
09:01:48.285‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61063 (0 in bulk, 100 individually)
09:01:48.286‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1100
09:01:48.287‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61163 (0 in bulk, 100 individually)
09:01:48.288‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1200
09:01:48.289‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61263 (0 in bulk, 100 individually)
09:01:48.290‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1300
09:01:48.290‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61363 (0 in bulk, 100 individually)
09:01:48.291‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1400
09:01:48.292‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61463 (0 in bulk, 100 individually)
09:01:48.293‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1500
09:01:48.293‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61563 (0 in bulk, 100 individually)
09:01:48.294‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1600
09:01:48.295‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61663 (0 in bulk, 100 individually)
09:01:48.296‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1700
09:01:48.296‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61763 (0 in bulk, 100 individually)
09:01:48.297‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1800
09:01:48.298‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61863 (0 in bulk, 100 individually)
09:01:48.298‖ Sync: CBLReplication[from https://redacted.hostname.com/pg/data/pm]: active, progress = 0 / 1838, err: (null)
09:01:48.801‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 38 remote revisions from seq=61963 (0 in bulk, 38 individually)
09:01:48.864‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] checking 2 bulk-fetched remote revisions
09:01:48.867‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] inserted 2 revs in 0.002 sec (914.9/sec)
09:01:48.867‖ Sync: CBLReplication[from https://redacted.hostname.com/pg/data/pm]: active, progress = 2 / 1838, err: (null)

You’re right, definitely looks like it’s falling back to individual GET requests per document.

What server/version are you using?

Hi Jens, thanks. This backend is using Couchbase Server v3.1.0 and v 1.1.1 of the sync gateway.

Could you file an issue on Github, please? Then we can investigate. https://github.com/couchbase/couchbase-lite-ios/issues/new

Done: https://github.com/couchbase/couchbase-lite-ios/issues/1464
Thanks!