Replace the ExtensionHost load UMAs (Extensions.BackgroundPageLoadTime and friends)

Replace the ExtensionHost load UMAs (Extensions.BackgroundPageLoadTime and
friends) to measure the time from the URL starting to load to it loading.
Extensions.BackgroundPageLoadTime2 replaces Extensions.BackgroundPageLoadTime
etc.

Previously it measured from ExtensionHost construction to it loading, which is
wrong because URL loading can be deferred in a queue, or callers just might not
try to load it until later.

Also do a bit of UMA cleanup: delete some of the Extension page load UMA that
isn't used anymore, and add back the Extensions.PopupLoadTime2 load UMA which
was forgotten about at some point.

R=yoz@chromium.org, isherman@chromium.org
BUG=453073
Committed: https://crrev.com/301145111134ce6d2ccdef5a306d40e2217be051
Cr-Commit-Position: refs/heads/master@{#315149}

[not at google - send to devlin, 2015-02-06 00:55:48]

kalman@chromium.org changed reviewers:
+ isherman@chromium.org, yoz@chromium.org

[not at google - send to devlin, 2015-02-06 00:55:49]

wip.

This is the problem I was referring to in crrev.com/874643003. The load UMA is
wrong.

Ilya, what will I need to change to fix these? The TIMES --> MEDIUM_TIMES may
not be needed with the measurement fix, but given the measured time is changing
anyway, I'll probably need new UMA names for these, right?

[Yoyo Zhou, 2015-02-06 01:59:12]

LGTM, I do think we want a new metric name because the old one is wrong. It
looks like the process creation queue (the extra time we were measuring) doesn't
account for that much, but this is more correct.

https://codereview.chromium.org/902963002/diff/20001/extensions/browser/exten...
File extensions/browser/extension_host.cc (right):

https://codereview.chromium.org/902963002/diff/20001/extensions/browser/exten...
extensions/browser/extension_host.cc:314:
UMA_HISTOGRAM_MEDIUM_TIMES("Extensions.EventPageLoadTime",
I think this is the right change, even though on my machine I don't have any
that go over about 5 seconds.

[Yoyo Zhou, 2015-02-06 02:52:25]

On 2015/02/06 01:59:12, Yoyo Zhou wrote:
> LGTM, I do think we want a new metric name because the old one is wrong. It
> looks like the process creation queue (the extra time we were measuring)
doesn't
> account for that much

After collecting some data, I take this back. On my debug build, with a local
metric for time until we call LoadInitialURL, it takes 0.5-2 seconds in most
cases. On my release build it's more like 200ms, still significant.

[Ilya Sherman, 2015-02-06 02:56:13]

https://codereview.chromium.org/902963002/diff/20001/extensions/browser/exten...
File extensions/browser/extension_host.cc (right):

https://codereview.chromium.org/902963002/diff/20001/extensions/browser/exten...
extensions/browser/extension_host.cc:318: since_created_->Elapsed());
If you change what macro is used -- really, if you change the underlying set of
buckets for the histogram -- then you do indeed need to rename the histogram as
well.

[not at google - send to devlin, 2015-02-06 15:49:45]

Ok, I'm going to add a new UMA and mark the old one in the description as not
all that useful. Yoyo, I'm not sure what local benchmarking is telling you, but
the UMA dashboard shows that these are > 10s in the 70th percentile. Perhaps
you're running on a supercomputer of some sort :)

[not at google - send to devlin, 2015-02-06 20:32:23]

New patchsets have been uploaded after l-g-t-m from yoz@chromium.org

[not at google - send to devlin, 2015-02-06 20:37:33]

^ don't look at that, upload is for self review only.

[not at google - send to devlin, 2015-02-06 20:52:37]

Patchset #3 (id:40001) has been deleted

[not at google - send to devlin, 2015-02-06 20:54:40]

Ok, here we go.

I didn't end up changing the UMA_HISTOGRAM_TIMES to UMA_HISTOGRAM_MEDIUM_TIMES
in the hope that this change will bring times back down to a manageable level.
Otherwise, we got problems.

[Yoyo Zhou, 2015-02-06 21:18:57]

On 2015/02/06 20:54:40, kalman wrote:
> Ok, here we go.
> 
> I didn't end up changing the UMA_HISTOGRAM_TIMES to UMA_HISTOGRAM_MEDIUM_TIMES
> in the hope that this change will bring times back down to a manageable level.
> Otherwise, we got problems.

What, I think MEDIUM_TIMES is still better here. Event pages load times look
less skewed by the queuing delay, but 10% of them are still >10s.

[Ilya Sherman, 2015-02-06 21:26:45]

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (left):

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:7965: -<histogram
name="Extensions.BackgroundPageLoadTime" units="milliseconds">
Please mark the old histogram as <obsolete>, rather than deleting it.

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:9014: +<histogram
name="Extensions.PopupLoadTime2" units="milliseconds">
I don't see a PopupLoadTime1.  Does this just have a "2" to be consistent with
the other histograms that you're renaming?  It's probably not viable for all
extensions time metrics to have a "2" in them going forward, so it might not
really make sense to include a "2" here.  Up to you, though.

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:9019: +    already has a background page
running.
Would it be worth splitting this metric into two cases, one for extensions that
were already running, and one for extensions that were not?  Bimodal histograms
tend to be hard to work with.

[not at google - send to devlin, 2015-02-06 22:51:07]

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (left):

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:7965: -<histogram
name="Extensions.BackgroundPageLoadTime" units="milliseconds">
On 2015/02/06 21:26:44, Ilya Sherman wrote:
> Please mark the old histogram as <obsolete>, rather than deleting it.

Done.

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:9014: +<histogram
name="Extensions.PopupLoadTime2" units="milliseconds">
On 2015/02/06 21:26:44, Ilya Sherman wrote:
> I don't see a PopupLoadTime1.  Does this just have a "2" to be consistent with
> the other histograms that you're renaming?  It's probably not viable for all
> extensions time metrics to have a "2" in them going forward, so it might not
> really make sense to include a "2" here.  Up to you, though.

Yes that's mostly why I did the "2" thing, to be consistent. However - if there
*had* been an Extensions.PopupLoadTime - which there was supposed to be, and we
may already have data uploaded about it (?) - I'd have needed to change it.

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:9019: +    already has a background page
running.
On 2015/02/06 21:26:44, Ilya Sherman wrote:
> Would it be worth splitting this metric into two cases, one for extensions
that
> were already running, and one for extensions that were not?  Bimodal
histograms
> tend to be hard to work with.

I did have a go at that actually but it wasn't clear that it'd be useful.

Ultimately it's time to render that we care about, how many resources are
consumed in opening a popup. The process startup thing is potentially a
side-effect of needing that which is hard to reason about. One useful bit of
data it'd give would be to compare cost of starting up a process vs not I
suppose, and the difference in whether there's a background page or not.
However, given these aren't actually real processes anyway - eh. Pretty subtle.

One way to split would be on whether there is any background page. That's
straightforward. It's not a metric I care about particularly, the only purpose
it would serve is some sort of normalization, potentially.

The other way would be whether the load caused a process to start vs the view
being attached to an existing process. What I'm unsure about here is races, what
the lifetime of a RenderProcessHost is vs a RenderViewHost. E.g. does Chrome
claim that it's made a RPH even though it hasn't quite finish, and happily
attaches a RVH to it anyway?

Alright - I think I'll leave it the way it is. If the data turns out to be
bimodal then I can make this change and call it something different (like
PopupLoadTimeWarm vs PopupLoadTimeCold).

[not at google - send to devlin, 2015-02-06 22:51:15]

Also changed to MEDIUM.

[Ilya Sherman, 2015-02-06 23:19:49]

Metrics LGTM, thanks.

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:9014: +<histogram
name="Extensions.PopupLoadTime2" units="milliseconds">
On 2015/02/06 22:51:07, kalman wrote:
> On 2015/02/06 21:26:44, Ilya Sherman wrote:
> > I don't see a PopupLoadTime1.  Does this just have a "2" to be consistent
with
> > the other histograms that you're renaming?  It's probably not viable for all
> > extensions time metrics to have a "2" in them going forward, so it might not
> > really make sense to include a "2" here.  Up to you, though.
> 
> Yes that's mostly why I did the "2" thing, to be consistent. However - if
there
> *had* been an Extensions.PopupLoadTime - which there was supposed to be, and
we
> may already have data uploaded about it (?) - I'd have needed to change it.

Hmm, if you think that there might already be data being uploaded for a metric
named "Extensions.PopupLoadTime", then please add that metric to histograms.xml
and mark it as <obsolete>.  If you're not sure, it doesn't hurt to add it, and
it's useful to be able to look at real metric names rather than just numeric
hashes when viewing the data server-side, including for pipeline debugging :)

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:9019: +    already has a background page
running.
On 2015/02/06 22:51:07, kalman wrote:
> On 2015/02/06 21:26:44, Ilya Sherman wrote:
> > Would it be worth splitting this metric into two cases, one for extensions
> that
> > were already running, and one for extensions that were not?  Bimodal
> histograms
> > tend to be hard to work with.
> 
> I did have a go at that actually but it wasn't clear that it'd be useful.
> 
> Ultimately it's time to render that we care about, how many resources are
> consumed in opening a popup. The process startup thing is potentially a
> side-effect of needing that which is hard to reason about. One useful bit of
> data it'd give would be to compare cost of starting up a process vs not I
> suppose, and the difference in whether there's a background page or not.
> However, given these aren't actually real processes anyway - eh. Pretty
subtle.
> 
> One way to split would be on whether there is any background page. That's
> straightforward. It's not a metric I care about particularly, the only purpose
> it would serve is some sort of normalization, potentially.
> 
> The other way would be whether the load caused a process to start vs the view
> being attached to an existing process. What I'm unsure about here is races,
what
> the lifetime of a RenderProcessHost is vs a RenderViewHost. E.g. does Chrome
> claim that it's made a RPH even though it hasn't quite finish, and happily
> attaches a RVH to it anyway?
> 
> Alright - I think I'll leave it the way it is. If the data turns out to be
> bimodal then I can make this change and call it something different (like
> PopupLoadTimeWarm vs PopupLoadTimeCold).

