Fix some limitations of slow startup metrics collection

* Create histograms after first page load rather than when the browser message loop starts up, since some of the stats we're interested in are only generated later in startup.
* Create a fast path to reduce overhead of ScopedSlowStartupUMA after stats have been collected.
* Make ScopedSlowStartupUMA idempotent in terms of only recording the first sample for a given histogram - this is so subsystems which are run multiple times during page load only record the initial instance.
    
BUG=160927


Review URL: https://chromiumcodereview.appspot.com/11896070

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

3 files changed, 84 insertions, 22 deletions

diff --git a/chrome/browser/chrome_browser_main.cc b/chrome/browser/chrome_browser_main.cc
index af8f4bc..06dd8f1 100644
--- a/chrome/browser/chrome_browser_main.cc
+++ b/chrome/browser/chrome_browser_main.cc
@@ -106,6 +106,10 @@
 #include "chrome/common/startup_metric_utils.h"
 #include "chrome/installer/util/google_update_settings.h"
 #include "content/public/browser/browser_thread.h"
+#include "content/public/browser/notification_observer.h"
+#include "content/public/browser/notification_registrar.h"
+#include "content/public/browser/notification_service.h"
+#include "content/public/browser/notification_types.h"
 #include "content/public/common/content_client.h"
 #include "content/public/common/content_switches.h"
 #include "content/public/common/main_function_params.h"
@@ -458,6 +462,31 @@ void LaunchDevToolsHandlerIfNeeded(Profile* profile,
   }
 }
 
