Add several new TRACE call and UMA metrics for SetupProfile().

I've replaced measuring GetProfile() (which includes cached profiles) with SetupProfile() which is more useful to track. I've added metrics to track the expensive components under SetupProfile(), which are
-chrome::RegisterProfilePrefs
-chrome_prefs::CreateProfilePrefs
-ProfileImpl::OnPrefsLoaded.

There currently are UMA histograms called Startup.SlowStartupPreferenceLoading, but I'm setting up different versions of these. They are tracking almost but not exactly the same things, but the current ones are only triggered for slow startups.
I considered modifying these to add a control version, but I thought adding new ones was better because:
-The histograms I'm adding have better names since they are called what they are actually checking
-I'm measuring at what I think is a better place (inside the method itself instead of near the caller.
-The new histograms are easily comparable for the work I'm doing since they are for all data (can just check percentile data).

Also changed the TRACE argument from path.value().c_str() to path.MaybeAsASCII() since the former was only giving the address inside the trace (I'm guessing it never worked).

If someone wants to have themselves also be added as an owner to any of the new histograms let me know.

BUG=454789

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

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

chrome/browser/prefs/browser_prefs.cc

@@ -6,7 +6,7 @@
 
 #include <string>
 
-#include "base/metrics/histogram.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/prefs/pref_registry_simple.h"
 #include "base/prefs/pref_service.h"
 #include "base/prefs/scoped_user_pref_update.h"
@@ -379,7 +379,8 @@ void RegisterLocalState(PrefRegistrySimple* registry) {
 
 // Register prefs applicable to all profiles.
 void RegisterProfilePrefs(user_prefs::PrefRegistrySyncable* registry) {
-  TRACE_EVENT0("browser", "chrome::RegisterUserPrefs");
+  TRACE_EVENT0("browser", "chrome::RegisterProfilePrefs");
+  SCOPED_UMA_HISTOGRAM_TIMER("Settings.RegisterProfilePrefsTime");
   // User prefs. Please keep this list alphabetized.
   autofill::AutofillManager::RegisterProfilePrefs(registry);
   bookmarks::RegisterProfilePrefs(registry);

chrome/browser/prefs/chrome_pref_service_factory.cc

@@ -11,7 +11,7 @@
 #include "base/compiler_specific.h"
 #include "base/files/file_path.h"
 #include "base/metrics/field_trial.h"
-#include "base/metrics/histogram.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/prefs/default_pref_store.h"
 #include "base/prefs/json_pref_store.h"
 #include "base/prefs/pref_filter.h"
@@ -501,6 +501,7 @@ scoped_ptr<PrefServiceSyncable> CreateProfilePrefs(
     const scoped_refptr<user_prefs::PrefRegistrySyncable>& pref_registry,
     bool async) {
   TRACE_EVENT0("browser", "chrome_prefs::CreateProfilePrefs");
+  SCOPED_UMA_HISTOGRAM_TIMER("PrefService.CreateProfilePrefsTime");
 
   // A StartSyncFlare used to kick sync early in case of a reset event. This is
   // done since sync may bring back the user's server value post-reset which

chrome/browser/profiles/profile_impl.cc

@@ -15,6 +15,7 @@
 #include "base/files/file_util.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/memory/weak_ptr.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/path_service.h"
 #include "base/prefs/json_pref_store.h"
 #include "base/prefs/scoped_user_pref_update.h"
@@ -266,10 +267,10 @@ PrefStore* CreateExtensionPrefStore(Profile* profile,
 Profile* Profile::CreateProfile(const base::FilePath& path,
                                 Delegate* delegate,
                                 CreateMode create_mode) {
-  TRACE_EVENT_BEGIN1("browser",
+  TRACE_EVENT1("browser,startup",
                "Profile::CreateProfile",
                "profile_path",
-                     path.value().c_str());
+               path.AsUTF8Unsafe());
 
   // Get sequenced task runner for making sure that file operations of
   // this profile (defined by |path|) are executed in expected order
@@ -282,9 +283,9 @@ Profile* Profile::CreateProfile(const base::FilePath& path,
     CreateProfileDirectory(sequenced_task_runner.get(), path);
   } else if (create_mode == CREATE_MODE_SYNCHRONOUS) {
     if (!base::PathExists(path)) {
-      // TODO(tc): http://b/1094718 Bad things happen if we can't write to the
-      // profile directory.  We should eventually be able to run in this
-      // situation.
+      // TODO(rogerta): http://crbug/160553 - Bad things happen if we can't
+      // write to the profile directory.  We should eventually be able to run in
+      // this situation.
       if (!base::CreateDirectory(path))
         return NULL;
     }
@@ -411,7 +412,7 @@ ProfileImpl::ProfileImpl(
       start_time_(Time::Now()),
       delegate_(delegate),
       predictor_(NULL) {
-  TRACE_EVENT0("browser", "ProfileImpl::ctor")
+  TRACE_EVENT0("browser,startup", "ProfileImpl::ctor")
   DCHECK(!path.empty()) << "Using an empty path will attempt to write " <<
                             "profile files to the root directory!";
 
@@ -666,12 +667,6 @@ void ProfileImpl::DoFinalInit() {
   // as a URLDataSource early.
   RegisterDomDistillerViewerSource(this);
 
-  // Creation has been finished.
-  TRACE_EVENT_END1("browser",
-                   "Profile::CreateProfile",
-                   "profile_path",
-                   path_.value().c_str());
-
 #if defined(OS_CHROMEOS)
   if (chromeos::UserSessionManager::GetInstance()
           ->RestartToApplyPerSessionFlagsIfNeed(this, true)) {
@@ -848,7 +843,8 @@ ExtensionSpecialStoragePolicy*
 }
 
 void ProfileImpl::OnPrefsLoaded(bool success) {
-  TRACE_EVENT0("browser", "ProfileImpl::OnPrefsLoaded")
+  TRACE_EVENT0("browser", "ProfileImpl::OnPrefsLoaded");
+  SCOPED_UMA_HISTOGRAM_TIMER("Profile.OnPrefsLoadedTime");
   if (!success) {
     if (delegate_)
       delegate_->OnProfileCreated(this, false, false);

chrome/browser/profiles/profile_manager.cc

@@ -374,21 +374,13 @@ Profile* ProfileManager::GetActiveUserProfile() {
 
 Profile* ProfileManager::GetProfile(const base::FilePath& profile_dir) {
   TRACE_EVENT0("browser", "ProfileManager::GetProfile");
-  SCOPED_UMA_HISTOGRAM_TIMER("Profile.GetProfile");
 
   // If the profile is already loaded (e.g., chrome.exe launched twice), just
   // return it.
   Profile* profile = GetProfileByPath(profile_dir);
   if (NULL != profile)
     return profile;
-
-  profile = CreateProfileHelper(profile_dir);
-  DCHECK(profile);
-  if (profile) {
-    bool result = AddProfile(profile);
-    DCHECK(result);
-  }
-  return profile;
+  return CreateAndInitializeProfile(profile_dir);
 }
 
 size_t ProfileManager::GetNumberOfProfiles() {
@@ -402,10 +394,10 @@ void ProfileManager::CreateProfileAsync(
     const base::string16& icon_url,
     const std::string& supervised_user_id) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
-  TRACE_EVENT1("startup",
+  TRACE_EVENT1("browser,startup",
                "ProfileManager::CreateProfileAsync",
                "profile_path",
-               profile_path.value().c_str());
+               profile_path.AsUTF8Unsafe());
 
   // Make sure that this profile is not pending deletion.
   if (IsProfileMarkedForDeletion(profile_path)) {
@@ -1076,6 +1068,8 @@ void ProfileManager::DoFinalInitLogging(Profile* profile) {
 
 Profile* ProfileManager::CreateProfileHelper(const base::FilePath& path) {
   TRACE_EVENT0("browser", "ProfileManager::CreateProfileHelper");
+  SCOPED_UMA_HISTOGRAM_TIMER("Profile.CreateProfileHelperTime");
+
   return Profile::CreateProfile(path, NULL, Profile::CREATE_MODE_SYNCHRONOUS);
 }
 
@@ -1142,6 +1136,19 @@ bool ProfileManager::AddProfile(Profile* profile) {
   return true;
 }
 
+Profile* ProfileManager::CreateAndInitializeProfile(
+    const base::FilePath& profile_dir) {
+  TRACE_EVENT0("browser", "ProfileManager::CreateAndInitializeProfile");
+  SCOPED_UMA_HISTOGRAM_LONG_TIMER("Profile.CreateAndInitializeProfile");
+  Profile* profile = CreateProfileHelper(profile_dir);
+  DCHECK(profile);
+  if (profile) {
+    bool result = AddProfile(profile);
+    DCHECK(result);
+  }
+  return profile;
+}
+
 void ProfileManager::FinishDeletingProfile(const base::FilePath& profile_dir) {
   ProfileInfoCache& cache = GetProfileInfoCache();
   // TODO(sail): Due to bug 88586 we don't delete the profile instance. Once we

chrome/browser/profiles/profile_manager.h

@@ -256,6 +256,10 @@ class ProfileManager : public base::NonThreadSafe,
   // Returns true if the profile was added, false otherwise.
   bool AddProfile(Profile* profile);
 
+  // Synchronously creates and returns a profile. This handles both the full
+  // creation and adds it to the set managed by this ProfileManager.
+  Profile* CreateAndInitializeProfile(const base::FilePath& profile_dir);
+
   // Schedules the profile at the given path to be deleted on shutdown.
   void FinishDeletingProfile(const base::FilePath& profile_dir);
 

components/keyed_service/content/browser_context_dependency_manager.cc

@@ -21,6 +21,9 @@ const char kDumpBrowserContextDependencyGraphFlag[] =
 void BrowserContextDependencyManager::RegisterProfilePrefsForServices(
     const content::BrowserContext* context,
     user_prefs::PrefRegistrySyncable* pref_registry) {
+  TRACE_EVENT0(
+     "browser",
+     "BrowserContextDependencyManager::RegisterProfilePrefsForServices");
   RegisterPrefsForServices(context, pref_registry);
 }
 

tools/metrics/histograms/histograms.xml

@@ -27403,6 +27403,11 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="PrefService.CreateProfilePrefsTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>The amount of time that elapsed during CreateProfilePrefs.</summary>
+</histogram>
+
 <histogram name="Prerender.AbandonTimeUntilUsed" units="milliseconds">
   <owner>davidben@chromium.org</owner>
   <owner>tburkard@chromium.org</owner>
@@ -28462,6 +28467,19 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   <summary>Size of the cookies database.</summary>
 </histogram>
 
+<histogram name="Profile.CreateAndInitializeProfile" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>Length of time to setup profile.</summary>
+</histogram>
+
+<histogram name="Profile.CreateProfileHelperTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during ProfileManager::CreateProfileHelper.
+    This is called when a profile is created synchronously (usually at startup).
+  </summary>
+</histogram>
+
 <histogram name="Profile.CreateResult" enum="ProfileCreateResult">
   <owner>pam@chromium.org</owner>
   <owner>rlp@chromium.org</owner>
@@ -28551,6 +28569,9 @@ Therefore, the affected-histogram name has to have at least one dot in it.
 </histogram>
 
 <histogram name="Profile.GetProfile" units="milliseconds">
+  <obsolete>
+    Deprecated 02/2015. Profile.CreateAndInitializeProfile is more useful.
+  </obsolete>
   <owner>rkaplow@chromium.org</owner>
   <summary>Length of time to retrieve profile.</summary>
 </histogram>
@@ -28725,6 +28746,13 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="Profile.OnPrefsLoadedTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during ProfileImpl::OnPrefsLoaded.
+  </summary>
+</histogram>
+
 <histogram name="Profile.Opening" enum="ProfileOpen">
   <obsolete>
     Deprecated because it did not present the information clearly.
@@ -33387,6 +33415,13 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   <summary>The number of pinned tabs opened when a profile is loaded.</summary>
 </histogram>
 
+<histogram name="Settings.RegisterProfilePrefsTime" units="milliseconds">
+  <owner>rkaplow@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed during RegisterProfilePrefs.
+  </summary>
+</histogram>
+
 <histogram name="Settings.ShowHomeButton" enum="BooleanEnabled">
   <owner>mpearson@chromium.org</owner>
   <summary>