Fair enough.

[not at google - send to devlin, 2015-02-06 23:30:46]

New patchsets have been uploaded after l-g-t-m from isherman@chromium.org

[not at google - send to devlin, 2015-02-06 23:32:13]

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/902963002/diff/60001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:9014: +<histogram
name="Extensions.PopupLoadTime2" units="milliseconds">
On 2015/02/06 23:19:49, Ilya Sherman wrote:
> On 2015/02/06 22:51:07, kalman wrote:
> > On 2015/02/06 21:26:44, Ilya Sherman wrote:
> > > I don't see a PopupLoadTime1.  Does this just have a "2" to be consistent
> with
> > > the other histograms that you're renaming?  It's probably not viable for
all
> > > extensions time metrics to have a "2" in them going forward, so it might
not
> > > really make sense to include a "2" here.  Up to you, though.
> > 
> > Yes that's mostly why I did the "2" thing, to be consistent. However - if
> there
> > *had* been an Extensions.PopupLoadTime - which there was supposed to be, and
> we
> > may already have data uploaded about it (?) - I'd have needed to change it.
> 
> Hmm, if you think that there might already be data being uploaded for a metric
> named "Extensions.PopupLoadTime", then please add that metric to
histograms.xml
> and mark it as <obsolete>.  If you're not sure, it doesn't hurt to add it, and
> it's useful to be able to look at real metric names rather than just numeric
> hashes when viewing the data server-side, including for pipeline debugging :)

Done.

[not at google - send to devlin, 2015-02-06 23:53:22]

The CQ bit was checked by kalman@chromium.org

[commit-bot: I haz the power, 2015-02-06 23:54:36]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/902963002/100001

[commit-bot: I haz the power, 2015-02-07 00:43:55]

Committed patchset #5 (id:100001)

[commit-bot: I haz the power, 2015-02-07 00:44:54]

Patchset 5 (id:??) landed as
https://crrev.com/301145111134ce6d2ccdef5a306d40e2217be051
Cr-Commit-Position: refs/heads/master@{#315149}