chrome/browser/sync/startup_controller.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "chrome/browser/sync/startup_controller.h"
   6
   7 #include "base/command_line.h"
   8 #include "base/message_loop/message_loop.h"
   9 #include "base/metrics/histogram.h"
  10 #include "base/strings/string_number_conversions.h"
  11 #include "chrome/browser/sync/supervised_user_signin_manager_wrapper.h"
  12 #include "chrome/common/chrome_switches.h"
  13 #include "components/signin/core/browser/profile_oauth2_token_service.h"
  14 #include "components/sync_driver/sync_prefs.h"
  15
  16 namespace browser_sync {
  17
  18 namespace {
  19
  20 // The amount of time we'll wait to initialize sync if no data type triggers
  21 // initialization via a StartSyncFlare.
  22 const int kDeferredInitFallbackSeconds = 10;
  23
  24 // Enum (for UMA, primarily) defining different events that cause us to
  25 // exit the "deferred" state of initialization and invoke start_backend.
  26 enum DeferredInitTrigger {
  27   // We have received a signal from a SyncableService requesting that sync
  28   // starts as soon as possible.
  29   TRIGGER_DATA_TYPE_REQUEST,
  30   // No data type requested sync to start and our fallback timer expired.
  31   TRIGGER_FALLBACK_TIMER,
  32   MAX_TRIGGER_VALUE
  33 };
  34
  35 }  // namespace
  36
  37 StartupController::StartupController(
  38     ProfileSyncServiceStartBehavior start_behavior,
  39     const ProfileOAuth2TokenService* token_service,
  40     const sync_driver::SyncPrefs* sync_prefs,
  41     const SupervisedUserSigninManagerWrapper* signin,
  42     base::Closure start_backend)
  43     : received_start_request_(false),
  44       setup_in_progress_(false),
  45       auto_start_enabled_(start_behavior == AUTO_START),
  46       sync_prefs_(sync_prefs),
  47       token_service_(token_service),
  48       signin_(signin),
  49       start_backend_(start_backend),
  50       fallback_timeout_(
  51           base::TimeDelta::FromSeconds(kDeferredInitFallbackSeconds)),
  52       first_start_(true),
  53       weak_factory_(this) {
  54   if (base::CommandLine::ForCurrentProcess()->HasSwitch(
  55           switches::kSyncDeferredStartupTimeoutSeconds)) {
  56     int timeout = kDeferredInitFallbackSeconds;
  57     if (base::StringToInt(
  58             base::CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
  59                 switches::kSyncDeferredStartupTimeoutSeconds),
  60             &timeout)) {
  61       DCHECK_GE(timeout, 0);
  62       DVLOG(2) << "Sync StartupController overriding startup timeout to "
  63                << timeout << " seconds.";
  64       fallback_timeout_ = base::TimeDelta::FromSeconds(timeout);
  65     }
  66   }
  67 }
  68
  69 StartupController::~StartupController() {}
  70
  71 void StartupController::Reset(const syncer::ModelTypeSet registered_types) {
  72   received_start_request_ = false;
  73   start_up_time_ = base::Time();
  74   start_backend_time_ = base::Time();
  75   // Don't let previous timers affect us post-reset.
  76   weak_factory_.InvalidateWeakPtrs();
  77   registered_types_ = registered_types;
  78 }
  79
  80 void StartupController::set_setup_in_progress(bool in_progress) {
  81   setup_in_progress_ = in_progress;
  82 }
  83
  84 bool StartupController::StartUp(StartUpDeferredOption deferred_option) {
  85   const bool first_start = start_up_time_.is_null();
  86   if (first_start)
  87     start_up_time_ = base::Time::Now();
  88
  89   if (deferred_option == STARTUP_BACKEND_DEFERRED &&
  90       !base::CommandLine::ForCurrentProcess()->HasSwitch(
  91           switches::kSyncDisableDeferredStartup) &&
  92       sync_prefs_->GetPreferredDataTypes(registered_types_)
  93           .Has(syncer::SESSIONS)) {
  94     if (first_start) {
  95       base::MessageLoop::current()->PostDelayedTask(
  96           FROM_HERE,
  97           base::Bind(&StartupController::OnFallbackStartupTimerExpired,
  98                      weak_factory_.GetWeakPtr()), fallback_timeout_);
  99     }
 100     return false;
 101   }
 102
 103   if (start_backend_time_.is_null()) {
 104     start_backend_time_ = base::Time::Now();
 105     start_backend_.Run();
 106     first_start_ = false;
 107   }
 108
 109   return true;
 110 }
 111
 112 void StartupController::OverrideFallbackTimeoutForTest(
 113     const base::TimeDelta& timeout) {
 114   fallback_timeout_ = timeout;
 115 }
 116
 117 bool StartupController::TryStart() {
 118   if (sync_prefs_->IsManaged())
 119     return false;
 120
 121   if (sync_prefs_->IsStartSuppressed())
 122     return false;
 123
 124   if (signin_->GetEffectiveUsername().empty())
 125     return false;
 126
 127   if (!token_service_)
 128     return false;
 129
 130   if (!token_service_->RefreshTokenIsAvailable(
 131           signin_->GetAccountIdToUse())) {
 132     return false;
 133   }
 134
 135   // TODO(tim): Seems wrong to always record this histogram here...
 136   // If we got here then tokens are loaded and user logged in and sync is
 137   // enabled. If OAuth refresh token is not available then something is wrong.
 138   // When PSS requests access token, OAuth2TokenService will return error and
 139   // PSS will show error to user asking to reauthenticate.
 140   UMA_HISTOGRAM_BOOLEAN("Sync.RefreshTokenAvailable", true);
 141
 142   // If sync setup has completed we always start the backend. If the user is in
 143   // the process of setting up now, we should start the backend to download
 144   // account control state / encryption information). If autostart is enabled,
 145   // but we haven't completed sync setup, we try to start sync anyway, since
 146   // it's possible we crashed/shutdown after logging in but before the backend
 147   // finished initializing the last time.
 148   //
 149   // However, the only time we actually need to start sync _immediately_ is if
 150   // we haven't completed sync setup and the user is in the process of setting
 151   // up - either they just signed in (for the first time) on an auto-start
 152   // platform or they explicitly kicked off sync setup, and e.g we need to
 153   // fetch account details like encryption state to populate UI. Otherwise,
 154   // for performance reasons and maximizing parallelism at chrome startup, we
 155   // defer the heavy lifting for sync init until things have calmed down.
 156   if (sync_prefs_->HasSyncSetupCompleted()) {
 157     // For first time, defer start if data type hasn't requested sync to avoid
 158     // stressing browser start. If |first_start_| is false, most likely the
 159     // first attempt to start is intercepted by backup. When backup finishes,
 160     // TryStart() is called again and we should start immediately to avoid
 161     // unnecessary delay.
 162     if (!received_start_request_ && first_start_)
 163       return StartUp(STARTUP_BACKEND_DEFERRED);
 164     else
 165       return StartUp(STARTUP_IMMEDIATE);
 166   } else if (setup_in_progress_ || auto_start_enabled_) {
 167     // We haven't completed sync setup. Start immediately if the user explicitly
 168     // kicked this off or we're supposed to automatically start syncing.
 169     return StartUp(STARTUP_IMMEDIATE);
 170   }
 171
 172   return false;
 173 }
 174
 175 void StartupController::RecordTimeDeferred() {
 176   DCHECK(!start_up_time_.is_null());
 177   base::TimeDelta time_deferred = base::Time::Now() - start_up_time_;
 178   UMA_HISTOGRAM_CUSTOM_TIMES("Sync.Startup.TimeDeferred2",
 179       time_deferred,
 180       base::TimeDelta::FromSeconds(0),
 181       base::TimeDelta::FromMinutes(2),
 182       60);
 183 }
 184
 185 void StartupController::OnFallbackStartupTimerExpired() {
 186   DCHECK(!base::CommandLine::ForCurrentProcess()->HasSwitch(
 187       switches::kSyncDisableDeferredStartup));
 188
 189   if (!start_backend_time_.is_null())
 190     return;
 191
 192   DVLOG(2) << "Sync deferred init fallback timer expired, starting backend.";
 193   RecordTimeDeferred();
 194   UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
 195                             TRIGGER_FALLBACK_TIMER,
 196                             MAX_TRIGGER_VALUE);
 197   received_start_request_ = true;
 198   TryStart();
 199 }
 200
 201 std::string StartupController::GetBackendInitializationStateString() const {
 202   if (!start_backend_time_.is_null())
 203     return "Started";
 204   else if (!start_up_time_.is_null())
 205     return "Deferred";
 206   else
 207     return "Not started";
 208 }
 209
 210 void StartupController::OnDataTypeRequestsSyncStartup(syncer::ModelType type) {
 211   if (base::CommandLine::ForCurrentProcess()->HasSwitch(
 212           switches::kSyncDisableDeferredStartup)) {
 213     DVLOG(2) << "Ignoring data type request for sync startup: "
 214              << syncer::ModelTypeToString(type);
 215     return;
 216   }
 217
 218   if (!start_backend_time_.is_null())
 219     return;
 220
 221   DVLOG(2) << "Data type requesting sync startup: "
 222            << syncer::ModelTypeToString(type);
 223   // Measure the time spent waiting for init and the type that triggered it.
 224   // We could measure the time spent deferred on a per-datatype basis, but
 225   // for now this is probably sufficient.
 226   if (!start_up_time_.is_null()) {
 227     RecordTimeDeferred();
 228     UMA_HISTOGRAM_ENUMERATION("Sync.Startup.TypeTriggeringInit",
 229                               ModelTypeToHistogramInt(type),
 230                               syncer::MODEL_TYPE_COUNT);
 231     UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
 232                               TRIGGER_DATA_TYPE_REQUEST,
 233                               MAX_TRIGGER_VALUE);
 234   }
 235   received_start_request_ = true;
 236   TryStart();
 237 }
 238
 239 }  // namespace browser_sync