sync: GU retry with less explicit TimeTicks logic

sync: GU retry with less explicit TimeTicks logic

For reasons described in crbug.com/338016, I changed my mind on explicit
time tracking.  This is an attempt to clean up my mistake.

This new approach has the NudgeTracker keep track of the time when the
next retry GU is scheduled, and a flag that is set to true when we
should perform a retry GU at the next possible opportunity.  Before a
sync cycle, the NudgeTracker is provided with a TimeTicks::Now() value
and asked to update the flag accordingly.

This does a better job of ensuring the value of
NudgeTracker::IsRetryRequired() is consistent.  After this CL, we can
guarantee that its value will be the same before, during, and after the
sync cycle.  The previous implementation relied on a call to
TimeTicks::Now() in download.cc, so it did not have this property.

There is one tricky part to this patch.  We need to be careful that we
the call to RecordSuccessfulSyncCycle() after a sync cycle does not
overwrite pending retry state that may have been set by that sync
cycle's SyncSessionDelegate::OnReceivedRetryDelay() function.  To avoid
that problem, we store the value from that call in the SyncScheduler and
act on it only after we've updated the NudgeTracker's state when the
sync cycle is complete.

BUG=338016
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=248611

[rlarocque, 2014-01-25 00:15:00]

I've come to the realization that it's unrealistic to expect that we can make
the explicit time tracking strategy work.  I was wrong when I argued for it in
your GU retry code review.  This is my attempt to fix that mistake by rewriting
the way NudgeTracker deals with time.

As currently implemented, this code only responds to GU retry requests when the
request happens after a "normal" sync cycle.  I'm not sure whether or not that's
correct.  I can change it if you think it should behave differently.

Please review.

[pavely, 2014-01-27 11:53:57]

On 2014/01/25 00:15:00, rlarocque wrote:
> I've come to the realization that it's unrealistic to expect that we can make
> the explicit time tracking strategy work.  I was wrong when I argued for it in
> your GU retry code review.  This is my attempt to fix that mistake by
rewriting
> the way NudgeTracker deals with time.
> 
> As currently implemented, this code only responds to GU retry requests when
the
> request happens after a "normal" sync cycle.  I'm not sure whether or not
that's
> correct.  I can change it if you think it should behave differently.
> 
> Please review.

lgtm with two nits.

[pavely, 2014-01-27 11:54:05]

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
File sync/engine/sync_scheduler_impl.cc (right):

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
sync/engine/sync_scheduler_impl.cc:926: }
Not required for this change but I would put "received_pending_retry_ = false;"
here to show that all actions were performed and next call to
ProcessReceivedGURetryDelay will be no-op.

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
File sync/engine/sync_scheduler_impl.h (right):

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
sync/engine/sync_scheduler_impl.h:338: // Set byt he OnReceivedGuRetryDelay
callback.
typo: "byt he" => "by the"

[haitaol1, 2014-01-27 23:17:06]

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
File sync/engine/sync_scheduler_impl.cc (right):

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
sync/engine/sync_scheduler_impl.cc:484: ProcessReceivedGuRetryDelay();
Previously retry may be scheduled even when sync failed (partially successful).
Retry should depend on server command only.

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
sync/engine/sync_scheduler_impl.cc:917: received_pending_retry_ = true;
Why change this? Previous implementation is simple and easy to understand. This
change is complicated and requires coordinating calls in several places. I don't
think there's a need for that.

I see your argument about NudgeTracker::IsRetryRequired() being consistent
before/after. I'm not sure that's true. E.g. if sync cycle starts before retry
timeout and finishes after, shouldn't IsRetryRequired() be false before and true
after.

https://codereview.chromium.org/146113003/diff/1/sync/sessions/nudge_tracker.cc
File sync/sessions/nudge_tracker.cc (right):

