Record metrics for slow startups

Record metrics for slow startups

* Add a mechanism to collect duration of various operations for slow startups (defined as taking >= 10s).
* Move collection of Startup.BrowserMessageLoopStartTimeFromMainEntry metric to startup_metric_utils.cc.
* Change bucketing of Startup.BrowserMessageLoopStartTimeFromMainEntry from 0-5min instead of from 0-1 hour to improve granularity.
* Collect metrics for major operations in Safe Browsing startup.

BUG=160927
TEST=None


Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=176808

[jeremy, 2013-01-06 15:01:49]

tony: General review.
Shess: safe_browsing/ , specifically, am I timing the right things here? Any
other part of safe browsing that would be good to measure for slow startups?

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

lgtm with nits

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
File chrome/common/startup_metric_utils.cc (right):

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:25: typedef
base::hash_map<std::string,base::TimeDelta> SubstemStartupTimeHash;
s/Substem/Subsystem/ ?

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:84: base::Time::Now() -
MainEntryStartTime();
nit: indent only 4 spaces

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

https://codereview.chromium.org/11785014/diff/13/chrome/browser/safe_browsing...
File chrome/browser/safe_browsing/database_manager.cc (right):

https://codereview.chromium.org/11785014/diff/13/chrome/browser/safe_browsing...
chrome/browser/safe_browsing/database_manager.cc:505:
scoped_timer("Startup.SlowStartupSafeBrowsingGetDatabase");
I believe that this will measure the time to load the prefixset into memory. 
Other calls in the Init() below just set variables.

https://codereview.chromium.org/11785014/diff/13/chrome/browser/safe_browsing...
File chrome/browser/safe_browsing/safe_browsing_service.cc (right):

https://codereview.chromium.org/11785014/diff/13/chrome/browser/safe_browsing...
chrome/browser/safe_browsing/safe_browsing_service.cc:169:
scoped_timer("Startup.SlowStartupSafeBrowsingServiceInitialize");
I'm less certain about what this will measure.  I wouldn't be surprised if the
values turn out to be very small.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
File chrome/common/startup_metric_utils.cc (right):

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:34: base::Lock*
slow_startup_time_hash_lock = new base::Lock;
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.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:78: //   cases where Chrome is
auto-started and IO is heavily loaded.
Redundant with previous comment and test.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:78: //   cases where Chrome is
auto-started and IO is heavily loaded.
Redundant with previous comment/test.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:85: HISTOGRAM_CUSTOM_TIMES(
UMA_?

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:90: kStartupTimeBuckets);
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.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:100: std::string histogram_name =
i->first;
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.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:106:
base::Histogram::kUmaTargetedHistogramFlag);
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?

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
File chrome/common/startup_metric_utils.h (right):

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.h:38: // Scoper that records the time period
before it's distructed in a histogram
s/distructed/destructed/

I often wonder about having an UMA-logging scoper to sanitize the many "I'll
make up a timer" cases, I'll be interested to hear how this goes.

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

https://codereview.chromium.org/11785014/diff/13/chrome/browser/safe_browsing...
File chrome/browser/safe_browsing/safe_browsing_service.cc (right):

https://codereview.chromium.org/11785014/diff/13/chrome/browser/safe_browsing...
chrome/browser/safe_browsing/safe_browsing_service.cc:169:
scoped_timer("Startup.SlowStartupSafeBrowsingServiceInitialize");
Neither would I, but I think if nothing else it'll be useful to contrast against
the other metrics.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
File chrome/common/startup_metric_utils.cc (right):

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:25: typedef
base::hash_map<std::string,base::TimeDelta> SubstemStartupTimeHash;
On 2013/01/07 20:44:49, tonyg wrote:
> s/Substem/Subsystem/ ?

Done.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:34: base::Lock*
slow_startup_time_hash_lock = new base::Lock;
Doh!

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:84: base::Time::Now() -
MainEntryStartTime();
On 2013/01/07 20:44:49, tonyg wrote:
> nit: indent only 4 spaces

Done.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:85: HISTOGRAM_CUSTOM_TIMES(
On 2013/01/07 21:47:25, shess wrote:
> UMA_?

Done.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:90: kStartupTimeBuckets);
On 2013/01/07 21:47:25, shess wrote:
> 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.

Done.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:100: std::string histogram_name =
i->first;
On 2013/01/07 21:47:25, shess wrote:
> 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.

Done.

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

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:106:
base::Histogram::kUmaTargetedHistogramFlag);
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.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
File chrome/common/startup_metric_utils.h (right):

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.h:38: // Scoper that records the time period
before it's distructed in a histogram
On 2013/01/07 21:47:25, shess wrote:
> s/distructed/destructed/
> 
> I often wonder about having an UMA-logging scoper to sanitize the many "I'll
> make up a timer" cases, I'll be interested to hear how this goes.

Done.

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

lgtm.  I suspect the histogram parameters in the end just won't matter all
_that_ much.

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
File chrome/common/startup_metric_utils.cc (right):

https://codereview.chromium.org/11785014/diff/13/chrome/common/startup_metric...
chrome/common/startup_metric_utils.cc:106:
base::Histogram::kUmaTargetedHistogramFlag);
On 2013/01/10 15:08:39, jeremy wrote:
> 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.

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.

[commit-bot: I haz the power, 2013-01-14 18:17:26]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/jeremy@chromium.org/11785014/14001

[commit-bot: I haz the power, 2013-01-14 18:17:37]

Presubmit check for 11785014-14001 failed and returned exit status 1.


Running presubmit commit checks ...

** Presubmit ERRORS **
Missing LGTM from an OWNER for files in these directories:
    chrome
    chrome/browser/bookmarks

Presubmit checks took 1.7s to calculate.

Was the presubmit check useful? Please send feedback & hate mail to
maruel@chromium.org!

[jeremy, 2013-01-14 18:25:12]

sky: owner review plz, thanks!

[sky, 2013-01-14 21:54:11]

LGTM

https://codereview.chromium.org/11785014/diff/14001/chrome/common/startup_met...
File chrome/common/startup_metric_utils.cc (right):

https://codereview.chromium.org/11785014/diff/14001/chrome/common/startup_met...
chrome/common/startup_metric_utils.cc:64: // Bail if uptime < 7 minutes, to
filter out cases where Chrome may have been
This case seems pretty common to me, eg reboot and then start chrome right away.
What else is someone going to do with their machine other than use chrome:)

https://codereview.chromium.org/11785014/diff/14001/chrome/common/startup_met...
File chrome/common/startup_metric_utils.h (right):

https://codereview.chromium.org/11785014/diff/14001/chrome/common/startup_met...
chrome/common/startup_metric_utils.h:44: : start_time_(base::TimeTicks::Now()),
nit: indentation is off here.

https://codereview.chromium.org/11785014/diff/14001/chrome/common/startup_met...
chrome/common/startup_metric_utils.h:50: base::TimeTicks start_time_;
nit: const on both of these.

[commit-bot: I haz the power, 2013-01-15 01:18:20]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/jeremy@chromium.org/11785014/23001

[commit-bot: I haz the power, 2013-01-15 02:11:55]

Failed to trigger a try job on android_dbg
HTTP Error 400: Bad Request

[commit-bot: I haz the power, 2013-01-15 02:11:59]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/jeremy@chromium.org/11785014/32001

[commit-bot: I haz the power, 2013-01-15 06:35:59]

Change committed as 176808