Record metrics for slow startups

chrome/common/startup_metric_utils.cc

Index: chrome/common/startup_metric_utils.cc
diff --git a/chrome/common/startup_metric_utils.cc b/chrome/common/startup_metric_utils.cc
index 2292fffe77da3a7991b9e62ddff2aac2bfd4150b..bb2fbd2f0310f2ce18179f465ef8a700ec42d639 100644
--- a/chrome/common/startup_metric_utils.cc
+++ b/chrome/common/startup_metric_utils.cc
@@ -4,21 +4,38 @@
 
 #include "chrome/common/startup_metric_utils.h"
 
+#include "base/hash_tables.h"
 #include "base/logging.h"
+#include "base/metrics/histogram.h"
+#include "base/synchronization/lock.h"
+#include "base/sys_info.h"
 #include "base/time.h"
 
 namespace {
 
 // Mark as volatile to defensively make sure usage is thread-safe.
 // Note that at the time of this writing, access is only on the UI thread.
-static volatile bool g_non_browser_ui_displayed = false;
+volatile bool g_non_browser_ui_displayed = false;
 
 const base::Time* MainEntryPointTimeInternal() {
   static base::Time main_start_time = base::Time::Now();
   return &main_start_time;
 }
 
-static bool g_main_entry_time_was_recorded = false;
+typedef base::hash_map<std::string,base::TimeDelta> SubstemStartupTimeHash;

[tonyg, 2013/01/07 20:44:49]

s/Substem/Subsystem/ ?

[jeremy, 2013/01/10 15:08:39]

Done.

+
+SubstemStartupTimeHash* GetSubstemStartupTimeHash() {
+  static SubstemStartupTimeHash* slow_startup_time_hash =
+                                    new SubstemStartupTimeHash;
+  return slow_startup_time_hash;
+}
+
+base::Lock* GetSubstemStartupTimeHashLock() {
+  base::Lock* slow_startup_time_hash_lock = new base::Lock;

[Scott Hess - ex-Googler, 2013/01/07 21:47:25]

Is this supposed to protect the hash?  Having it be newly allocated each time
doesn't seem right.

Would it make as much/more sense to just have ~ScopedSlowStartupUMA() post the
results to the main thread?  Then the thread safety is a non-issue.  Hmm, but I
suppose it would most likely get posted after the finishing-starting-up thingie
was posted, due to being posted from the destructor.

[jeremy, 2013/01/10 15:08:39]

Doh!

+  return slow_startup_time_hash_lock;
+}
+
+bool g_main_entry_time_was_recorded = false;
 }  // namespace
 
 namespace startup_metric_utils {
@@ -37,9 +54,65 @@ void RecordMainEntryPointTime() {
   MainEntryPointTimeInternal();
 }
 
+// Return the time recorded by RecordMainEntryPointTime().
 const base::Time MainEntryStartTime() {
   DCHECK(g_main_entry_time_was_recorded);
   return *MainEntryPointTimeInternal();
 }
 
+void OnBrowserStartupComplete() {
+  // Bail if uptime < 7 minutes, to filter out cases where Chrome may have been
+  // autostarted and the machine is under io pressure.
+  const int64 kSevenMinutesInMilliseconds =
+      base::TimeDelta::FromMinutes(7).InMilliseconds();
+  if (base::SysInfo::Uptime() < kSevenMinutesInMilliseconds)
+    return;
+
+  // The Startup.BrowserMessageLoopStartTime histogram recorded in
+  // chrome_browser_main.cc exhibits instability in the field which limits its
+  // usefulness in all scenarios except when we have a very large sample size.
+  // Attempt to mitigate this with a new metric:
+  // * Measure time from main entry rather than the OS' notion of process start
+  //   time.
+  // * Only measure launches that occur 7 minutes after boot to try to avoid
+  //   cases where Chrome is auto-started and IO is heavily loaded.

[Scott Hess - ex-Googler, 2013/01/07 21:47:25]

Redundant with previous comment and test.

[Scott Hess - ex-Googler, 2013/01/07 21:47:25]

Redundant with previous comment/test.

+  const base::TimeDelta kStartupTimeMin(base::TimeDelta::FromMilliseconds(1));
+  const base::TimeDelta kStartupTimeMax(base::TimeDelta::FromMinutes(5));
+  static const size_t kStartupTimeBuckets(100);
+
+  base::TimeDelta startup_time_from_main_entry =
+                      base::Time::Now() - MainEntryStartTime();

[tonyg, 2013/01/07 20:44:49]

nit: indent only 4 spaces

[jeremy, 2013/01/10 15:08:39]

Done.

+  HISTOGRAM_CUSTOM_TIMES(

[Scott Hess - ex-Googler, 2013/01/07 21:47:25]

UMA_?

[jeremy, 2013/01/10 15:08:39]

Done.

+      "Startup.BrowserMessageLoopStartTimeFromMainEntry",
+      startup_time_from_main_entry,
+      kStartupTimeMin,
+      kStartupTimeMax,
+      kStartupTimeBuckets);

[Scott Hess - ex-Googler, 2013/01/07 21:47:25]

Is this of material gain versus UMA_HISTOGRAM_LONG_TIMES()?  Histogram buckets
are logarithmic, so with in a 1-hour histogram the 5-minute bucket is around
90%, and having 100 buckets doesn't gain you much information over 50 buckets.

[jeremy, 2013/01/10 15:08:39]

Done.

+
+  // 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)
+    return;
+  {
+    base::AutoLock locker(*GetSubstemStartupTimeHashLock());
+    SubstemStartupTimeHash* time_hash = GetSubstemStartupTimeHash();
+    for (auto i = time_hash->begin(); i != time_hash->end(); ++i) {
+      std::string histogram_name = i->first;

[Scott Hess - ex-Googler, 2013/01/07 21:47:25]

const, and as long as you're making i->first more self-documenting, might as
well pull i->second into a TimeDelta so that it's self-documenting, too.

[jeremy, 2013/01/10 15:08:39]

Done.

I thought of doing that for i->second, but the function call it's in makes it
self-explanatory,  IMHO.

+      base::Histogram* counter = base::Histogram::FactoryTimeGet(
+          histogram_name,
+          kStartupTimeMin,
+          kStartupTimeMax,
+          kStartupTimeBuckets,
+          base::Histogram::kUmaTargetedHistogramFlag);

[Scott Hess - ex-Googler, 2013/01/07 21:47:25]

Hmm, so I guess you can't use the macro for this, so part of my rationale for
using an ill-fitting packaged call doesn't apply.  Note that the 10 second
bucket will be very high, like 70th percentile, so you'll be losing a lot of
resolution if you happen to catch the item at fault.  Do you want the quick
items to be logged at all if i->second was really fast?

[jeremy, 2013/01/10 15:08:39]

Agree, do you have any suggestions for good parameters here? Since I don't know
what data I'm going to see your guess is as good as mine.

[Scott Hess - ex-Googler, 2013/01/10 20:43:13]

Well ... what kinds of information would be useful for acting on?  The bundled
HISTOGRAM_TIMES macros all use 1ms min, and 10s, 3m, and 1h max.  1h seems way
too long, and the difference between 3m and 5m is probably not all that
important (both are bad!).  Likewise, the difference between .1s and 1s probably
isn't too useful.  So like 1s to 10m, maybe, in 50 buckets?

Also, I think if you just matched UMA_HISTOGRAM_LONG_TIMES(), that's hard to
argue against, and would match the other histogram.  The only reason this
discussion is happening is that once you've made a different decision than
handed down by tradition, someone starts asking "Why?"

BTW, the task-profiler data exposed at chrome://profiler/ could maybe inform
some of this.  I don't recall what all is done for purposes of mining that in
aggregate, maybe ask jar.

+      counter->AddTime(i->second);
+    }
+  }
+}
+
+ScopedSlowStartupUMA::~ScopedSlowStartupUMA() {
+  base::AutoLock locker(*GetSubstemStartupTimeHashLock());
+  (*GetSubstemStartupTimeHash())[histogram_name_] =
+      base::TimeTicks::Now() - start_time_;
+}
+
 }  // namespace startup_metric_utils