Refactor Extension initialization logic. Add tracing and additional histogram.

chrome/browser/extensions/extension_service.cc

 // Copyright (c) 2013 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/extensions/extension_service.h"
 
 #include <algorithm>
 #include <iterator>
 #include <set>
 
@@ skipping 368 matching lines @@
     // includes those that have been disabled due to blacklisting or blocking.
     include_mask |= ExtensionRegistry::DISABLED |
                     ExtensionRegistry::BLACKLISTED | ExtensionRegistry::BLOCKED;
   }
   return registry_->GetExtensionById(id, include_mask);
 }
 
 void ExtensionService::Init() {
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   TRACE_EVENT0("browser,startup", "ExtensionService::Init");
-  base::Time begin_time = base::Time::Now();
+  SCOPED_UMA_HISTOGRAM_TIMER("Extensions.ExtensionServiceInitTime");
 
   DCHECK(!is_ready());  // Can't redo init.
   DCHECK_EQ(registry_->enabled_extensions().size(), 0u);
 
   const base::CommandLine* cmd_line = base::CommandLine::ForCurrentProcess();
   if (cmd_line->HasSwitch(switches::kInstallEphemeralAppFromWebstore)) {
     // The sole purpose of this launch is to install a new extension from CWS
     // and immediately terminate: loading already installed extensions is
     // unnecessary and may interfere with the inline install dialog (e.g. if an
     // extension listens to onStartup and opens a window).
     SetReadyAndNotifyListeners();
   } else {
     // LoadAllExtensions() calls OnLoadedInstalledExtensions().
     component_loader_->LoadAll();
     extensions::InstalledLoader(this).LoadAllExtensions();
 
-    // Attempt to re-enable extensions whose only disable reason is reloading.
-    std::vector<std::string> extensions_to_enable;
-    const ExtensionSet& disabled_extensions = registry_->disabled_extensions();
-    for (ExtensionSet::const_iterator iter = disabled_extensions.begin();
-        iter != disabled_extensions.end(); ++iter) {
-      const Extension* e = iter->get();
-      if (extension_prefs_->GetDisableReasons(e->id()) ==
-          Extension::DISABLE_RELOAD) {
-        extensions_to_enable.push_back(e->id());
-      }
-    }
-    for (std::vector<std::string>::iterator it = extensions_to_enable.begin();
-         it != extensions_to_enable.end(); ++it) {
-      EnableExtension(*it);
-    }
-
-    // Finish install (if possible) of extensions that were still delayed while
-    // the browser was shut down.
-    scoped_ptr<extensions::ExtensionPrefs::ExtensionsInfo> delayed_info(
-        extension_prefs_->GetAllDelayedInstallInfo());
-    for (size_t i = 0; i < delayed_info->size(); ++i) {
-      ExtensionInfo* info = delayed_info->at(i).get();
-      scoped_refptr<const Extension> extension(NULL);
-      if (info->extension_manifest) {
-        std::string error;
-        extension = Extension::Create(
-            info->extension_path,
-            info->extension_location,
-            *info->extension_manifest,
-            extension_prefs_->GetDelayedInstallCreationFlags(
-                info->extension_id),
-            info->extension_id,
-            &error);
-        if (extension.get())
-          delayed_installs_.Insert(extension);
-      }
-    }
-    MaybeFinishDelayedInstallations();
-
-    scoped_ptr<extensions::ExtensionPrefs::ExtensionsInfo> delayed_info2(
-        extension_prefs_->GetAllDelayedInstallInfo());
-    UMA_HISTOGRAM_COUNTS_100("Extensions.UpdateOnLoad",
-                             delayed_info2->size() - delayed_info->size());
-
+    EnabledReloadableExtensions();
+    MaybeFinishShutdownDelayed();
     SetReadyAndNotifyListeners();
 
-    // TODO(erikkay) this should probably be deferred to a future point
+    // TODO:(erikkay) this should probably be deferred to a future point

[Yoyo Zhou, 2015/02/25 00:19:57]

nit: TODO style is
// TODO(erikkay): etc.

[rkaplow, 2015/02/25 16:37:49]

Done.

     // rather than running immediately at startup.
     CheckForExternalUpdates();
 
     LoadGreylistFromPrefs();
   }
-
-  UMA_HISTOGRAM_TIMES("Extensions.ExtensionServiceInitTime",
-                      base::Time::Now() - begin_time);
 }
 
