mac: Add a profiler for startup time.

The profiler records UMA metrics for several key phases in Chrome startup.

BUG=393819

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

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@283974 0039d316-1c4b-4281-b951-d872f2087c98

chrome/browser/app_controller_mac.mm

@@ -30,6 +30,7 @@
 #include "chrome/browser/extensions/extension_service.h"
 #include "chrome/browser/first_run/first_run.h"
 #include "chrome/browser/lifetime/application_lifetime.h"
+#include "chrome/browser/mac/mac_startup_profiler.h"
 #include "chrome/browser/profiles/profile_info_cache_observer.h"
 #include "chrome/browser/profiles/profile_manager.h"
 #include "chrome/browser/profiles/profiles_state.h"
@@ -281,6 +282,8 @@ class AppControllerProfileObserver : public ProfileInfoCacheObserver {
 // the profile is loaded or any preferences have been registered). Defer any
 // user-data initialization until -applicationDidFinishLaunching:.
 - (void)awakeFromNib {
+  MacStartupProfiler::GetInstance()->Profile(
+      MacStartupProfiler::AWAKE_FROM_NIB);
   // We need to register the handlers early to catch events fired on launch.
   NSAppleEventManager* em = [NSAppleEventManager sharedAppleEventManager];
   [em setEventHandler:self
@@ -360,7 +363,8 @@ class AppControllerProfileObserver : public ProfileInfoCacheObserver {
 // (NSApplicationDelegate protocol) This is the Apple-approved place to override
 // the default handlers.
 - (void)applicationWillFinishLaunching:(NSNotification*)notification {
-  // Nothing here right now.
+  MacStartupProfiler::GetInstance()->Profile(
+      MacStartupProfiler::WILL_FINISH_LAUNCHING);
 }
 
 - (BOOL)tryToTerminateApplication:(NSApplication*)app {
@@ -734,6 +738,10 @@ class AppControllerProfileObserver : public ProfileInfoCacheObserver {
 // This is called after profiles have been loaded and preferences registered.
 // It is safe to access the default profile here.
 - (void)applicationDidFinishLaunching:(NSNotification*)notify {
+  MacStartupProfiler::GetInstance()->Profile(
+      MacStartupProfiler::DID_FINISH_LAUNCHING);
+  MacStartupProfiler::GetInstance()->RecordMetrics();
+
   // Notify BrowserList to keep the application running so it doesn't go away
   // when all the browser windows get closed.
   chrome::IncrementKeepAliveCount();

chrome/browser/chrome_browser_main_mac.h

@@ -16,6 +16,7 @@ class ChromeBrowserMainPartsMac : public ChromeBrowserMainPartsPosix {
   // BrowserParts overrides.
   virtual void PreEarlyInitialization() OVERRIDE;
   virtual void PreMainMessageLoopStart() OVERRIDE;
+  virtual void PostMainMessageLoopStart() OVERRIDE;
   virtual void PreProfileInit() OVERRIDE;
   virtual void PostProfileInit() OVERRIDE;
 

chrome/browser/chrome_browser_main_mac.mm

@@ -20,6 +20,7 @@
 #import "chrome/browser/chrome_browser_application_mac.h"
 #include "chrome/browser/mac/install_from_dmg.h"
 #import "chrome/browser/mac/keystone_glue.h"
+#include "chrome/browser/mac/mac_startup_profiler.h"
 #include "chrome/browser/ui/app_list/app_list_service.h"
 #include "chrome/common/chrome_paths.h"
 #include "chrome/common/chrome_switches.h"
@@ -175,6 +176,8 @@ void ChromeBrowserMainPartsMac::PreEarlyInitialization() {
 }
 
 void ChromeBrowserMainPartsMac::PreMainMessageLoopStart() {
+  MacStartupProfiler::GetInstance()->Profile(
+      MacStartupProfiler::PRE_MAIN_MESSAGE_LOOP_START);
   ChromeBrowserMainPartsPosix::PreMainMessageLoopStart();
 
   // Tell Cocoa to finish its initialization, which we want to do manually
@@ -257,7 +260,14 @@ void ChromeBrowserMainPartsMac::PreMainMessageLoopStart() {
   }];
 }
 
+void ChromeBrowserMainPartsMac::PostMainMessageLoopStart() {
+  MacStartupProfiler::GetInstance()->Profile(
+      MacStartupProfiler::POST_MAIN_MESSAGE_LOOP_START);
+}
+
 void ChromeBrowserMainPartsMac::PreProfileInit() {
+  MacStartupProfiler::GetInstance()->Profile(
+      MacStartupProfiler::PRE_PROFILE_INIT);
   ChromeBrowserMainPartsPosix::PreProfileInit();
   // This is called here so that the app shim socket is only created after
   // taking the singleton lock.
@@ -266,6 +276,8 @@ void ChromeBrowserMainPartsMac::PreProfileInit() {
 }
 
 void ChromeBrowserMainPartsMac::PostProfileInit() {
+  MacStartupProfiler::GetInstance()->Profile(
+      MacStartupProfiler::POST_PROFILE_INIT);
   ChromeBrowserMainPartsPosix::PostProfileInit();
   g_browser_process->metrics_service()->RecordBreakpadRegistration(
       breakpad::IsCrashReporterEnabled());

chrome/browser/mac/mac_startup_profiler.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/mac/mac_startup_profiler.h"
+
+#include "base/logging.h"
+#include "base/metrics/histogram.h"
+#include "components/startup_metric_utils/startup_metric_utils.h"
+
+// static
+MacStartupProfiler* MacStartupProfiler::GetInstance() {
+  return Singleton<MacStartupProfiler>::get();
+}
+
+MacStartupProfiler::MacStartupProfiler() : recorded_metrics_(false) {
+}
+
+MacStartupProfiler::~MacStartupProfiler() {
+}
+
+void MacStartupProfiler::Profile(Location location) {
+  profiled_times_[location] = base::Time::Now();
+}
+
+void MacStartupProfiler::RecordMetrics() {
+  const base::Time* main_entry_time =
+      startup_metric_utils::MainEntryPointTime();
+  DCHECK(main_entry_time);
+  DCHECK(!recorded_metrics_);
+
+  recorded_metrics_ = true;
+
+  for (std::map<Location, base::Time>::const_iterator it =
+           profiled_times_.begin();
+       it != profiled_times_.end();
+       ++it) {
+    const base::Time& location_time = it->second;
+    base::TimeDelta delta = location_time - *main_entry_time;
+    RecordHistogram(it->first, delta);
+  }
+}
+
+const std::string MacStartupProfiler::HistogramName(Location location) {
+  std::string prefix("Startup.OSX.");
+  switch (location) {
+    case PRE_MAIN_MESSAGE_LOOP_START:
+      return prefix + "PreMainMessageLoopStart";
+    case AWAKE_FROM_NIB:
+      return prefix + "AwakeFromNib";
+    case POST_MAIN_MESSAGE_LOOP_START:
+      return prefix + "PostMainMessageLoopStart";
+    case PRE_PROFILE_INIT:
+      return prefix + "PreProfileInit";
+    case POST_PROFILE_INIT:
+      return prefix + "PostProfileInit";
+    case WILL_FINISH_LAUNCHING:
+      return prefix + "WillFinishLaunching";
+    case DID_FINISH_LAUNCHING:
+      return prefix + "DockIconWillFinishBouncing";
+  }
+}
+
+void MacStartupProfiler::RecordHistogram(Location location,
+                                         const base::TimeDelta& delta) {
+  const std::string name(HistogramName(location));
+  base::TimeDelta min = base::TimeDelta::FromMilliseconds(10);
+  base::TimeDelta max = base::TimeDelta::FromMinutes(1);
+  int bucket_count = 100;
+
+  // No need to cache the histogram pointers, since each invocation of this
+  // method will be the first and only usage of a histogram with that given
+  // name.
+  base::HistogramBase* histogram = base::Histogram::FactoryTimeGet(
+      name,
+      min,
+      max,
+      bucket_count,
+      base::HistogramBase::kUmaTargetedHistogramFlag);
+  histogram->AddTime(delta);
+}

chrome/browser/mac/mac_startup_profiler.h

+// 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.
+
+#ifndef CHROME_BROWSER_MAC_MAC_STARTUP_PROFILER_H_
+#define CHROME_BROWSER_MAC_MAC_STARTUP_PROFILER_H_
+
+#include <map>
+
+#include "base/memory/singleton.h"
+#include "base/time/time.h"
+
+// A lightweight profiler of startup performance. Records UMA metrics for the
+// time delta between Chrome's launch and major initialization phases.
+class MacStartupProfiler {
+ public:
+  // Returns pointer to the singleton instance for the current process.
+  static MacStartupProfiler* GetInstance();
+
+  MacStartupProfiler();
+  ~MacStartupProfiler();
+
+  // These locations correspond to major phases of Chrome startup.
+  // Profiling of these locations should occur at the beginning of the method
+  // indicated by the enum name.
+  // The ordering of the enum matches the order in which the initialization
+  // phases are reached.
+  enum Location {
+    PRE_MAIN_MESSAGE_LOOP_START,
+    AWAKE_FROM_NIB,
+    POST_MAIN_MESSAGE_LOOP_START,
+    PRE_PROFILE_INIT,
+    POST_PROFILE_INIT,
+    WILL_FINISH_LAUNCHING,
+    DID_FINISH_LAUNCHING,
+  };
+
+  // Record timestamp for the given location event.
+  void Profile(Location location);
+
+  // Call once to record all UMA metrics for all profiled locations.
+  void RecordMetrics();
+
+ private:
+  friend struct DefaultSingletonTraits<MacStartupProfiler>;
+
+  // Returns the name of the histogram for the given location.
+  const std::string HistogramName(Location location);
+
+  // Records UMA metrics for a specific location.
+  void RecordHistogram(Location location, const base::TimeDelta& delta);
+
+  // Keeps track of the time at which each initialization phase was reached.
+  std::map<Location, base::Time> profiled_times_;
+
+  // Whether UMA metrics have been recorded. Only record UMA metrics once.
+  bool recorded_metrics_;
+
+  DISALLOW_COPY_AND_ASSIGN(MacStartupProfiler);
+};
+
+#endif  // CHROME_BROWSER_MAC_MAC_STARTUP_PROFILER_H_

chrome/chrome_browser.gypi

@@ -668,6 +668,8 @@
       'browser/mac/keystone_glue.mm',
       'browser/mac/keystone_registration.h',
       'browser/mac/keystone_registration.mm',
+      'browser/mac/mac_startup_profiler.cc',
+      'browser/mac/mac_startup_profiler.h',
       'browser/mac/master_prefs.h',
       'browser/mac/master_prefs.mm',
       'browser/mac/obsolete_system.cc',

components/startup_metric_utils/startup_metric_utils.cc

@@ -229,6 +229,12 @@ void OnInitialPageLoadComplete() {
   g_startup_stats_collection_finished = true;
 }
 
+const base::Time* MainEntryPointTime() {
+  if (!g_main_entry_time_was_recorded)
+    return NULL;
+  return MainEntryPointTimeInternal();
+}
+
 ScopedSlowStartupUMA::~ScopedSlowStartupUMA() {
   if (g_startup_stats_collection_finished)
     return;

components/startup_metric_utils/startup_metric_utils.h

@@ -52,6 +52,11 @@ void OnBrowserStartupComplete(bool is_first_run);
 // stats.
 void OnInitialPageLoadComplete();
 
+// Returns the time of main entry recorded from RecordMainEntryPointTime.
+// Returns NULL if that method has not yet been called.
+// This method is expected to be called from the UI thread.
+const base::Time* MainEntryPointTime();
+
 // Scoper that records the time period before it's destructed in a histogram
 // with the given name. The histogram is only recorded for slow chrome startups.
 // Useful for trying to figure out what parts of Chrome cause slow startup.

tools/metrics/histograms/histograms.xml

@@ -30651,6 +30651,63 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   <summary>The calling application (if any).</summary>
 </histogram>
 
+<histogram name="Startup.OSX.AwakeFromNib" units="milliseconds">
+  <owner>erikchen@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed between main entry and the invocation of
+    -[AppControllerMac awakeFromNib].
+  </summary>
+</histogram>
+
+<histogram name="Startup.OSX.DockIconWillFinishBouncing" units="milliseconds">
+  <owner>erikchen@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed between main entry and the invocation of
+    -[AppControllerMac didFinishLaunching:]. At that point, the dock icon will
+    finish its current animation and stop bouncing.
+  </summary>
+</histogram>
+
+<histogram name="Startup.OSX.PostMainMessageLoopStart" units="milliseconds">
+  <owner>erikchen@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed between main entry and the invocation of
+    ChromeBrowserMainPartsMac::PostMainMessageLoopStart.
+  </summary>
+</histogram>
+
+<histogram name="Startup.OSX.PostProfileInit" units="milliseconds">
+  <owner>erikchen@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed between main entry and the invocation of
+    ChromeBrowserMainPartsMac::PostProfileInit.
+  </summary>
+</histogram>
+
+<histogram name="Startup.OSX.PreMainMessageLoopStart" units="milliseconds">
+  <owner>erikchen@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed between main entry and the invocation of
+    ChromeBrowserMainPartsMac::PreMainMessageLoopStart.
+  </summary>
+</histogram>
+
+<histogram name="Startup.OSX.PreProfileInit" units="milliseconds">
+  <owner>erikchen@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed between main entry and the invocation of
+    ChromeBrowserMainPartsMac::PreProfileInit.
+  </summary>
+</histogram>
+
+<histogram name="Startup.OSX.WillFinishLaunching" units="milliseconds">
+  <owner>erikchen@chromium.org</owner>
+  <summary>
+    The amount of time that elapsed between main entry and the invocation of
+    -[AppControllerMac willFinishLaunching:].
+  </summary>
+</histogram>
+
 <histogram name="Startup.ShowAppListColdStart" units="milliseconds">
   <owner>jeremy@chromium.org</owner>
   <summary>