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