+void ExtensionService::EnabledReloadableExtensions() {
+  TRACE_EVENT0("browser,startup",
+               "ExtensionService::EnabledReloadableExtensions");
+
+  std::vector<std::string> extensions_to_enable;
+  const ExtensionSet& disabled_extensions = registry_->disabled_extensions();
+  for (ExtensionSet::const_iterator iter = disabled_extensions.begin();
+       iter != disabled_extensions.end(); ++iter) {
+    const Extension* e = iter->get();
+    if (extension_prefs_->GetDisableReasons(e->id()) ==
+        Extension::DISABLE_RELOAD) {
+      extensions_to_enable.push_back(e->id());
+    }
+  }
+  for (std::vector<std::string>::iterator it = extensions_to_enable.begin();
+        it != extensions_to_enable.end(); ++it) {

[Alexei Svitkine (slow), 2015/02/25 16:10:53]

Nit: Since you're touching this code already, this would be a lot cleaner using
C++11 for-based loop, i.e.:

for (const std::string& extension : extensions_to_enable) {
}

[rkaplow, 2015/02/25 16:37:49]

Done.

+    EnableExtension(*it);
+  }
+}
+
+void ExtensionService::MaybeFinishShutdownDelayed() {
+  TRACE_EVENT0("browser,startup",
+               "ExtensionService::MaybeFinishShutdownDelayed");
+
+  scoped_ptr<extensions::ExtensionPrefs::ExtensionsInfo> delayed_info(
+    extension_prefs_->GetAllDelayedInstallInfo());

[Alexei Svitkine (slow), 2015/02/25 16:10:53]

This should be indented 1 more. You could probably just run "git cl format".

[rkaplow, 2015/02/25 16:37:49]

Done.

+  for (size_t i = 0; i < delayed_info->size(); ++i) {
+    ExtensionInfo* info = delayed_info->at(i).get();
+    scoped_refptr<const Extension> extension(NULL);
+    if (info->extension_manifest) {
+      std::string error;
+      extension = Extension::Create(
+          info->extension_path,
+          info->extension_location,
+          *info->extension_manifest,
+          extension_prefs_->GetDelayedInstallCreationFlags(
+              info->extension_id),
+          info->extension_id,
+          &error);
+      if (extension.get())
+        delayed_installs_.Insert(extension);
+    }
+  }
+  MaybeFinishDelayedInstallations();
+  scoped_ptr<extensions::ExtensionPrefs::ExtensionsInfo> delayed_info2(
+    extension_prefs_->GetAllDelayedInstallInfo());
+  UMA_HISTOGRAM_COUNTS_100("Extensions.UpdateOnLoad",
+                           delayed_info2->size() - delayed_info->size());
+}
+

[Yoyo Zhou, 2015/02/25 00:19:58]

nit: extraneous newline

[rkaplow, 2015/02/25 16:37:49]

Done.

+
 void ExtensionService::LoadGreylistFromPrefs() {
+  TRACE_EVENT0("browser,startup",
+               "ExtensionService::LoadGreylistFromPrefs");
+
   scoped_ptr<ExtensionSet> all_extensions =
       registry_->GenerateInstalledExtensionsSet();
 
   for (ExtensionSet::const_iterator it = all_extensions->begin();
        it != all_extensions->end(); ++it) {
     extensions::BlacklistState state =
         extension_prefs_->GetExtensionBlacklistState((*it)->id());
     if (state == extensions::BLACKLISTED_SECURITY_VULNERABILITY ||
         state == extensions::BLACKLISTED_POTENTIALLY_UNWANTED ||
         state == extensions::BLACKLISTED_CWS_POLICY_VIOLATION)
@@ skipping 779 matching lines @@
     updater_->CheckSoon();
   } else {
     // Sync can start updating before all the external providers are ready
     // during startup. Start the update as soon as those providers are ready,
     // but not before.
     update_once_all_providers_are_ready_ = true;
   }
 }
 
 // Some extensions will autoupdate themselves externally from Chrome.  These
