{"action":"created","issue":{"url":"https://api.github.com/repos/couchbase/couchbase-lite-ios/issues/1464","repository_url":"https://api.github.com/repos/couchbase/couchbase-lite-ios","labels_url":"https://api.github.com/repos/couchbase/couchbase-lite-ios/issues/1464/labels{/name}","comments_url":"https://api.github.com/repos/couchbase/couchbase-lite-ios/issues/1464/comments","events_url":"https://api.github.com/repos/couchbase/couchbase-lite-ios/issues/1464/events","html_url":"https://github.com/couchbase/couchbase-lite-ios/issues/1464","id":179604861,"number":1464,"title":"Pull replication performance issue in v1.3.1","user":{"login":"andyjohns","id":2933777,"avatar_url":"https://avatars.githubusercontent.com/u/2933777?v=3","gravatar_id":"","url":"https://api.github.com/users/andyjohns","html_url":"https://github.com/andyjohns","followers_url":"https://api.github.com/users/andyjohns/followers","following_url":"https://api.github.com/users/andyjohns/following{/other_user}","gists_url":"https://api.github.com/users/andyjohns/gists{/gist_id}","starred_url":"https://api.github.com/users/andyjohns/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/andyjohns/subscriptions","organizations_url":"https://api.github.com/users/andyjohns/orgs","repos_url":"https://api.github.com/users/andyjohns/repos","events_url":"https://api.github.com/users/andyjohns/events{/privacy}","received_events_url":"https://api.github.com/users/andyjohns/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2016-09-27T20:30:22Z","updated_at":"2016-09-27T22:54:12Z","closed_at":null,"body":"After updating to v1.3.1 library, and we see 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.\r\n\r\nUsing iOS Couchbase Lite v1.2.1 the beginning of an initial sync operation looks like:\r\n\r\n```\r\n08:59:32.734‖ Sync: CBLRestPusher[https://redacted.hostname.com/pg/data/pm]: Attempted to connect: online\r\n08:59:33.350‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm]: Server is Couchbase Sync Gateway/1.1.1\r\n08:59:33.352‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 100\r\n08: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)\r\n08:59:33.352‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...\r\n08:59:33.355‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 200\r\n08:59:33.356‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=953 (100 in bulk, 0 individually)\r\n08:59:33.356‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...\r\n08:59:33.358‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 300\r\n08:59:33.359‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=1481 (100 in bulk, 0 individually)\r\n08:59:33.359‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...\r\n08:59:33.361‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 400\r\n08:59:33.361‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60463 (100 in bulk, 0 individually)\r\n08:59:33.362‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 100 remote revisions...\r\n```\r\n\r\nHowever, with iOS Couchbase Lite v1.3.1 we have a very different log, this is where it appears bulk fetching is not being used:\r\n\r\n```\r\n09:01:45.044‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm]: Server is Apache-Coyote/1.1\r\n09:01:45.044‖ WARNING: JSON error parsing _changes feed: lexical error: invalid char in json text.\r\n {at -[CBLChangeTracker parseBytes:length:]:351}\r\n09: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.\r\n\", <https://redacted.hostname.com/pg/data/pm/_changes?feed=normal&heartbeat=59000&style=all_docs&active_only=true>]\r\n09:01:48.213‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 100\r\n09: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)\r\n09:01:48.214‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] bulk-fetching 2 remote revisions...\r\n09:01:48.217‖ Sync: CBLReplication[from https://redacted.hostname.com/pg/data/pm]: active, progress = 0 / 143, err: (null)\r\n09:01:48.269‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 200\r\n09:01:48.270‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=953 (0 in bulk, 100 individually)\r\n09:01:48.272‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 300\r\n09:01:48.272‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=1481 (1 in bulk, 99 individually)\r\n09:01:48.274‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 400\r\n09:01:48.275‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60463 (0 in bulk, 100 individually)\r\n09:01:48.276‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 500\r\n09:01:48.277‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60563 (0 in bulk, 100 individually)\r\n09:01:48.278‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 600\r\n09:01:48.278‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60663 (0 in bulk, 100 individually)\r\n09:01:48.279‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 700\r\n09:01:48.280‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60763 (0 in bulk, 100 individually)\r\n09:01:48.281‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 800\r\n09:01:48.282‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60863 (0 in bulk, 100 individually)\r\n09:01:48.283‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 900\r\n09:01:48.284‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=60963 (0 in bulk, 100 individually)\r\n09:01:48.285‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1000\r\n09:01:48.285‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61063 (0 in bulk, 100 individually)\r\n09:01:48.286‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1100\r\n09:01:48.287‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61163 (0 in bulk, 100 individually)\r\n09:01:48.288‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1200\r\n09:01:48.289‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61263 (0 in bulk, 100 individually)\r\n09:01:48.290‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1300\r\n09:01:48.290‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61363 (0 in bulk, 100 individually)\r\n09:01:48.291‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1400\r\n09:01:48.292‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61463 (0 in bulk, 100 individually)\r\n09:01:48.293‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1500\r\n09:01:48.293‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61563 (0 in bulk, 100 individually)\r\n09:01:48.294‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1600\r\n09:01:48.295‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61663 (0 in bulk, 100 individually)\r\n09:01:48.296‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1700\r\n09:01:48.296‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61763 (0 in bulk, 100 individually)\r\n09:01:48.297‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] Progress: 0 / 1800\r\n09:01:48.298‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 100 remote revisions from seq=61863 (0 in bulk, 100 individually)\r\n09:01:48.298‖ Sync: CBLReplication[from https://redacted.hostname.com/pg/data/pm]: active, progress = 0 / 1838, err: (null)\r\n09:01:48.801‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] queued 38 remote revisions from seq=61963 (0 in bulk, 38 individually)\r\n09:01:48.864‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] checking 2 bulk-fetched remote revisions\r\n09:01:48.867‖ Sync: CBLRestPuller[https://redacted.hostname.com/pg/data/pm] inserted 2 revs in 0.002 sec (914.9/sec)\r\n09:01:48.867‖ Sync: CBLReplication[from https://redacted.hostname.com/pg/data/pm]: active, progress = 2 / 1838, err: (null)\r\n```\r\n\r\n--------\r\n* Version:   Couchbase Lite iOS and macOS v1.3.1\r\n* Client OS: iOS 9.3, MacOS 10.11.6\r\n* Server:    Couchbase Server v3.1.0 and v1.1.1 of the sync gateway.\r\n"},"comment":{"url":"https://api.github.com/repos/couchbase/couchbase-lite-ios/issues/comments/250022815","html_url":"https://github.com/couchbase/couchbase-lite-ios/issues/1464#issuecomment-250022815","issue_url":"https://api.github.com/repos/couchbase/couchbase-lite-ios/issues/1464","id":250022815,"user":{"login":"snej","id":43241,"avatar_url":"https://avatars.githubusercontent.com/u/43241?v=3","gravatar_id":"","url":"https://api.github.com/users/snej","html_url":"https://github.com/snej","followers_url":"https://api.github.com/users/snej/followers","following_url":"https://api.github.com/users/snej/following{/other_user}","gists_url":"https://api.github.com/users/snej/gists{/gist_id}","starred_url":"https://api.github.com/users/snej/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/snej/subscriptions","organizations_url":"https://api.github.com/users/snej/orgs","repos_url":"https://api.github.com/users/snej/repos","events_url":"https://api.github.com/users/snej/events{/privacy}","received_events_url":"https://api.github.com/users/snej/received_events","type":"User","site_admin":false},"created_at":"2016-09-27T22:54:12Z","updated_at":"2016-09-27T22:54:12Z","body":"Could you turn on SyncVerbose logging and capture the start of the replication, up through the point where it decides to request docs individually?"}}
{"actor":{"display_login":"snej"}}