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/a4b659fe-1bcc-4bb3-a01c-ae2f2136e6bd%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
