Home | History | Annotate | Download | only in sync 
      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 
     55   if (CommandLine::ForCurrentProcess()->HasSwitch(
     56           switches::kSyncDeferredStartupTimeoutSeconds)) {
     57     int timeout = kDeferredInitFallbackSeconds;
     58     if (base::StringToInt(CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
     59             switches::kSyncDeferredStartupTimeoutSeconds), &timeout)) {
     60       DCHECK_GE(timeout, 0);
     61       DVLOG(2) << "Sync StartupController overriding startup timeout to "
     62                << timeout << " seconds.";
     63       fallback_timeout_ = base::TimeDelta::FromSeconds(timeout);
     64     }
     65   }
     66 }
     67 
     68 StartupController::~StartupController() {}
     69 
     70 void StartupController::Reset(const syncer::ModelTypeSet registered_types) {
     71   received_start_request_ = false;
     72   start_up_time_ = base::Time();
     73   start_backend_time_ = base::Time();
     74   // Don't let previous timers affect us post-reset.
     75   weak_factory_.InvalidateWeakPtrs();
     76   registered_types_ = registered_types;
     77 }
     78 
     79 void StartupController::set_setup_in_progress(bool in_progress) {
     80   setup_in_progress_ = in_progress;
     81 }
     82 
     83 bool StartupController::StartUp(StartUpDeferredOption deferred_option) {
     84   const bool first_start = start_up_time_.is_null();
     85   if (first_start)
     86     start_up_time_ = base::Time::Now();
     87 
     88   if (deferred_option == STARTUP_BACKEND_DEFERRED &&
     89       !CommandLine::ForCurrentProcess()->HasSwitch(
     90           switches::kSyncDisableDeferredStartup) &&
     91       sync_prefs_->GetPreferredDataTypes(registered_types_)
     92           .Has(syncer::SESSIONS)) {
     93     if (first_start) {
     94       base::MessageLoop::current()->PostDelayedTask(
     95           FROM_HERE,
     96           base::Bind(&StartupController::OnFallbackStartupTimerExpired,
     97                      weak_factory_.GetWeakPtr()), fallback_timeout_);
     98     }
     99     return false;
    100   }
    101 
    102   if (start_backend_time_.is_null()) {
    103     start_backend_time_ = base::Time::Now();
    104     start_backend_.Run();
    105     first_start_ = false;
    106   }
    107 
    108   return true;
    109 }
    110 
    111 void StartupController::OverrideFallbackTimeoutForTest(
    112     const base::TimeDelta& timeout) {
    113   fallback_timeout_ = timeout;
    114 }
    115 
    116 bool StartupController::TryStart() {
    117   if (sync_prefs_->IsManaged())
    118     return false;
    119 
    120   if (sync_prefs_->IsStartSuppressed())
    121     return false;
    122 
    123   if (signin_->GetEffectiveUsername().empty())
    124     return false;
    125 
    126   if (!token_service_)
    127     return false;
    128 
    129   if (!token_service_->RefreshTokenIsAvailable(
    130           signin_->GetAccountIdToUse())) {
    131     return false;
    132   }
    133 
    134   // TODO(tim): Seems wrong to always record this histogram here...
    135   // If we got here then tokens are loaded and user logged in and sync is
    136   // enabled. If OAuth refresh token is not available then something is wrong.
    137   // When PSS requests access token, OAuth2TokenService will return error and
    138   // PSS will show error to user asking to reauthenticate.
    139   UMA_HISTOGRAM_BOOLEAN("Sync.RefreshTokenAvailable", true);
    140 
    141   // If sync setup has completed we always start the backend. If the user is in
    142   // the process of setting up now, we should start the backend to download
    143   // account control state / encryption information). If autostart is enabled,
    144   // but we haven't completed sync setup, we try to start sync anyway, since
    145   // it's possible we crashed/shutdown after logging in but before the backend
    146   // finished initializing the last time.
    147   //
    148   // However, the only time we actually need to start sync _immediately_ is if
    149   // we haven't completed sync setup and the user is in the process of setting
    150   // up - either they just signed in (for the first time) on an auto-start
    151   // platform or they explicitly kicked off sync setup, and e.g we need to
    152   // fetch account details like encryption state to populate UI. Otherwise,
    153   // for performance reasons and maximizing parallelism at chrome startup, we
    154   // defer the heavy lifting for sync init until things have calmed down.
    155   if (sync_prefs_->HasSyncSetupCompleted()) {
    156     // For first time, defer start if data type hasn't requested sync to avoid
    157     // stressing browser start. If |first_start_| is false, most likely the
    158     // first attempt to start is intercepted by backup. When backup finishes,
    159     // TryStart() is called again and we should start immediately to avoid
    160     // unnecessary delay.
    161     if (!received_start_request_ && first_start_)
    162       return StartUp(STARTUP_BACKEND_DEFERRED);
    163     else
    164       return StartUp(STARTUP_IMMEDIATE);
    165   } else if (setup_in_progress_ || auto_start_enabled_) {
    166     // We haven't completed sync setup. Start immediately if the user explicitly
    167     // kicked this off or we're supposed to automatically start syncing.
    168     return StartUp(STARTUP_IMMEDIATE);
    169   }
    170 
    171   return false;
    172 }
    173 
    174 void StartupController::RecordTimeDeferred() {
    175   DCHECK(!start_up_time_.is_null());
    176   base::TimeDelta time_deferred = base::Time::Now() - start_up_time_;
    177   UMA_HISTOGRAM_CUSTOM_TIMES("Sync.Startup.TimeDeferred2",
    178       time_deferred,
    179       base::TimeDelta::FromSeconds(0),
    180       base::TimeDelta::FromMinutes(2),
    181       60);
    182 }
    183 
    184 void StartupController::OnFallbackStartupTimerExpired() {
    185   DCHECK(!CommandLine::ForCurrentProcess()->HasSwitch(
    186       switches::kSyncDisableDeferredStartup));
    187 
    188   if (!start_backend_time_.is_null())
    189     return;
    190 
    191   DVLOG(2) << "Sync deferred init fallback timer expired, starting backend.";
    192   RecordTimeDeferred();
    193   UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
    194                             TRIGGER_FALLBACK_TIMER,
    195                             MAX_TRIGGER_VALUE);
    196   received_start_request_ = true;
    197   TryStart();
    198 }
    199 
    200 std::string StartupController::GetBackendInitializationStateString() const {
    201   if (!start_backend_time_.is_null())
    202     return "Started";
    203   else if (!start_up_time_.is_null())
    204     return "Deferred";
    205   else
    206     return "Not started";
    207 }
    208 
    209 void StartupController::OnDataTypeRequestsSyncStartup(syncer::ModelType type) {
    210   if (CommandLine::ForCurrentProcess()->HasSwitch(
    211           switches::kSyncDisableDeferredStartup)) {
    212     DVLOG(2) << "Ignoring data type request for sync startup: "
    213              << syncer::ModelTypeToString(type);
    214     return;
    215   }
    216 
    217   if (!start_backend_time_.is_null())
    218     return;
    219 
    220   DVLOG(2) << "Data type requesting sync startup: "
    221            << syncer::ModelTypeToString(type);
    222   // Measure the time spent waiting for init and the type that triggered it.
    223   // We could measure the time spent deferred on a per-datatype basis, but
    224   // for now this is probably sufficient.
    225   if (!start_up_time_.is_null()) {
    226     RecordTimeDeferred();
    227     UMA_HISTOGRAM_ENUMERATION("Sync.Startup.TypeTriggeringInit",
    228                               ModelTypeToHistogramInt(type),
    229                               syncer::MODEL_TYPE_COUNT);
    230     UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
    231                               TRIGGER_DATA_TYPE_REQUEST,
    232                               MAX_TRIGGER_VALUE);
    233   }
    234   received_start_request_ = true;
    235   TryStart();
    236 }
    237 
    238 }  // namespace browser_sync
    239