+// Heap allocated class that listens for first page load, kicks off stat
+// recording and then deletes itself.
+class LoadCompleteListener : public content::NotificationObserver {
+ public:
+   LoadCompleteListener() {
+     registrar_.Add(this,
+                    content::NOTIFICATION_LOAD_COMPLETED_MAIN_FRAME,
+                    content::NotificationService::AllSources());
+   }
+   virtual ~LoadCompleteListener() {}
+
+   // content::NotificationObserver implementation.
+   virtual void Observe(int type,
+                        const content::NotificationSource& source,
+                        const content::NotificationDetails& details) {
+     DCHECK(type == content::NOTIFICATION_LOAD_COMPLETED_MAIN_FRAME);
+     startup_metric_utils::OnInitialPageLoadComplete();
+     delete this;
+   }
+
+ private:
+  content::NotificationRegistrar registrar_;
+  DISALLOW_COPY_AND_ASSIGN(LoadCompleteListener);
+};
+
 }  // namespace
 
 namespace chrome_browser {
@@ -1627,6 +1656,9 @@ void RecordBrowserStartupTime() {
 
   // Record collected startup metrics.
   startup_metric_utils::OnBrowserStartupComplete();
+
+  // Deletes self.
+  new LoadCompleteListener();
 }
 
 // This code is specific to the Windows-only PreReadExperiment field-trial.
diff --git a/chrome/common/startup_metric_utils.cc b/chrome/common/startup_metric_utils.cc
index 75aa6fe..8f3bdac 100644
--- a/chrome/common/startup_metric_utils.cc
+++ b/chrome/common/startup_metric_utils.cc
@@ -38,6 +38,9 @@ base::Lock* GetSubsystemStartupTimeHashLock() {
 }
 
 bool g_main_entry_time_was_recorded = false;
+bool g_startup_stats_collection_finished = false;
+bool g_was_slow_startup = false;
+
 }  // namespace
 
 namespace startup_metric_utils {
@@ -67,12 +70,10 @@ void OnBrowserStartupComplete() {
   // autostarted and the machine is under io pressure.
   const int64 kSevenMinutesInMilliseconds =
       base::TimeDelta::FromMinutes(7).InMilliseconds();
-  if (base::SysInfo::Uptime() < kSevenMinutesInMilliseconds)
+  if (base::SysInfo::Uptime() < kSevenMinutesInMilliseconds) {
+    g_startup_stats_collection_finished = true;
     return;
-
-  const base::TimeDelta kStartupTimeMin(base::TimeDelta::FromMilliseconds(1));
-  const base::TimeDelta kStartupTimeMax(base::TimeDelta::FromMinutes(5));
-  static const size_t kStartupTimeBuckets(100);
+  }
 
   // The Startup.BrowserMessageLoopStartTime histogram recorded in
   // chrome_browser_main.cc exhibits instability in the field which limits its
@@ -90,8 +91,25 @@ void OnBrowserStartupComplete() {
 
   // Record histograms for the subsystem times for startups > 10 seconds.
   const base::TimeDelta kTenSeconds = base::TimeDelta::FromSeconds(10);
-  if (startup_time_from_main_entry < kTenSeconds)
+  if (startup_time_from_main_entry < kTenSeconds) {
+    g_startup_stats_collection_finished = true;
+    return;
+  }
+
+  // If we got here this was what we consider to be a slow startup which we
+  // want to record stats for.
+  g_was_slow_startup = true;
+}
+
+void OnInitialPageLoadComplete() {
+  if (!g_was_slow_startup)
     return;
+  DCHECK(!g_startup_stats_collection_finished);
+
+  const base::TimeDelta kStartupTimeMin(
+      base::TimeDelta::FromMilliseconds(1));
+  const base::TimeDelta kStartupTimeMax(base::TimeDelta::FromMinutes(5));
+  static const size_t kStartupTimeBuckets = 100;
 
   // Set UMA flag for histograms outside chrome/ that can't use the
   // ScopedSlowStartupUMA class.
@@ -102,27 +120,35 @@ void OnBrowserStartupComplete() {
 
   // Iterate over the stats recorded by ScopedSlowStartupUMA and create
   // histograms for them.
-  {
-    base::AutoLock locker(*GetSubsystemStartupTimeHashLock());
-    SubsystemStartupTimeHash* time_hash = GetSubsystemStartupTimeHash();
-    for (SubsystemStartupTimeHash::iterator i = time_hash->begin();
-        i != time_hash->end();
-        ++i) {
-      const std::string histogram_name = i->first;
-      base::HistogramBase* counter = base::Histogram::FactoryTimeGet(
-          histogram_name,
-          kStartupTimeMin,
-          kStartupTimeMax,
-          kStartupTimeBuckets,
-          base::HistogramBase::kUmaTargetedHistogramFlag);
-      counter->AddTime(i->second);
-    }
+  base::AutoLock locker(*GetSubsystemStartupTimeHashLock());
+  SubsystemStartupTimeHash* time_hash = GetSubsystemStartupTimeHash();
+  for (SubsystemStartupTimeHash::iterator i = time_hash->begin();
+      i != time_hash->end();
+      ++i) {
+    const std::string histogram_name = i->first;
+    base::HistogramBase* counter = base::Histogram::FactoryTimeGet(
+        histogram_name,
+        kStartupTimeMin,
+        kStartupTimeMax,
+        kStartupTimeBuckets,
+        base::Histogram::kUmaTargetedHistogramFlag);
+    counter->AddTime(i->second);
   }
+
+  g_startup_stats_collection_finished = true;
 }
 
 ScopedSlowStartupUMA::~ScopedSlowStartupUMA() {
+  if (g_startup_stats_collection_finished)
+    return;
+
   base::AutoLock locker(*GetSubsystemStartupTimeHashLock());
-  (*GetSubsystemStartupTimeHash())[histogram_name_] =
+  SubsystemStartupTimeHash* hash = GetSubsystemStartupTimeHash();
+  // Only record the initial sample for a given histogram.
+  if (hash->find(histogram_name_) !=  hash->end())
+    return;
+
+  (*hash)[histogram_name_] =
       base::TimeTicks::Now() - start_time_;
 }
 
diff --git a/chrome/common/startup_metric_utils.h b/chrome/common/startup_metric_utils.h
index e5e3915..52a4187 100644
--- a/chrome/common/startup_metric_utils.h
+++ b/chrome/common/startup_metric_utils.h
@@ -35,6 +35,10 @@ void RecordMainEntryPointTime();
 // startup stats.
 void OnBrowserStartupComplete();
 
+// Called when the initial page load has finished in order to record startup
+// stats.
+void OnInitialPageLoadComplete();
+
 // 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.