@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?
On Wednesday, February 25, 2015 at 11:37:30 PM UTC+5:30, Eric Levine wrote:
>
> 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/1259910e-d20a-4a04-aabf-8133eda01c4d%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
