Slow Couchbase Cache Receive Times

[Eric Levine]

I'm running a test using the Sync Gateway's REST API to create simple documents and trying to see how long it takes to trigger a change notification.  In the Sync Gateway logs, I see that every other create has an extra second of delay between the time the SG saves and receives the document from the Cache.  The Sync Gateway is connection to Couchbase, both running on my development laptop (Win 8.1, 8GB RAM, Core i7).

• Is there some kind of configuration I can do to Couchbase in order to eliminate this extra second of delay?  
  
• Could this be related to the bug filed here: https://github.com/couchbase/sync_gateway/issues/616 ?  
  

Here is a log where you can see the times alternating:

12:11:04.440273 HTTP:  #015: POST /db/  (ADMIN)

12:11:04.441296 CRUD+: Invoking sync on doc "53b8000698070afc3ec3f3b8a60b49d8" rev 1-e75473076989d19a3ce08a38245588c3

12:11:04.442271 CRUD:   Doc "53b8000698070afc3ec3f3b8a60b49d8" in channels "{message}"

12:11:04.442271 Cache: SAVING #748

12:11:04.442271 CRUD: Stored doc "53b8000698070afc3ec3f3b8a60b49d8" / "1-e75473076989d19a3ce08a38245588c3"

12:11:04.442271 HTTP+: #015:     --> 200   (2.0 ms)

12:11:04.799498 Cache: Received #748 after 357ms ("53b8000698070afc3ec3f3b8a60b49d8" / "1-e75473076989d19a3ce08a38245588c3")

12:11:04.800498 Cache:     #748 ==> channel "message"

12:11:04.800498 Cache: Pruned 1 old entries from channel "*"

12:11:04.800498 Cache:     #748 ==> channel "*"

12:11:05.454488 HTTP:  #017: POST /db/  (ADMIN)

12:11:05.459488 CRUD+: Invoking sync on doc "8946aaf282d44e04c2c814e713419113" rev 1-fff628538779e1ee70aa623aebe46b20

12:11:05.459488 CRUD:   Doc "8946aaf282d44e04c2c814e713419113" in channels "{message}"

12:11:05.460487 Cache: SAVING #749

12:11:05.460487 CRUD: Stored doc "8946aaf282d44e04c2c814e713419113" / "1-fff628538779e1ee70aa623aebe46b20"

12:11:05.461468 HTTP+: #017:     --> 200   (7.0 ms)

12:11:06.462539 HTTP:  #018: GET /  (ADMIN)

12:11:06.462539 HTTP+: #018:     --> 200   (0.0 ms)

12:11:06.463516 HTTP:  #019: POST /db/  (ADMIN)

12:11:06.464539 CRUD+: Invoking sync on doc "56f1a3c1fa3233ed05bd0b62b01cef42" rev 1-239026d014d235c8f5c6d5ee9fa0e083

12:11:06.464539 CRUD:   Doc "56f1a3c1fa3233ed05bd0b62b01cef42" in channels "{message}"

12:11:06.464539 Cache: SAVING #750

12:11:06.465514 CRUD: Stored doc "56f1a3c1fa3233ed05bd0b62b01cef42" / "1-239026d014d235c8f5c6d5ee9fa0e083"

12:11:06.465514 HTTP+: #019:     --> 200   (2.0 ms)

12:11:06.801415 Cache: Received #750 after 336ms ("56f1a3c1fa3233ed05bd0b62b01cef42" / "1-239026d014d235c8f5c6d5ee9fa0e083")

12:11:06.801415 Cache:   Deferring #750 (1 now waiting for #749...#749)

12:11:06.801415 Cache: Received #749 after 1340ms ("8946aaf282d44e04c2c814e713419113" / "1-fff628538779e1ee70aa623aebe46b20")

This is what I get when running the same test against Sync Gateway using Walrus:

14:07:30.086626 HTTP:  #019: POST /db/  (ADMIN)

14:07:30.087596 CRUD+: Invoking sync on doc "ba56c11f6f8e1ddcc5ed7697c5115699" rev 1-e856c5ebe93ee6dca43c03dbc089850f

14:07:30.087596 CRUD:   Doc "ba56c11f6f8e1ddcc5ed7697c5115699" in channels "{message}"

14:07:30.089597 Cache: SAVING #12