https://codereview.chromium.org/146113003/diff/1/sync/sessions/nudge_tracker....
sync/sessions/nudge_tracker.cc:245: void
NudgeTracker::ToggleRetryFlagIfRequired(base::TimeTicks now) {
Seems redundant to keep both is_retry_required and next_retry_time. How about
changing this to SetSyncCycleStartTime() and compare start time with
next_retry_time in IsRetryRequired and RecordSuccessfulSyncCycle? In this way,
next_retry_time_ is also not lost if GU failed.

[rlarocque, 2014-01-28 01:06:33]

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
File sync/engine/sync_scheduler_impl.cc (right):

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
sync/engine/sync_scheduler_impl.cc:484: ProcessReceivedGuRetryDelay();
On 2014/01/27 23:17:07, haitaol1 wrote:
> Previously retry may be scheduled even when sync failed (partially
successful).
> Retry should depend on server command only.

Interesting.  I think that makes a few corner cases a bit easier to handle.

https://codereview.chromium.org/146113003/diff/1/sync/engine/sync_scheduler_i...
sync/engine/sync_scheduler_impl.cc:917: received_pending_retry_ = true;
On 2014/01/27 23:17:07, haitaol1 wrote:
> Why change this? Previous implementation is simple and easy to understand.
This
> change is complicated and requires coordinating calls in several places. I
don't
> think there's a need for that.

Agreed, it is complicated.  Pavel made similar comments.  I'll have to change
this.

> I see your argument about NudgeTracker::IsRetryRequired() being consistent
> before/after. I'm not sure that's true. E.g. if sync cycle starts before retry
> timeout and finishes after, shouldn't IsRetryRequired() be false before and
true
> after.

I was trying to prevent a scenario where the NudgeTracker was modified while the
sync cycle is in progress.  The NudgeTracker is always referenced as a 'const
NudgeTracker&' while the sync cycle is in progress.  To use the
SyncSessionDelegate to escape the sync cycle, return to this context, and modify
it anyway seems like cheating.  

Depending on some details of how the NudgeTracker keeps track of the retry state
and what the semantics of GU retries should be, this could cause subtle bugs.  

For example, let's say the syncer is fetching updates because of a GU retry.  If
the server decides to return more than one batch of items and also sets a new
retry delay, should the second sync cycle (the one that fetches the next batch
of the items) also have the is_retry flag set?  I would think yes.  If this
callback can change the NudgeTracker's IsRetryRequired(), we'd need to be very
careful about how we handle this scenario.

https://codereview.chromium.org/146113003/diff/1/sync/sessions/nudge_tracker.cc
File sync/sessions/nudge_tracker.cc (right):

https://codereview.chromium.org/146113003/diff/1/sync/sessions/nudge_tracker....
sync/sessions/nudge_tracker.cc:245: void
NudgeTracker::ToggleRetryFlagIfRequired(base::TimeTicks now) {
On 2014/01/27 23:17:07, haitaol1 wrote:
> Seems redundant to keep both is_retry_required and next_retry_time. How about
> changing this to SetSyncCycleStartTime() and compare start time with
> next_retry_time in IsRetryRequired and RecordSuccessfulSyncCycle? In this way,
> next_retry_time_ is also not lost if GU failed.

I wanted to avoid saving the value of 'now' inside the NudgeTracker.  My reasons
for this are subjective.  I think that 'now' is a bit too much information for
the NudgeTracker.  It's easy to justify why the NudgeTracker should have an
'is_retry_required_' member.  That's less true with 'sync_cycle_start_time_'.

Anyway, it seems that trying to prevent storing sync_cycle_start_time_ here has
led to significantly worse code in other places, so it's getting very hard
justify that decision.  I might need to take your suggestion and store the
timestamp here.

[rlarocque, 2014-01-28 02:29:36]

I've updated the callback that sets the GU retry time to make it a bit simpler. 
I've also added a bunch of tests that enforce what I believe is the correct
behavior.  

I haven't updated the NudgeTracker to use timestamps internally yet.  I can
update the patch to do that too if you're still interested, though I don't think
it would change behavior in any case.

[haitaol1, 2014-01-28 20:09:20]

https://codereview.chromium.org/146113003/diff/80001/sync/sessions/nudge_trac...
File sync/sessions/nudge_tracker.cc (right):

https://codereview.chromium.org/146113003/diff/80001/sync/sessions/nudge_trac...
sync/sessions/nudge_tracker.cc:253: if (next_retry_time_ < now) {
where is next_retry_time nulled? Seems nudge tracker is stuck in retry without
that.

I feel storing start time is easy and may be useful in the future, too.

[rlarocque, 2014-01-28 22:24:37]

I've updated the NudgeTracker logic.  It's using timestamps instead of a flag
now.  I think it would be possible to replace the sync_cycle_start_time_
timestamp with a bool, but I'm pretty sure we'll need both the
current_retry_time_ and next_retry_time_ timestamps in order to pass all the
tests.

This version lines up with my earlier notes about the amount of complexity
required to make this logic correct, so I'm feeling a bit better about the
correctness of this patch.

PTAL.

https://codereview.chromium.org/146113003/diff/80001/sync/sessions/nudge_trac...
File sync/sessions/nudge_tracker.cc (right):

https://codereview.chromium.org/146113003/diff/80001/sync/sessions/nudge_trac...
sync/sessions/nudge_tracker.cc:253: if (next_retry_time_ < now) {
On 2014/01/28 20:09:20, haitaol1 wrote:
> where is next_retry_time nulled? Seems nudge tracker is stuck in retry without
> that.
> 
> I feel storing start time is easy and may be useful in the future, too.

Thanks!

I had a nagging feeling that this code was wrong somehow, since I had concluded
on Friday that it was impossible to write this code correctly with so little
state.  But my unit tests passed and seemed to cover all the cases, so I figured
it must be correct...  Looks like I *was* missing something obvious.

I've updated the tests to catch this.

[haitaol1, 2014-01-28 23:07:23]

https://codereview.chromium.org/146113003/diff/130001/sync/sessions/nudge_tra...
File sync/sessions/nudge_tracker.cc (right):

https://codereview.chromium.org/146113003/diff/130001/sync/sessions/nudge_tra...
sync/sessions/nudge_tracker.cc:255: if (!next_retry_time_.is_null()) {
Probably don't set current_retry_time if it's not null, which means last retry
GU failed. So current_retry_time always stores the time of earliest retry that
hasn't succeeded.

[rlarocque, 2014-01-28 23:17:09]

https://codereview.chromium.org/146113003/diff/130001/sync/sessions/nudge_tra...
File sync/sessions/nudge_tracker.cc (right):

https://codereview.chromium.org/146113003/diff/130001/sync/sessions/nudge_tra...
sync/sessions/nudge_tracker.cc:255: if (!next_retry_time_.is_null()) {
On 2014/01/28 23:07:23, haitaol1 wrote:
> Probably don't set current_retry_time if it's not null, which means last retry
> GU failed. So current_retry_time always stores the time of earliest retry that
> hasn't succeeded.

Correct.  That was my intention.  At least, that's the behavior that makes the
most sense to me.

If a retry GU fails, then we'll go into exponential backoff.  It would make
sense to me that IsRetryRequired() will be true when that backoff expires and we
make another attempt at the GU retry.

Leaving current_retry_time_ alone in the failure case seems to me a not-too-bad
way of achieving that goal.

Am I missing some obvious side-effects of this choice?  Or is my understanding
of the desired behavior wrong?

[rlarocque, 2014-01-29 00:03:47]

I misunderstood the desired behavior of one very unlikely edge case.

It turns out that the desired behavior if we perform a GU retry and it fails but
also receives a new GU retry timeout, we should go into exponential backoff.  We
don't forget about the GU retry that failed and continue backing off until we
can execute it successfully.  We also don't forget about the GU retry request we
received during the sync cycle.  If we're out of exponential backoff by the time
that timeout expires, we need to service it, too.

I've uploaded new code and tests that implement the NudgeTracker functions
according to my new understanding of the requirements.

[haitaol1, 2014-01-29 00:32:56]

lgtm

[rlarocque, 2014-01-29 01:11:27]

On 2014/01/29 00:32:56, haitaol1 wrote:
> lgtm

Thanks.

Pavel: There have been quite a few changes since you last LGTM'ed the patch. 
Please let me know if you'd like me to wait until you've had a chance to
re-review before committing.

[pavely, 2014-01-29 01:14:03]

On 2014/01/29 01:11:27, rlarocque wrote:
> On 2014/01/29 00:32:56, haitaol1 wrote:
> > lgtm
> 
> Thanks.
> 
> Pavel: There have been quite a few changes since you last LGTM'ed the patch. 
> Please let me know if you'd like me to wait until you've had a chance to
> re-review before committing.

Go ahead and commit. I'll review after the fact in a couple of days.

[pavely, 2014-01-29 15:35:05]

https://codereview.chromium.org/146113003/diff/150001/sync/engine/sync_schedu...
File sync/engine/sync_scheduler_impl.cc (right):

https://codereview.chromium.org/146113003/diff/150001/sync/engine/sync_schedu...
sync/engine/sync_scheduler_impl.cc:237: (nudge_tracker_.IsSyncRequired() ||
nudge_tracker_.IsRetryRequired()) &&
SetSyncCycleStartTime isn't called in this case. If previous sync cycle called
SetRetryTime this call wouldn't notice it.

The semantic of variables is:
- current_retry_time : earliest unsatisfied retry time.
- next_retry_time : latest known retry time.

If the above semantic is right then SetNextRetryTime should also copy retry time
into current_retry_time if it is not set.

[rlarocque, 2014-01-29 18:27:41]

https://codereview.chromium.org/146113003/diff/150001/sync/engine/sync_schedu...
File sync/engine/sync_scheduler_impl.cc (right):

https://codereview.chromium.org/146113003/diff/150001/sync/engine/sync_schedu...
sync/engine/sync_scheduler_impl.cc:237: (nudge_tracker_.IsSyncRequired() ||
nudge_tracker_.IsRetryRequired()) &&
On 2014/01/29 15:35:05, pavely wrote:
> SetSyncCycleStartTime isn't called in this case. If previous sync cycle called
> SetRetryTime this call wouldn't notice it.
> 
> The semantic of variables is:
> - current_retry_time : earliest unsatisfied retry time.
> - next_retry_time : latest known retry time.
> 
> If the above semantic is right then SetNextRetryTime should also copy retry
time
> into current_retry_time if it is not set.

I had forgotten that this was a different code path.  I think this will need a
call to SetSyncCycleStartTime().  That would fix the behavior.

I'm not sure I agree with your suggestion about current_retry_time semantics.

I think the behavior we're trying to achieve is that the client should only act
on the most recently received retry.  There is a special case where the GU retry
attempt fails, in which case we should have the IsRetryRequired() flag set until
one of the exponential backoff attempts is successful.

It seems to me that if we set current_retry_time in SetNextRetryTime(), we won't
be able to override it if a new retry time arrives before it times out.

[pavely, 2014-02-03 20:52:23]

lgtm

[rlarocque, 2014-02-03 20:54:54]

On 2014/02/03 20:52:23, pavely wrote:
> lgtm

Thanks for the reviews.  This took a lot of time, but I think the result was
worth it.  The current CL is much clearer than what I had originally proposed.

[rlarocque, 2014-02-03 20:55:07]

The CQ bit was checked by rlarocque@chromium.org

[commit-bot: I haz the power, 2014-02-03 20:55:14]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/rlarocque@chromium.org/146113003/170001

[commit-bot: I haz the power, 2014-02-03 23:36:01]

Change committed as 248611

[commit-bot: I haz the power, 2014-02-03 23:36:04]

CQ bit was unchecked on CL. Ignoring.

[commit-bot: I haz the power, 2014-02-03 23:36:06]

CQ bit was unchecked on CL. Ignoring.

[commit-bot: I haz the power, 2014-02-03 23:36:07]

CQ bit was unchecked on CL. Ignoring.

[commit-bot: I haz the power, 2014-02-03 23:36:11]

CQ bit was unchecked on CL. Ignoring.

[commit-bot: I haz the power, 2014-02-03 23:36:24]

CQ bit was unchecked on CL. Ignoring.