sync: remove buggy freshness condition in SyncSchedulerImpl add defensive DCHECKs.

sync: remove buggy freshness condition in SyncSchedulerImpl add defensive DCHECKs.

We were using last_sync_session_end_time, which would effectively allow config jobs to cancel nudges that were scheduled to start before the config ended.  There was code to reset the start time of nudges to hack around this, (which is removed in this patch) which was pretty confusing because after executing

if (scheduled_start < Now())
  scheduled_start = Now();

scheduled_start is less than Now() again.   This check was purely to get around the freshness check (AFAICT), and I think the new code is clearer.  It also affects the Sync.Freq histogram, see bug for detail.

The integration tests also caught the fact that we weren't checking Succeeded() before updating that time, which means failed jobs could have caused legitimate nudges to be cancelled -- note this probably wasn't a big problem in practice due to the hack mentioned above.  We now check Succeeded().

This also adds a few DCHECKs for situations that were previously unsupported but would technically squeak through. For example, there's a DCHECK in ScheduleConfiguration that there is no pending config job, but that situation could have arisen if we swapped to NORMAL_MODE and back before the config job executed -- in fact, one of the tests was doing this, but it's clearly unsupported. 

Also fixes an issue with test_util::SimulateSuccess where we would not set ModelNeutralState results for config jobs, which meant that in some cases, tests would *not* reset wait_interval_ on successful backoff relief.  The changes to the test file now ensure this can't regress.

BUG=143595
Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=155370

[tim (not reviewing), 2012-08-20 05:46:34]

Hey guys, please review.

Nicolas, let me know what your thoughts are on the Freq histogram.

[rlarocque, 2012-08-20 19:02:20]

I tried to find a way to break this using only a series of NUDGEs, but couldn't.
 That's because we clear the pending_nudge_ before we start the job, then
monopolize the syncer thread until it is finished.  Any calls to ScheduleNudge()
and related methods won't be run until after the job is finished and the job's
end time recorded, so all nudges will have a scheduled_start >
last_nudge_or_poll_time_.  It works, but it's not obvious how it works.  

If the goal here is only to have the successful completion of some jobs cancel
other pending jobs, why not just put that logic in FinishSyncSessionJob()?  That
way we wouldn't have to rely on Time::Now() and (IMO) it would be easier to
follow.

http://codereview.chromium.org/10825439/diff/13001/sync/engine/sync_scheduler...
File sync/engine/sync_scheduler_impl.h (right):

http://codereview.chromium.org/10825439/diff/13001/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.h:319: // (if a POLL [which uses all data types]
took place *after* the nudge was
Can a POLL really replace a NUDGE?  What if the NUDGE had a notification
payload?

[Nicolas Zea, 2012-08-20 20:31:58]

Re histograms, I think we really need to track per-datatype delays. WIthout
that, as you say, the utility isn't really there now that tab sync is nudging
all the time.

http://codereview.chromium.org/10825439/diff/13001/sync/sessions/test_util.cc
File sync/sessions/test_util.cc (right):

http://codereview.chromium.org/10825439/diff/13001/sync/sessions/test_util.cc...
sync/sessions/test_util.cc:55: case APPLY_UPDATES:
Note that in syncer.cc:164, configuration jobs manually set the last_step to
SYNCER_END. I don't think this is necessary.

http://codereview.chromium.org/10825439/diff/13001/sync/sessions/test_util.cc...
sync/sessions/test_util.cc:62: default:
fix indent for these two lines

[tim (not reviewing), 2012-08-27 21:19:01]

On 2012/08/20 19:02:20, rlarocque wrote:
> I tried to find a way to break this using only a series of NUDGEs, but
couldn't.
>  That's because we clear the pending_nudge_ before we start the job, then
> monopolize the syncer thread until it is finished.  Any calls to
ScheduleNudge()
> and related methods won't be run until after the job is finished and the job's
> end time recorded, so all nudges will have a scheduled_start >
> last_nudge_or_poll_time_.  It works, but it's not obvious how it works.  
> 
> If the goal here is only to have the successful completion of some jobs cancel
> other pending jobs, why not just put that logic in FinishSyncSessionJob()? 
That
> way we wouldn't have to rely on Time::Now() and (IMO) it would be easier to
> follow.

The scheduler doesn't explicitly track all pending jobs.  At least, it wasn't
initially designed to in the MessageLoop, though it does track pending_nudge,
but not polls.  However, I could probably do something similar to AdjustPolling
and reset the poll timer. And on your other comment, you're right, an incoming
notification with a payload should probably always go through, since the time
between the last session finishing and this new nudge being scheduled is going
to be too short to safely discard the hint.