14:07:30.090597 CRUD: Stored doc "ba56c11f6f8e1ddcc5ed7697c5115699" / "1-e856c5ebe93ee6dca43c03dbc089850f"

14:07:30.090597 Cache: Received #12 after   0ms ("ba56c11f6f8e1ddcc5ed7697c5115699" / "1-e856c5ebe93ee6dca43c03dbc089850f")

14:07:30.090597 Cache:     #12 ==> channel "message"

14:07:30.090597 HTTP+: #019:     --> 200   (4.0 ms)

14:07:30.091596 Cache:     #12 ==> channel "*"

14:07:30.093595 Changes+: Notifying that "db" changed (keys="{*, message}") count=7

14:07:30.093595 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{"*":0x0} ...

14:07:30.094597 Cache: getCachedChanges("*", {0 11}) --> 1 changes valid from #12

14:07:30.094597 Changes+: MultiChangesFeed sending &{Seq:12 ID:ba56c11f6f8e1ddcc5ed7697c5115699 Deleted:false Removed:{} Doc:map[_id:ba56c11f6f8e1ddcc5ed7697c5115699 channels:message message:map[Body:message body CreatedAt:2015-02-23T19:07:30.0855959Z Receieved:false ReceievedAt:0001-01-01T05:00:00Z Title:REST Test 2 UpdateReceivedAt:0001-01-01T05:00:00Z Updated:false UpdatedAt:0001-01-01T05:00:00Z] _rev:1-e856c5ebe93ee6dca43c03dbc089850f] Changes:[map[rev:1-e856c5ebe93ee6dca43c03dbc089850f]] branched:false}

14:07:30.097595 Changes+: MultiChangesFeed waiting...

14:07:30.100596 Changes+: Waiting for "db"'s count to pass 7

14:07:30.097595 Changes: sending 1 change(s)

14:07:31.094174 HTTP:  #020: GET /  (ADMIN)

14:07:31.095175 HTTP+: #020:     --> 200   (1.0 ms)

14:07:31.097140 HTTP:  #021: POST /db/  (ADMIN)

14:07:31.098147 CRUD+: Invoking sync on doc "1e2041f576809d55e975bc7ee8ab937f" rev 1-a8a432e20da860843bbfab2dc2abc78e

14:07:31.099138 CRUD:   Doc "1e2041f576809d55e975bc7ee8ab937f" in channels "{message}"

14:07:31.099138 Cache: SAVING #13

14:07:31.100171 CRUD: Stored doc "1e2041f576809d55e975bc7ee8ab937f" / "1-a8a432e20da860843bbfab2dc2abc78e"

14:07:31.100171 Cache: Received #13 after   1ms ("1e2041f576809d55e975bc7ee8ab937f" / "1-a8a432e20da860843bbfab2dc2abc78e")

14:07:31.101183 Cache:     #13 ==> channel "message"

14:07:31.101183 Cache:     #13 ==> channel "*"

[Adam Fraser]

The latency you're describing here is the time between when Sync Gateway issues a write against the Couchbase server ("Cache: SAVING"), and the time the Sync Gateway reads that document from the Couchbase server's mutation feed ("Cache: Received").  

I agree this may be related to #616, but you're also seeing some interesting sequencing in this log excerpt ( Deferring #750 (1 now waiting for #749...#749)) - if that's actually alternating throughout the log, can you post the full log to a gist for review?

Thanks,

Adam

I haven't seen that 'alternative

[Eric Levine]

Adam,

Here is the full log from a run of 10 document creations over the REST API: https://gist.github.com/elevine/a25cb722d701702e0f12.  Let me know if there is anything else I can provide that would help.  

--

Eric Levine

[Eric Levine]

I also saw this issue today, which seems like it could be related: Dig into huge go-couchbase latencies in logs #665 

[arihant rk]

@adam,

what exactly deferring and Received deduplicated mean.

Cache: Received #37575 after 768ms ("test.doc" / "3-2f8e42685209539ef4a582eb584d51f2")

13:16:02.665819 2017-02-28T13:16:02.665+05:30 Cache:   Deferring #37575 (1 now waiting for #37574...#37574)

13:16:02.665899 2017-02-28T13:16:02.665+05:30 Cache: Received deduplicated #37574 for ("test1.doc" / "2-1d10497e322f66e5b03366d76aeb17dc")

does this cause skipping of particular document(sequence) in _changes feed.

also what if particular sequence does reach syncgateway from couchbase mutation feed?