-// are typically part of some larger client application package.  To support
-// these, the extension will register its location in the the preferences file
+// are typically part of some larger client application package. To support
+// these, the extension will register its location in the preferences file
 // (and also, on Windows, in the registry) and this code will periodically
 // check that location for a .crx file, which it will then install locally if
 // a new version is available.
-// Errors are reported through ExtensionErrorReporter. Succcess is not
+// Errors are reported through ExtensionErrorReporter. Success is not
 // reported.
 void ExtensionService::CheckForExternalUpdates() {
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  TRACE_EVENT0("browser,startup",
+               "ExtensionService::CheckForExternalUpdates");
+  SCOPED_UMA_HISTOGRAM_TIMER("Extensions.CheckForExternalUpdatesTime");
 
   // Note that this installation is intentionally silent (since it didn't
   // go through the front-end).  Extensions that are registered in this
   // way are effectively considered 'pre-bundled', and so implicitly
   // trusted.  In general, if something has HKLM or filesystem access,
   // they could install an extension manually themselves anyway.
 
   // Ask each external extension provider to give us a call back for each
   // extension they know about. See OnExternalExtension(File|UpdateUrl)Found.
   extensions::ProviderCollection::const_iterator i;
@@ skipping 125 matching lines @@
   // Calling UnloadAllExtensionsForTest here triggers a false-positive presubmit
   // warning about calling test code in production.
   UnloadAllExtensionsInternal();
   component_loader_->LoadAll();
   extensions::InstalledLoader(this).LoadAllExtensions();
   // Don't call SetReadyAndNotifyListeners() since tests call this multiple
   // times.
 }
 
 void ExtensionService::SetReadyAndNotifyListeners() {
-  const base::TimeTicks start_time = base::TimeTicks::Now();
+  TRACE_EVENT0("browser,startup",
+               "ExtensionService::SetReadyAndNotifyListeners");
+  SCOPED_UMA_HISTOGRAM_TIMER(
+    "Extensions.ExtensionServiceNotifyReadyListenersTime");

[Yoyo Zhou, 2015/02/25 00:19:57]

There are two metrics related to this one:
Extensions.ProcessManagerStartupHostsTime and
Extensions.BackgroundContentsServiceStartupTime. (The functions being recorded
there are called from this function.) We could do the same for those as we do
here.

[rkaplow, 2015/02/25 16:37:49]

Ok, switched to the cleaner SCOPED version there.
I added the traces as well, although that will just be tracing the method calls,
so they won't match 1:1 to the times being measured, but that is ok.

+
   ready_->Signal();
   content::NotificationService::current()->Notify(
       extensions::NOTIFICATION_EXTENSIONS_READY_DEPRECATED,
       content::Source<Profile>(profile_),
       content::NotificationService::NoDetails());
-  UMA_HISTOGRAM_TIMES("Extensions.ExtensionServiceNotifyReadyListenersTime",
-                      base::TimeTicks::Now() - start_time);
 }
 
 void ExtensionService::OnLoadedInstalledExtensions() {
   if (updater_)
     updater_->Start();
 
   OnBlacklistUpdated();
 }
 
 void ExtensionService::AddExtension(const Extension* extension) {
@@ skipping 1112 matching lines @@
 }
 
 void ExtensionService::OnProfileDestructionStarted() {
   ExtensionIdSet ids_to_unload = registry_->enabled_extensions().GetIDs();
   for (ExtensionIdSet::iterator it = ids_to_unload.begin();
        it != ids_to_unload.end();
        ++it) {
     UnloadExtension(*it, UnloadedExtensionInfo::REASON_PROFILE_SHUTDOWN);
   }
 }