I also saw this issue today, which seems like it could be related: Dig into huge go-couchbase latencies in logs #665 <https://github.com/couchbase/sync_gateway/issues/665>
On Wednesday, February 25, 2015 at 1:05:11 PM UTC-5, Eric Levine wrote: > > 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 > > > > > On Wednesday, February 25, 2015 at 12:57:57 PM UTC-5, Adam Fraser wrote: >> >> 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 >> >> On Monday, February 23, 2015 at 11:19:31 AM UTC-8, Eric Levine wrote: >>> >>> 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 "*" >>> >>> >>> >>> -- You received this message because you are subscribed to the Google Groups "Couchbase Mobile" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/mobile-couchbase/84e1cb12-66c1-4082-89d1-f22f83488b1b%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