I'll make some changes and re-upload.

> 
>
http://codereview.chromium.org/10825439/diff/13001/sync/engine/sync_scheduler...
> File sync/engine/sync_scheduler_impl.h (right):
> 
>
http://codereview.chromium.org/10825439/diff/13001/sync/engine/sync_scheduler...
> sync/engine/sync_scheduler_impl.h:319: // (if a POLL [which uses all data
types]
> took place *after* the nudge was
> Can a POLL really replace a NUDGE?  What if the NUDGE had a notification
> payload?

[tim (not reviewing), 2012-08-27 21:19:38]

http://codereview.chromium.org/10825439/diff/13001/sync/sessions/test_util.cc
File sync/sessions/test_util.cc (right):

http://codereview.chromium.org/10825439/diff/13001/sync/sessions/test_util.cc...
sync/sessions/test_util.cc:55: case APPLY_UPDATES:
On 2012/08/20 20:31:58, nzea wrote:
> Note that in syncer.cc:164, configuration jobs manually set the last_step to
> SYNCER_END. I don't think this is necessary.


SyncSchedulerTest doesn't use the code in syncer.cc, though, it relies on
SetSyncerStepsForPurpose for the canonical definition of start/stop for a config
job. 

As a result the scheduler wasn't resetting wait_interval_ in these tests, and
now (with this patch) that will cause a failure.

[tim (not reviewing), 2012-09-05 01:08:28]

New patch uploaded that no longer drops most stale NUDGEs as part of the
freshness condition, uploads some UMA tracking the freshness heuristic, and
changes the datatype Freq histograms to be based off of independent,
per-datatype "last nudge" values.

[tim (not reviewing), 2012-09-05 15:57:34]

On 2012/09/05 01:08:28, timsteele wrote:
> New patch uploaded that no longer drops most stale NUDGEs as part of the
> freshness condition, uploads some UMA tracking the freshness heuristic, and
> changes the datatype Freq histograms to be based off of independent,
> per-datatype "last nudge" values.

Note I'm still working on the DropsStale test, and plan to add a case for the
payload-less notification nudge as well.

[tim (not reviewing), 2012-09-06 21:47:27]

PTAL.  I added an assertion for a case that was previously handled by the
freshness check, namely if there were illegal reentrant (w.r.t scheduler)
invocations of ScheduleNudge* while a sync cycle was taking place.

[rlarocque, 2012-09-06 22:17:13]

LGTM.  I'd like to hear Nicolas' opinion before commit, though.

[Nicolas Zea, 2012-09-06 22:40:57]

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
File sync/engine/sync_scheduler_impl.cc (right):

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:826: // We are interested in recording time
between local nudges for datatypes.
maybe add a TODO: consider recording LOCAL_NOTIFICATION types as well?

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:833: ModelTypeStateMap::const_iterator iter =
info.types.begin();
nit: move this into for loop declaration?

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:837: continue;
shouldn't this insert now into the map for the type before continuing?

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:842: now -
last_local_nudges_by_model_type_[iter->first]);
nit: save the iterator from the find(..) above and reuse it here.

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
File sync/engine/sync_scheduler_impl.h (right):

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.h:9: #include <map>
abc order

[tim (not reviewing), 2012-09-06 23:12:52]

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
File sync/engine/sync_scheduler_impl.cc (right):

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:826: // We are interested in recording time
between local nudges for datatypes.
On 2012/09/06 22:40:57, nzea wrote:
> maybe add a TODO: consider recording LOCAL_NOTIFICATION types as well?

Done.

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:833: ModelTypeStateMap::const_iterator iter =
info.types.begin();
On 2012/09/06 22:40:57, nzea wrote:
> nit: move this into for loop declaration?

Done.

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:837: continue;
On 2012/09/06 22:40:57, nzea wrote:
> shouldn't this insert now into the map for the type before continuing?

Gah. Yeah.  Re-worked this.

http://codereview.chromium.org/10825439/diff/25008/sync/engine/sync_scheduler...
sync/engine/sync_scheduler_impl.cc:842: now -
last_local_nudges_by_model_type_[iter->first]);
On 2012/09/06 22:40:57, nzea wrote:
> nit: save the iterator from the find(..) above and reuse it here.

See new code.

[Nicolas Zea, 2012-09-07 00:04:20]

LGTM!

[commit-bot: I haz the power, 2012-09-07 00:14:41]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/tim@chromium.org/10825439/22009

[commit-bot: I haz the power, 2012-09-07 12:57:15]

Change committed as 155370