sync: final pieces to sync deferred initialization

chrome/browser/sync/startup_controller.cc

+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "chrome/browser/sync/startup_controller.h"
+
+#include "base/command_line.h"
+#include "base/message_loop/message_loop.h"
+#include "base/metrics/histogram.h"
+#include "chrome/browser/managed_mode/managed_user_signin_manager_wrapper.h"
+#include "chrome/browser/signin/profile_oauth2_token_service.h"
+#include "chrome/browser/sync/sync_prefs.h"
+#include "chrome/common/chrome_switches.h"
+
+namespace browser_sync {
+
+namespace {
+
+// The amount of time we'll wait to initialize sync if no data type triggers
+// initialization via a StartSyncFlare.
+const int kDeferredInitFallbackSeconds = 10;
+
+// Enum (for UMA, primarily) defining different events that cause us to
+// exit the "deferred" state of initialization and invoke start_backend.
+enum DeferredInitTrigger {
+  // We have received a signal from a SyncableService requesting that sync
+  // starts as soon as possible.
+  TRIGGER_DATA_TYPE_REQUEST,
+  // No data type requested sync to start and our fallback timer expired.
+  TRIGGER_FALLBACK_TIMER,
+  MAX_TRIGGER_VALUE
+};
+
+}  // namespace
+
+StartupController::StartupController(
+    ProfileSyncServiceStartBehavior start_behavior,
+    ProfileOAuth2TokenService* token_service,
+    const browser_sync::SyncPrefs* sync_prefs,
+    const ManagedUserSigninManagerWrapper* signin,
+    base::Closure start_backend)
+    : received_start_request_(false),
+      setup_in_progress_(false),
+      auto_start_enabled_(start_behavior == AUTO_START),
+      sync_prefs_(sync_prefs),
+      token_service_(token_service),
+      signin_(signin),
+      start_backend_(start_backend),
+      fallback_timeout_(
+          base::TimeDelta::FromSeconds(kDeferredInitFallbackSeconds)),
+      weak_factory_(this) {}
+
+StartupController::~StartupController() {}
+
+void StartupController::Reset() {
+  received_start_request_ = false;
+  setup_in_progress_ = false;
+  start_up_time_ = base::Time();
+  start_backend_time_ = base::Time();
+  // Don't let previous timers affect us post-reset.
+  weak_factory_.InvalidateWeakPtrs();
+}
+
+void StartupController::set_setup_in_progress(bool in_progress) {
+  setup_in_progress_ = in_progress;
+}
+
+void StartupController::StartUp(StartUpDeferredOption deferred_option) {
+  const bool first_start = start_up_time_.is_null();
+  if (first_start)
+    start_up_time_ = base::Time::Now();
+
+  if (deferred_option == STARTUP_BACKEND_DEFERRED &&

[haitaol1, 2014/02/20 00:01:06]

I think the code can be simplified if this block is moved to TryStart(), i.e.
backend is always started when StartUp() is called. 
* StartUp() is only called once so first_start is not needed 
* You can bind to StartUp() directly, so OnFallbackStartupTimerExpired() is not
needed
* Only need to to update UMA "Sync.Startup.TimeDeferred" in StartUp().

Let me know if you'd like chat offline.

[tim (not reviewing), 2014/02/20 22:52:52]

I played around with this and it gets a little messy. I might still be
misunderstanding.  Here are the things I hit:

* TryStart can in theory be continually called by ProfileSyncService even after
we've started the backend and the conditions can continue to be true. Meaning
it'll take additional checks to ensure StartUp is only called once. We could
require the caller to not call in the already-initialized case, but I'd rather
it just be handled by no-op.
* We want to set start_up_time_ in the deferred init case but not call StartUp
to invoke the callback, meaning we'd have to inline the initialization of that
value in TryStart for one case but not the others.
* Having OnFallbackTimerExpired & OnDataTypeTriggered methods lets us record
extra UMA (DeferredInitTrigger) and gives an opportunity to add DCHECKs specific
to each case without extra parameters and if-cases to StartUp.  I like this for
the moment :/

So, the code I had at the end of TryStart wound up looking like

  if (sync_prefs_->HasSyncSetupCompleted()) {
    if (!received_start_request_) {
      if (start_up_time_.is_null()) {
        start_up_time_ = base::Time::Now();
        if (CommandLine::ForCurrentProcess()->
            HasSwitch(switches::kSyncEnableDeferredStartup)) {
          base::MessageLoop::current()->PostDelayedTask(
              FROM_HERE,
              base::Bind(&StartupController::OnFallbackStartupTimerExpired,
                         weak_factory_.GetWeakPtr()), fallback_timeout_);
          return;
        }
      }
    } else {
      StartUp();
    }
  } else if (setup_in_progress_ || auto_start_enabled_) {
    // We haven't completed sync setup. Start immediately if the user explicitly
    // kicked this off or we're supposed to automatically start syncing.
    StartUp();
  } 

So my inclination is to leave it for now, but maybe once the command line flag
is gone we can simplify?  That said, this led me to fix a few idempotency issues
(with start_backend_time_).

[haitaol1, 2014/02/25 00:53:01]

fair enough

On 2014/02/20 22:52:52, timsteele wrote:

+      CommandLine::ForCurrentProcess()->
+          HasSwitch(switches::kSyncEnableDeferredStartup)) {
+    if (first_start) {
+      base::MessageLoop::current()->PostDelayedTask(
+          FROM_HERE,
+          base::Bind(&StartupController::OnFallbackStartupTimerExpired,
+                     weak_factory_.GetWeakPtr()), fallback_timeout_);
+    }
+    return;
+  }
+
+  start_backend_time_ = base::Time::Now();
+  start_backend_.Run();
+}
+
+void StartupController::OverrideFallbackTimeoutForTest(
+    const base::TimeDelta& timeout) {
+  fallback_timeout_ = timeout;
+}
+
+void StartupController::TryStart() {

[haitaol1, 2014/02/20 00:01:06]

can you return a bool to indicate whether the conditions for startup are met?
Could be useful  later for determining whether should run in backup mode.

[tim (not reviewing), 2014/02/20 22:52:52]

Done.

+  if (sync_prefs_->IsManaged())
+    return;
+
+  if (sync_prefs_->IsStartSuppressed())
+    return;
+
+  if (signin_->GetEffectiveUsername().empty())
+    return;
+
+  if (!token_service_)
+    return;
+
+  if (!token_service_->RefreshTokenIsAvailable(
+          signin_->GetAccountIdToUse())) {
+    return;
+  }
+
+  // TODO(tim): Seems wrong to always record this histogram here...
+  // If we got here then tokens are loaded and user logged in and sync is
+  // enabled. If OAuth refresh token is not available then something is wrong.
+  // When PSS requests access token, OAuth2TokenService will return error and
+  // PSS will show error to user asking to reauthenticate.
+  UMA_HISTOGRAM_BOOLEAN("Sync.RefreshTokenAvailable", true);
+
+  // If sync setup has completed we always start the backend. If the user is in
+  // the process of setting up now, we should start the backend to download
+  // account control state / encryption information). If autostart is enabled,
+  // but we haven't completed sync setup, we try to start sync anyway, since
+  // it's possible we crashed/shutdown after logging in but before the backend
+  // finished initializing the last time.
+  //
+  // However, the only time we actually need to start sync _immediately_ is if
+  // we haven't completed sync setup and the user is in the process of setting
+  // up - either they just signed in (for the first time) on an auto-start
+  // platform or they explicitly kicked off sync setup, and e.g we need to
+  // fetch account details like encryption state to populate UI. Otherwise,
+  // for performance reasons and maximizing parallelism at chrome startup, we
+  // defer the heavy lifting for sync init until things have calmed down.
+  if (sync_prefs_->HasSyncSetupCompleted()) {
+    if (!received_start_request_)
+      StartUp(STARTUP_BACKEND_DEFERRED);
+    else
+      StartUp(STARTUP_IMMEDIATE);
+  } else if (setup_in_progress_ || auto_start_enabled_) {
+    // We haven't completed sync setup. Start immediately if the user explicitly
+    // kicked this off or we're supposed to automatically start syncing.
+    StartUp(STARTUP_IMMEDIATE);
+  }
+}
+
+void StartupController::OnFallbackStartupTimerExpired() {
+  DCHECK(CommandLine::ForCurrentProcess()->HasSwitch(
+      switches::kSyncEnableDeferredStartup));
+
+  if (!start_backend_time_.is_null())
+    return;
+
+  DVLOG(2) << "Sync deferred init fallback timer expired, starting backend.";
+  DCHECK(!start_up_time_.is_null());
+  base::TimeDelta time_deferred = base::Time::Now() - start_up_time_;
+  UMA_HISTOGRAM_TIMES("Sync.Startup.TimeDeferred", time_deferred);
+  UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
+                            TRIGGER_FALLBACK_TIMER,
+                            MAX_TRIGGER_VALUE);
+  received_start_request_ = true;
+  TryStart();

[haitaol1, 2014/02/20 00:01:06]

can you call StartUp() here? 

[tim (not reviewing), 2014/02/20 22:52:52]

The current model and one I'd like to stick to is that we always re-check
conditions when initializing sync.  It's protection against things like
IsManaged changing while the closure sits on the message loop, and is more
future-proof to new TryStart conditions that we deem "important".

+}
+
+std::string StartupController::GetBackendInitializationStateString() const {
+  if (!start_backend_time_.is_null())
+    return "Started";
+  else if (!start_up_time_.is_null())
+    return "Deferred";
+  else
+    return "Not started";
+}
+
+void StartupController::OnDataTypeRequestsSyncStartup(syncer::ModelType type) {
+  if (!CommandLine::ForCurrentProcess()->HasSwitch(
+          switches::kSyncEnableDeferredStartup)) {
+    DVLOG(2) << "Ignoring data type request for sync startup: "
+             << syncer::ModelTypeToString(type);
+    return;
+  }
+
+  if (!start_backend_time_.is_null())
+    return;
+
+  DVLOG(2) << "Data type requesting sync startup: "
+           << syncer::ModelTypeToString(type);
+  // Measure the time spent waiting for init and the type that triggered it.
+  // We could measure the time spent deferred on a per-datatype basis, but
+  // for now this is probably sufficient.
+  if (!start_up_time_.is_null()) {
+    base::TimeDelta time_deferred = base::Time::Now() - start_up_time_;
+    UMA_HISTOGRAM_TIMES("Sync.Startup.TimeDeferred", time_deferred);
+    UMA_HISTOGRAM_ENUMERATION("Sync.Startup.TypeTriggeringInit",

[haitaol1, 2014/02/20 00:01:06]

This UMA and the one below don't have to be in if{}. Seems better to update UMA
and TryStart() if the type is in pss->GetPreferredDataTypes().

[tim (not reviewing), 2014/02/20 22:52:52]

That data-type filtering is handled by the caller. I'll make a note in the
header.

As for the "if", nothing technically enforces that a flare can't be sent twice
by a datatype, so it seems prudent for us to protect against misuse like that
(bug or otherwise)? Or am I misunderstanding?

[haitaol1, 2014/02/25 00:53:01]

I'm more concerned that backend is started by disabled types? Is that possible?


On 2014/02/20 22:52:52, timsteele wrote:

[tim (not reviewing), 2014/02/25 01:17:44]

No, I don't believe so, because the caller (PSS) is responsible for filtering
the type by active types.

+                              ModelTypeToHistogramInt(type),
+                              syncer::MODEL_TYPE_COUNT);
+    UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
+                              TRIGGER_DATA_TYPE_REQUEST,
+                              MAX_TRIGGER_VALUE);
+  }
+  received_start_request_ = true;
+  TryStart();
+}
+
+}  // namespace browser_sync