diff options
-rw-r--r-- | sync/engine/sync_scheduler_impl.cc | 101 | ||||
-rw-r--r-- | sync/engine/sync_scheduler_impl.h | 26 | ||||
-rw-r--r-- | sync/engine/sync_scheduler_unittest.cc | 70 | ||||
-rw-r--r-- | sync/engine/sync_scheduler_whitebox_unittest.cc | 5 | ||||
-rw-r--r-- | sync/sessions/test_util.cc | 18 |
5 files changed, 156 insertions, 64 deletions
diff --git a/sync/engine/sync_scheduler_impl.cc b/sync/engine/sync_scheduler_impl.cc index 195eda4..d5f9dff 100644 --- a/sync/engine/sync_scheduler_impl.cc +++ b/sync/engine/sync_scheduler_impl.cc @@ -7,6 +7,7 @@ #include <algorithm> #include <cstring> +#include "base/auto_reset.h" #include "base/bind.h" #include "base/compiler_specific.h" #include "base/location.h" @@ -206,7 +207,8 @@ SyncSchedulerImpl::SyncSchedulerImpl(const std::string& name, connection_code_(HttpResponse::SERVER_CONNECTION_OK), delay_provider_(delay_provider), syncer_(syncer), - session_context_(context) { + session_context_(context), + no_scheduling_allowed_(false) { DCHECK(sync_loop_); } @@ -275,6 +277,13 @@ void SyncSchedulerImpl::Start(Mode mode) { if (old_mode != mode_) { // We just changed our mode. See if there are any pending jobs that we could // execute in the new mode. + if (mode_ == NORMAL_MODE) { + // It is illegal to switch to NORMAL_MODE if a previous CONFIGURATION job + // has not yet completed. + DCHECK(!wait_interval_.get() || + !wait_interval_->pending_configure_job.get()); + } + DoPendingJobIfPossible(false); } } @@ -450,12 +459,43 @@ SyncSchedulerImpl::JobProcessDecision SyncSchedulerImpl::DecideOnJob( DCHECK_EQ(mode_, NORMAL_MODE); DCHECK_NE(job.purpose, SyncSessionJob::CONFIGURATION); - // Freshness condition - if (job.scheduled_start < last_sync_session_end_time_) { - SDVLOG(2) << "Dropping job because of freshness"; - return DROP; - } + // Note about some subtle scheduling semantics. + // + // It's possible at this point that |job| is known to be unnecessary, and + // dropping it would be perfectly safe and correct. Consider + // + // 1) |job| is a POLL with a |scheduled_start| time that is less than + // the time that the last successful all-datatype NUDGE completed. + // + // 2) |job| is a NUDGE (for any combination of types) with a + // |scheduled_start| time that is less than the time that the last + // successful all-datatype NUDGE completed, and it has a NOTIFICATION + // GetUpdatesCallerInfo value yet offers no new notification hint. + // + // 3) |job| is a NUDGE with a |scheduled_start| time that is less than + // the time that the last successful matching-datatype NUDGE completed, + // and payloads (hints) are identical to that last successful NUDGE. + // + // Case 1 can occur if the POLL timer fires *after* a call to + // ScheduleSyncSessionJob for a NUDGE, but *before* the thread actually + // picks the resulting posted task off of the MessageLoop. The NUDGE will + // run first and complete at a time greater than the POLL scheduled_start. + // However, this case (and POLLs in general) is so rare that we ignore it ( + // and avoid the required bookeeping to simplify code). + // + // We avoid cases 2 and 3 by externally synchronizing NUDGE requests -- + // scheduling a NUDGE requires command of the sync thread, which is + // impossible* from outside of SyncScheduler if a NUDGE is taking place. + // And if you have command of the sync thread when scheduling a NUDGE and a + // previous NUDGE exists, they will be coalesced and the stale job will be + // cancelled via the session-equality check in DoSyncSessionJob. + // + // * It's not strictly "impossible", but it would be reentrant and hence + // illegal. e.g. scheduling a job and re-entering the SyncScheduler is NOT a + // legal side effect of any of the work being done as part of a sync cycle. + // See |no_scheduling_allowed_| for details. + // Decision now rests on state of auth tokens. if (!session_context_->connection_manager()->HasInvalidAuthToken()) return CONTINUE; @@ -469,6 +509,9 @@ void SyncSchedulerImpl::InitOrCoalescePendingJob(const SyncSessionJob& job) { if (pending_nudge_.get() == NULL) { SDVLOG(2) << "Creating a pending nudge job"; SyncSession* s = job.session.get(); + + // Get a fresh session with similar configuration as before (resets + // StatusController). scoped_ptr<SyncSession> session(new SyncSession(s->context(), s->delegate(), s->source(), s->routing_info(), s->workers())); @@ -476,7 +519,6 @@ void SyncSchedulerImpl::InitOrCoalescePendingJob(const SyncSessionJob& job) { make_linked_ptr(session.release()), false, ConfigurationParams(), job.from_here); pending_nudge_.reset(new SyncSessionJob(new_job)); - return; } @@ -587,6 +629,7 @@ void SyncSchedulerImpl::ScheduleNudgeImpl( const ModelTypeStateMap& type_state_map, bool is_canary_job, const tracked_objects::Location& nudge_location) { DCHECK_EQ(MessageLoop::current(), sync_loop_); + DCHECK(!type_state_map.empty()) << "Nudge scheduled for no types!"; SDVLOG_LOC(nudge_location, 2) << "In ScheduleNudgeImpl with delay " @@ -597,6 +640,7 @@ void SyncSchedulerImpl::ScheduleNudgeImpl( << (is_canary_job ? " (canary)" : ""); SyncSourceInfo info(source, type_state_map); + UpdateNudgeTimeRecords(info); SyncSession* session(CreateSyncSession(info)); SyncSessionJob job(SyncSessionJob::NUDGE, TimeTicks::Now() + delay, @@ -700,6 +744,11 @@ void SyncSchedulerImpl::PostDelayedTask( void SyncSchedulerImpl::ScheduleSyncSessionJob(const SyncSessionJob& job) { DCHECK_EQ(MessageLoop::current(), sync_loop_); + if (no_scheduling_allowed_) { + NOTREACHED() << "Illegal to schedule job while session in progress."; + return; + } + TimeDelta delay = job.scheduled_start - TimeTicks::Now(); if (delay < TimeDelta::FromMilliseconds(0)) delay = TimeDelta::FromMilliseconds(0); @@ -725,6 +774,8 @@ void SyncSchedulerImpl::ScheduleSyncSessionJob(const SyncSessionJob& job) { void SyncSchedulerImpl::DoSyncSessionJob(const SyncSessionJob& job) { DCHECK_EQ(MessageLoop::current(), sync_loop_); + + AutoReset<bool> protector(&no_scheduling_allowed_, true); if (!ShouldRunJob(job)) { SLOG(WARNING) << "Not executing " @@ -769,24 +820,33 @@ void SyncSchedulerImpl::DoSyncSessionJob(const SyncSessionJob& job) { FinishSyncSessionJob(job); } -void SyncSchedulerImpl::FinishSyncSessionJob(const SyncSessionJob& job) { +void SyncSchedulerImpl::UpdateNudgeTimeRecords(const SyncSourceInfo& info) { DCHECK_EQ(MessageLoop::current(), sync_loop_); - // Update timing information for how often datatypes are triggering nudges. + + // We are interested in recording time between local nudges for datatypes. + // TODO(tim): Consider tracking LOCAL_NOTIFICATION as well. + if (info.updates_source != GetUpdatesCallerInfo::LOCAL) + return; + base::TimeTicks now = TimeTicks::Now(); - if (!last_sync_session_end_time_.is_null()) { - ModelTypeStateMap::const_iterator iter; - for (iter = job.session->source().types.begin(); - iter != job.session->source().types.end(); - ++iter) { + // Update timing information for how often datatypes are triggering nudges. + for (ModelTypeStateMap::const_iterator iter = info.types.begin(); + iter != info.types.end(); + ++iter) { + base::TimeTicks previous = last_local_nudges_by_model_type_[iter->first]; + last_local_nudges_by_model_type_[iter->first] = now; + if (previous.is_null()) + continue; + #define PER_DATA_TYPE_MACRO(type_str) \ - SYNC_FREQ_HISTOGRAM("Sync.Freq" type_str, \ - now - last_sync_session_end_time_); + SYNC_FREQ_HISTOGRAM("Sync.Freq" type_str, now - previous); SYNC_DATA_TYPE_HISTOGRAM(iter->first); #undef PER_DATA_TYPE_MACRO - } } - last_sync_session_end_time_ = now; +} +void SyncSchedulerImpl::FinishSyncSessionJob(const SyncSessionJob& job) { + DCHECK_EQ(MessageLoop::current(), sync_loop_); // Now update the status of the connection from SCM. We need this to decide // whether we need to save/run future jobs. The notifications from SCM are not // reliable. @@ -808,6 +868,7 @@ void SyncSchedulerImpl::FinishSyncSessionJob(const SyncSessionJob& job) { !job.config_params.ready_task.is_null()) { // If this was a configuration job with a ready task, invoke it now that // we finished successfully. + AutoReset<bool> protector(&no_scheduling_allowed_, true); job.config_params.ready_task.Run(); } @@ -974,10 +1035,6 @@ void SyncSchedulerImpl::DoPendingJobIfPossible(bool is_canary_job) { job_to_execute = wait_interval_->pending_configure_job.get(); } else if (mode_ == NORMAL_MODE && pending_nudge_.get()) { SDVLOG(2) << "Found pending nudge job"; - // Pending jobs mostly have time from the past. Reset it so this job - // will get executed. - if (pending_nudge_->scheduled_start < TimeTicks::Now()) - pending_nudge_->scheduled_start = TimeTicks::Now(); scoped_ptr<SyncSession> session(CreateSyncSession( pending_nudge_->session->source())); diff --git a/sync/engine/sync_scheduler_impl.h b/sync/engine/sync_scheduler_impl.h index 461455a..cf5e24c 100644 --- a/sync/engine/sync_scheduler_impl.h +++ b/sync/engine/sync_scheduler_impl.h @@ -5,6 +5,7 @@ #ifndef SYNC_ENGINE_SYNC_SCHEDULER_IMPL_H_ #define SYNC_ENGINE_SYNC_SCHEDULER_IMPL_H_ +#include <map> #include <string> #include "base/callback.h" @@ -278,6 +279,12 @@ class SyncSchedulerImpl : public SyncScheduler { // the client starts up and does not need to perform an initial sync. void SendInitialSnapshot(); + // This is used for histogramming and analysis of ScheduleNudge* APIs. + // SyncScheduler is the ultimate choke-point for all such invocations (with + // and without InvalidationState variants, all NudgeSources, etc) and as such + // is the most flexible place to do this bookkeeping. + void UpdateNudgeTimeRecords(const sessions::SyncSourceInfo& info); + virtual void OnActionableError(const sessions::SyncSessionSnapshot& snapshot); base::WeakPtrFactory<SyncSchedulerImpl> weak_ptr_factory_; @@ -313,10 +320,6 @@ class SyncSchedulerImpl : public SyncScheduler { // The mode of operation. Mode mode_; - // TODO(tim): Bug 26339. This needs to track more than just time I think, - // since the nudges could be for different types. Current impl doesn't care. - base::TimeTicks last_sync_session_end_time_; - // The latest connection code we got while trying to connect. HttpResponse::ServerConnectionCode connection_code_; @@ -331,7 +334,20 @@ class SyncSchedulerImpl : public SyncScheduler { // Invoked to run through the sync cycle. scoped_ptr<Syncer> syncer_; - sessions::SyncSessionContext *session_context_; + sessions::SyncSessionContext* session_context_; + + // A map tracking LOCAL NudgeSource invocations of ScheduleNudge* APIs, + // organized by datatype. Each datatype that was part of the types requested + // in the call will have its TimeTicks value updated. + typedef std::map<ModelType, base::TimeTicks> ModelTypeTimeMap; + ModelTypeTimeMap last_local_nudges_by_model_type_; + + // Used as an "anti-reentrancy defensive assertion". + // While true, it is illegal for any new scheduling activity to take place. + // Ensures that higher layers don't break this law in response to events that + // take place during a sync cycle. We call this out because such violations + // could result in tight sync loops hitting sync servers. + bool no_scheduling_allowed_; DISALLOW_COPY_AND_ASSIGN(SyncSchedulerImpl); }; diff --git a/sync/engine/sync_scheduler_unittest.cc b/sync/engine/sync_scheduler_unittest.cc index dbf7b4f..63dc3c3 100644 --- a/sync/engine/sync_scheduler_unittest.cc +++ b/sync/engine/sync_scheduler_unittest.cc @@ -105,11 +105,10 @@ class SyncSchedulerTest : public testing::Test { syncer_ = new MockSyncer(); delay_ = NULL; - ModelSafeRoutingInfo routing_info; - routing_info[BOOKMARKS] = GROUP_UI; - routing_info[AUTOFILL] = GROUP_DB; - routing_info[THEMES] = GROUP_UI; - routing_info[NIGORI] = GROUP_PASSIVE; + routing_info_[BOOKMARKS] = GROUP_UI; + routing_info_[AUTOFILL] = GROUP_DB; + routing_info_[THEMES] = GROUP_UI; + routing_info_[NIGORI] = GROUP_PASSIVE; workers_.push_back(make_scoped_refptr(new FakeModelWorker(GROUP_UI))); workers_.push_back(make_scoped_refptr(new FakeModelWorker(GROUP_DB))); @@ -129,7 +128,7 @@ class SyncSchedulerTest : public testing::Test { &extensions_activity_monitor_, throttled_data_type_tracker_.get(), std::vector<SyncEngineEventListener*>(), NULL, NULL, true /* enable keystore encryption */)); - context_->set_routing_info(routing_info); + context_->set_routing_info(routing_info_); context_->set_notifications_enabled(true); context_->set_account_name("Test"); scheduler_.reset( @@ -140,6 +139,7 @@ class SyncSchedulerTest : public testing::Test { } SyncSchedulerImpl* scheduler() { return scheduler_.get(); } + const ModelSafeRoutingInfo& routing_info() { return routing_info_; } MockSyncer* syncer() { return syncer_; } MockDelayProvider* delay() { return delay_; } MockConnectionManager* connection() { return connection_.get(); } @@ -184,7 +184,7 @@ class SyncSchedulerTest : public testing::Test { } bool RunAndGetBackoff() { - ModelTypeSet nudge_types; + ModelTypeSet nudge_types(BOOKMARKS); StartSyncScheduler(SyncScheduler::NORMAL_MODE); scheduler()->ScheduleNudgeAsync( @@ -233,6 +233,7 @@ class SyncSchedulerTest : public testing::Test { std::vector<scoped_refptr<FakeModelWorker> > workers_; FakeExtensionsActivityMonitor extensions_activity_monitor_; scoped_ptr<ThrottledDataTypeTracker> throttled_data_type_tracker_; + ModelSafeRoutingInfo routing_info_; }; void RecordSyncShareImpl(SyncSession* s, SyncShareRecords* record) { @@ -406,10 +407,16 @@ TEST_F(SyncSchedulerTest, NudgeWithConfigWithBackingOff) { scheduler()->ScheduleNudgeAsync( zero(), NUDGE_SOURCE_LOCAL, model_types, FROM_HERE); RunLoop(); + // Note that we're not RunLoop()ing for the NUDGE we just scheduled, but + // for the first retry attempt from the config job (after + // waiting ~+/- 50ms). ASSERT_EQ(2U, records.snapshots.size()); ASSERT_EQ(0, counter.times_called()); + EXPECT_EQ(GetUpdatesCallerInfo::RECONFIGURATION, + records.snapshots[1].source().updates_source); RunLoop(); + // This is the 3rd attempt, which we've set up to SimulateSuccess. ASSERT_EQ(3U, records.snapshots.size()); ASSERT_EQ(1, counter.times_called()); @@ -693,7 +700,7 @@ TEST_F(SyncSchedulerTest, HasMoreToSync) { StartSyncScheduler(SyncScheduler::NORMAL_MODE); scheduler()->ScheduleNudgeAsync( - zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(), FROM_HERE); + zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(BOOKMARKS), FROM_HERE); RunLoop(); // If more nudges are scheduled, they'll be waited on by TearDown, and would // cause our expectation to break. @@ -708,7 +715,7 @@ TEST_F(SyncSchedulerTest, HasMoreToSyncThenFails) { StartSyncScheduler(SyncScheduler::NORMAL_MODE); scheduler()->ScheduleNudgeAsync( - zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(), FROM_HERE); + zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(BOOKMARKS), FROM_HERE); // We should detect the failure on the second sync share, and go into backoff. EXPECT_TRUE(RunAndGetBackoff()); @@ -774,7 +781,8 @@ TEST_F(SyncSchedulerTest, ConfigurationMode) { scheduler()->OnReceivedLongPollIntervalUpdate(poll); EXPECT_CALL(*syncer(), SyncShare(_,_,_)) .WillOnce(DoAll(Invoke(sessions::test_util::SimulateSuccess), - WithArg<0>(RecordSyncShare(&records)))); + WithArg<0>(RecordSyncShare(&records)))) + .RetiresOnSaturation(); StartSyncScheduler(SyncScheduler::CONFIGURATION_MODE); @@ -798,6 +806,27 @@ TEST_F(SyncSchedulerTest, ConfigurationMode) { ASSERT_EQ(1U, records.snapshots.size()); EXPECT_TRUE(CompareModelTypeSetToModelTypeStateMap(config_types, records.snapshots[0].source().types)); + + // Switch to NORMAL_MODE to ensure NUDGES were properly saved and run. + // SyncSchedulerWhiteboxTest also provides coverage for this, but much + // more targeted ('whitebox' style). + scheduler()->OnReceivedLongPollIntervalUpdate(TimeDelta::FromDays(1)); + SyncShareRecords records2; + EXPECT_CALL(*syncer(), SyncShare(_,_,_)) + .WillOnce(DoAll(Invoke(sessions::test_util::SimulateSuccess), + WithArg<0>(RecordSyncShare(&records2)))); + + // TODO(tim): Figure out how to remove this dangerous need to reset + // routing info between mode switches. + context()->set_routing_info(routing_info()); + StartSyncScheduler(SyncScheduler::NORMAL_MODE); + + ASSERT_EQ(1U, records2.snapshots.size()); + EXPECT_EQ(GetUpdatesCallerInfo::LOCAL, + records2.snapshots[0].source().updates_source); + EXPECT_TRUE(CompareModelTypeSetToModelTypeStateMap(nudge_types, + records2.snapshots[0].source().types)); + PumpLoop(); } class BackoffTriggersSyncSchedulerTest : public SyncSchedulerTest { @@ -919,14 +948,6 @@ TEST_F(SyncSchedulerTest, BackoffDropsJobs) { base::Bind(&CallbackCounter::Callback, base::Unretained(&counter))); ASSERT_FALSE(scheduler()->ScheduleConfiguration(params)); ASSERT_EQ(0, counter.times_called()); - - StartSyncScheduler(SyncScheduler::NORMAL_MODE); - - scheduler()->ScheduleNudgeAsync( - zero(), NUDGE_SOURCE_LOCAL, types, FROM_HERE); - scheduler()->ScheduleNudgeAsync( - zero(), NUDGE_SOURCE_LOCAL, types, FROM_HERE); - PumpLoop(); } // Test that backoff is shaping traffic properly with consecutive errors. @@ -959,7 +980,7 @@ TEST_F(SyncSchedulerTest, BackoffElevation) { // Run again with a nudge. scheduler()->ScheduleNudgeAsync( - zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(), FROM_HERE); + zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(BOOKMARKS), FROM_HERE); RunLoop(); ASSERT_EQ(kMinNumSamples, r.snapshots.size()); @@ -991,7 +1012,7 @@ TEST_F(SyncSchedulerTest, BackoffRelief) { // Run again to wait for polling. scheduler()->ScheduleNudgeAsync(zero(), NUDGE_SOURCE_LOCAL, - ModelTypeSet(), FROM_HERE); + ModelTypeSet(BOOKMARKS), FROM_HERE); RunLoop(); StopSyncScheduler(); @@ -1052,7 +1073,7 @@ TEST_F(SyncSchedulerTest, SyncerSteps) { StartSyncScheduler(SyncScheduler::NORMAL_MODE); scheduler()->ScheduleNudgeAsync( - zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(), FROM_HERE); + zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(BOOKMARKS), FROM_HERE); PumpLoop(); // Pump again to run job. PumpLoop(); @@ -1097,11 +1118,6 @@ TEST_F(SyncSchedulerTest, SyncerSteps) { Mock::VerifyAndClearExpectations(syncer()); } -// Test config tasks don't run during normal mode. -// TODO(tim): Implement this test and then the functionality! -TEST_F(SyncSchedulerTest, DISABLED_NoConfigDuringNormal) { -} - // Test that starting the syncer thread without a valid connection doesn't // break things when a connection is detected. TEST_F(SyncSchedulerTest, StartWhenNotConnected) { @@ -1113,7 +1129,7 @@ TEST_F(SyncSchedulerTest, StartWhenNotConnected) { StartSyncScheduler(SyncScheduler::NORMAL_MODE); scheduler()->ScheduleNudgeAsync( - zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(), FROM_HERE); + zero(), NUDGE_SOURCE_LOCAL, ModelTypeSet(BOOKMARKS), FROM_HERE); // Should save the nudge for until after the server is reachable. MessageLoop::current()->RunAllPending(); diff --git a/sync/engine/sync_scheduler_whitebox_unittest.cc b/sync/engine/sync_scheduler_whitebox_unittest.cc index 7f4dfdb..0a9c73e 100644 --- a/sync/engine/sync_scheduler_whitebox_unittest.cc +++ b/sync/engine/sync_scheduler_whitebox_unittest.cc @@ -71,10 +71,6 @@ class SyncSchedulerWhiteboxTest : public testing::Test { scheduler_->mode_ = mode; } - void SetLastSyncedTime(base::TimeTicks ticks) { - scheduler_->last_sync_session_end_time_ = ticks; - } - void ResetWaitInterval() { scheduler_->wait_interval_.reset(); } @@ -103,7 +99,6 @@ class SyncSchedulerWhiteboxTest : public testing::Test { void InitializeSyncerOnNormalMode() { SetMode(SyncScheduler::NORMAL_MODE); ResetWaitInterval(); - SetLastSyncedTime(base::TimeTicks::Now()); } SyncSchedulerImpl::JobProcessDecision CreateAndDecideJob( diff --git a/sync/sessions/test_util.cc b/sync/sessions/test_util.cc index ef734b7..4214c3d 100644 --- a/sync/sessions/test_util.cc +++ b/sync/sessions/test_util.cc @@ -48,11 +48,19 @@ void SimulateSuccess(sessions::SyncSession* session, } ASSERT_EQ(0U, session->status_controller().num_server_changes_remaining()); session->SetFinished(); - if (end == SYNCER_END) { - session->mutable_status_controller()->set_last_get_key_result(SYNCER_OK); - session->mutable_status_controller()->set_last_download_updates_result( - SYNCER_OK); - session->mutable_status_controller()->set_commit_result(SYNCER_OK); + switch(end) { + case SYNCER_END: + session->mutable_status_controller()->set_commit_result(SYNCER_OK); + // Fall through. + case APPLY_UPDATES: + DCHECK_EQ(end == APPLY_UPDATES, session->source().updates_source == + sync_pb::GetUpdatesCallerInfo::RECONFIGURATION); + session->mutable_status_controller()->set_last_get_key_result(SYNCER_OK); + session->mutable_status_controller()->set_last_download_updates_result( + SYNCER_OK); + break; + default: + ADD_FAILURE() << "Not a valid END state."; } } |