mac: Add a profiler for startup time.

chrome/browser/mac/mac_startup_profiler.cc

Index: chrome/browser/mac/mac_startup_profiler.cc
diff --git a/chrome/browser/mac/mac_startup_profiler.cc b/chrome/browser/mac/mac_startup_profiler.cc
new file mode 100644
index 0000000000000000000000000000000000000000..e2143b6a94a737594eb6e6138d1a09a9514712c4
--- /dev/null
+++ b/chrome/browser/mac/mac_startup_profiler.cc
@@ -0,0 +1,79 @@
+// 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"
+
+// static
+MacStartupProfiler* MacStartupProfiler::GetInstance() {
+  return Singleton<MacStartupProfiler>::get();
+}
+
+MacStartupProfiler::MacStartupProfiler() : recorded_metrics_(false) {
+}
+
+MacStartupProfiler::~MacStartupProfiler() {
+}
+
+void MacStartupProfiler::RecordLaunchTime() {
+  launch_time_ = base::Time::Now();

[jeremy, 2014/07/17 11:10:18]

startup_metric_utils also captures the process start time.  Can you expose the
timestamp used there (startup_metric_utils::MainEntryPointTimeInternal() and
access that here).

If nothing else, this means our startup metrics are using the same reference
time so we can compare them easily if need be.

+}
+
+void MacStartupProfiler::Profile(Location location) {
+  DCHECK(!launch_time_.is_null());
+  profiled_times_[location] = base::Time::Now();
+}
+
+void MacStartupProfiler::RecordMetrics() {
+  DCHECK(!launch_time_.is_null());
+  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 - launch_time_;
+    RecordHistogram(it->first, delta);
+  }
+}
+
+const std::string MacStartupProfiler::HistogramName(Location location) {
+  std::string prefix("OSX.Startup.");

[jeremy, 2014/07/17 11:10:18]

Any reason not to call these Startup.OSX so that the various startup UMAs are
clustered together?

+  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 + "DidFinishLaunching";
+  }
+}
+
+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;

[jeremy, 2014/07/16 08:19:24]

The histogram times/bucket count were a big issue when I was looking at startup
time.  There is a long tail on these numbers on end user machines, and most of
the buckets will likely be lower than 10 milliseconds.  I ended up having to
tweak these a few times, what are your thoughts?
To be clear, I have no issues with this - just something I ran into...

[erikchen, 2014/07/16 22:00:33]

I prefer to restrict my histogram ranges to the values that I care about. There
is no effective difference between 1 minute and 30. Something has gone horribly
wrong. 

[jeremy, 2014/07/17 11:10:18]

On an IO bound machine you may see some of these take over a minute, as long as
you only care about this range, that's fine.

+
+  // 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::kNoFlags);

[jeremy, 2014/07/16 08:19:23]

This is just a local histogram and doesn't go to UMA, right?

[erikchen, 2014/07/16 22:00:33]

That is not correct. These metrics are going to UMA.

[Ilya Sherman, 2014/07/16 22:02:40]

Jeremy noticed something important that I didn't: You're not setting the UMA
flag, so these histograms won't be uploaded.

[erikchen, 2014/07/16 22:12:18]

Ah, I see. I've fixed this.

[Ilya Sherman, 2014/07/16 22:14:21]

Thanks, LG.

+  histogram->AddTime(delta);
+}