Adding more metrics under ProfileImpl::OnPrefsLoaded. Trying to get a good view in what causes the latency there.

BUG=454789

Review URL: https://codereview.chromium.org/1080063002

Cr-Commit-Position: refs/heads/master@{#325094}

5 files changed, 76 insertions, 2 deletions

diff --git a/chrome/browser/extensions/api/font_settings/font_settings_api.cc b/chrome/browser/extensions/api/font_settings/font_settings_api.cc
index 09d618d..bd9b1ec 100644
--- a/chrome/browser/extensions/api/font_settings/font_settings_api.cc
+++ b/chrome/browser/extensions/api/font_settings/font_settings_api.cc
@@ -10,9 +10,11 @@
 #include "base/command_line.h"
 #include "base/json/json_writer.h"
 #include "base/lazy_instance.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/prefs/pref_service.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
+#include "base/trace_event/trace_event.h"
 #include "base/values.h"
 #include "chrome/browser/chrome_notification_types.h"
 #include "chrome/browser/extensions/api/preference/preference_api.h"
@@ -94,6 +96,9 @@ void RegisterFontFamilyMapObserver(
 
 FontSettingsEventRouter::FontSettingsEventRouter(
     Profile* profile) : profile_(profile) {
+  TRACE_EVENT0("browser,startup", "FontSettingsEventRouter::ctor")
+  SCOPED_UMA_HISTOGRAM_TIMER("Extensions.FontSettingsEventRouterCtorTime");
+
   registrar_.Init(profile_->GetPrefs());
 
   AddPrefToObserve(prefs::kWebKitDefaultFixedFontSize,
diff --git a/components/history/core/browser/history_service.cc b/components/history/core/browser/history_service.cc
index 238b682..d78ac874 100644
--- a/components/history/core/browser/history_service.cc
+++ b/components/history/core/browser/history_service.cc
@@ -25,9 +25,11 @@
 #include "base/location.h"
 #include "base/memory/ref_counted.h"
 #include "base/message_loop/message_loop.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/threading/thread.h"
 #include "base/time/time.h"
+#include "base/trace_event/trace_event.h"
 #include "components/history/core/browser/download_row.h"
 #include "components/history/core/browser/history_backend.h"
 #include "components/history/core/browser/history_client.h"
@@ -851,8 +853,11 @@ bool HistoryService::Init(
     bool no_db,
     const std::string& languages,
     const HistoryDatabaseParams& history_database_params) {
+  TRACE_EVENT0("browser,startup", "HistoryService::Init")
+  SCOPED_UMA_HISTOGRAM_TIMER("History.HistoryServiceInitTime");
   DCHECK(thread_) << "History service being called after cleanup";
   DCHECK(thread_checker_.CalledOnValidThread());
+
   base::Thread::Options options;
   options.timer_slack = base::TIMER_SLACK_MAXIMUM;
   if (!thread_->StartWithOptions(options)) {
diff --git a/extensions/browser/api/storage/storage_frontend.cc b/extensions/browser/api/storage/storage_frontend.cc
index 62a7fd0..e94ecd8 100644
--- a/extensions/browser/api/storage/storage_frontend.cc
+++ b/extensions/browser/api/storage/storage_frontend.cc
@@ -9,6 +9,8 @@
 #include "base/files/file_path.h"
 #include "base/json/json_reader.h"
 #include "base/lazy_instance.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/trace_event/trace_event.h"
 #include "content/public/browser/browser_context.h"
 #include "content/public/browser/browser_thread.h"
 #include "extensions/browser/api/extensions_api_client.h"
@@ -83,6 +85,9 @@ StorageFrontend::StorageFrontend(
 
 void StorageFrontend::Init(
     const scoped_refptr<SettingsStorageFactory>& factory) {
+  TRACE_EVENT0("browser,startup", "StorageFrontend::Init")
+  SCOPED_UMA_HISTOGRAM_TIMER("Extensions.StorageFrontendInitTime");
+
   observers_ = new SettingsObserverList();
   browser_context_observer_.reset(new DefaultObserver(browser_context_));
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
diff --git a/extensions/browser/extension_prefs.cc b/extensions/browser/extension_prefs.cc
index 87ea7bc..44853c8 100644
--- a/extensions/browser/extension_prefs.cc
+++ b/extensions/browser/extension_prefs.cc
@@ -7,10 +7,12 @@
 #include <iterator>
 
 #include "base/command_line.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/prefs/pref_notifier.h"
 #include "base/prefs/pref_service.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
+#include "base/trace_event/trace_event.h"
 #include "base/value_conversions.h"
 #include "components/crx_file/id_util.h"
 #include "components/pref_registry/pref_registry_syncable.h"
@@ -1744,6 +1746,9 @@ void ExtensionPrefs::FixMissingPrefs(const ExtensionIdList& extension_ids) {
 }
 
 void ExtensionPrefs::InitPrefStore() {
+  TRACE_EVENT0("browser,startup", "ExtensionPrefs::InitPrefStore")
+  SCOPED_UMA_HISTOGRAM_TIMER("Extensions.InitPrefStoreTime");
+
   if (extensions_disabled_) {
     extension_pref_value_map_->NotifyInitializationCompleted();
     return;
@@ -1752,7 +1757,10 @@ void ExtensionPrefs::InitPrefStore() {
   // When this is called, the PrefService is initialized and provides access
   // to the user preferences stored in a JSON file.
   ExtensionIdList extension_ids;
-  GetExtensions(&extension_ids);
+  {
+    SCOPED_UMA_HISTOGRAM_TIMER("Extensions.InitPrefGetExtensionsTime");
+    GetExtensions(&extension_ids);
+  }
   // Create empty preferences dictionary for each extension (these dictionaries
   // are pruned when persisting the preferences to disk).
   for (ExtensionIdList::iterator ext_id = extension_ids.begin();
@@ -2037,6 +2045,10 @@ void ExtensionPrefs::PopulateExtensionInfoPrefs(
 
 void ExtensionPrefs::InitExtensionControlledPrefs(
     ExtensionPrefValueMap* value_map) {
+  TRACE_EVENT0("browser,startup",
+               "ExtensionPrefs::InitExtensionControlledPrefs")
+  SCOPED_UMA_HISTOGRAM_TIMER("Extensions.InitExtensionControlledPrefsTime");
+
   ExtensionIdList extension_ids;
   GetExtensions(&extension_ids);
 
diff --git a/tools/metrics/histograms/histograms.xml b/tools/metrics/histograms/histograms.xml
index 3f97e5f..a2a957d 100644
--- a/tools/metrics/histograms/histograms.xml
+++ b/tools/metrics/histograms/histograms.xml
@@ -8789,7 +8789,7 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
-<histogram name="Extensions.CheckForExternalUpdatesTime">
+<histogram name="Extensions.CheckForExternalUpdatesTime" units="milliseconds">
   <owner>rkaplow@chromium.org</owner>
   <summary>
     The amount of time that elapsed during
@@ -9248,6 +9248,15 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="Extensions.FontSettingsEventRouterCtorTime"
+    units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during the FontSettingsEventRouter
+    construction.
+  </summary>
+</histogram>
+
 <histogram name="Extensions.FromWebstoreInconsistency"
     enum="ExtensionFromWebstoreInconcistencyEnum">
   <owner>Please list the metric's owners. Add more owner tags as needed.</owner>
@@ -9343,6 +9352,30 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="Extensions.InitExtensionControlledPrefsTime"
+    units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during
+    ExtensionPrefs::InitExtensionControlledPrefs.
+  </summary>
+</histogram>
+
+<histogram name="Extensions.InitPrefGetExtensionsTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during the GetExtensions call within
+    ExtensionPrefs::InitPrefStore.
+  </summary>
+</histogram>
+
+<histogram name="Extensions.InitPrefStoreTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during ExtensionPrefs::InitPrefStore.
+  </summary>
+</histogram>
+
 <histogram name="Extensions.InjectCssTime" units="milliseconds">
   <owner>kalman@chromium.org</owner>
   <owner>rdevlin.cronin@chromium.org</owner>
@@ -10165,6 +10198,13 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="Extensions.StorageFrontendInitTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during StorageFrontend::Init.
+  </summary>
+</histogram>
+
 <histogram name="Extensions.ThrottledNetworkRequestDelay" units="milliseconds">
   <owner>rdevlin.cronin@chromium.org</owner>
   <owner>kalman@chromium.org</owner>
@@ -11595,6 +11635,13 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="History.HistoryServiceInitTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during HistoryService::Init.
+  </summary>
+</histogram>
+
 <histogram name="History.NumFaviconBitmapsInDB">
   <owner>rogerm@chromium.org</owner>
   <summary>