Add UMA histogram timers for ProcessManager and BackgroundContentsService startup.

Add UMA histogram timers for ProcessManager and BackgroundContentsService startup.

These measure the time taken in response to ExtensionService ready signaling. These are the 2 heaviest observers of ready.

BUG=453073
Committed: https://crrev.com/1c99cbefc7c06e5542c8eb7be394e16d19bed398
Cr-Commit-Position: refs/heads/master@{#315081}

[Yoyo Zhou, 2015-02-05 02:44:14]

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

[Ilya Sherman, 2015-02-05 02:50:27]

https://codereview.chromium.org/874643003/diff/1/chrome/browser/background/ba...
File chrome/browser/background/background_contents_service.cc (right):

https://codereview.chromium.org/874643003/diff/1/chrome/browser/background/ba...
chrome/browser/background/background_contents_service.cc:13: #include
"base/metrics/histogram.h"
nit: Please include histogram_macros instead.

https://codereview.chromium.org/874643003/diff/1/tools/metrics/histograms/his...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/874643003/diff/1/tools/metrics/histograms/his...
tools/metrics/histograms/histograms.xml:1986: +<histogram
name="BackgroundContentsService.LoadOnExtensionsReadyTime">
If this is really measuring something extensions-related, maybe it makes more
sense to group this under the Extensions group/namespace?  The dashboard is
geared toward having fewer groups with more histograms in each, rather than
having lots of small groups.

https://codereview.chromium.org/874643003/diff/1/tools/metrics/histograms/his...
tools/metrics/histograms/histograms.xml:1986: +<histogram
name="BackgroundContentsService.LoadOnExtensionsReadyTime">
nit: Please add a units attribute.

[Yoyo Zhou, 2015-02-05 03:08:02]

https://codereview.chromium.org/874643003/diff/1/chrome/browser/background/ba...
File chrome/browser/background/background_contents_service.cc (right):

https://codereview.chromium.org/874643003/diff/1/chrome/browser/background/ba...
chrome/browser/background/background_contents_service.cc:13: #include
"base/metrics/histogram.h"
On 2015/02/05 02:50:26, Ilya Sherman wrote:
> nit: Please include histogram_macros instead.

Done.

https://codereview.chromium.org/874643003/diff/1/tools/metrics/histograms/his...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/874643003/diff/1/tools/metrics/histograms/his...
tools/metrics/histograms/histograms.xml:1986: +<histogram
name="BackgroundContentsService.LoadOnExtensionsReadyTime">
On 2015/02/05 02:50:26, Ilya Sherman wrote:
> If this is really measuring something extensions-related, maybe it makes more
> sense to group this under the Extensions group/namespace?  The dashboard is
> geared toward having fewer groups with more histograms in each, rather than
> having lots of small groups.

Done.

https://codereview.chromium.org/874643003/diff/1/tools/metrics/histograms/his...
tools/metrics/histograms/histograms.xml:1986: +<histogram
name="BackgroundContentsService.LoadOnExtensionsReadyTime">
On 2015/02/05 02:50:26, Ilya Sherman wrote:
> nit: Please add a units attribute.

Done.

[Ilya Sherman, 2015-02-05 03:08:54]

histograms lgtm, thanks :)

[not at google - send to devlin, 2015-02-05 16:17:35]

lgtm, are these events actually synchronous with starting up the processes, or
are there other things we could look at measuring? I would expect that starting
up processes is the most expensive thing that the extension system does at
chrome startup.

[Yoyo Zhou, 2015-02-05 19:10:51]

On 2015/02/05 16:17:35, kalman wrote:
> lgtm, are these events actually synchronous with starting up the processes, or
> are there other things we could look at measuring? I would expect that
starting
> up processes is the most expensive thing that the extension system does at
> chrome startup.

I think this is the closest I found, but I can keep looking.

[Yoyo Zhou, 2015-02-05 19:10:56]

The CQ bit was checked by yoz@chromium.org

[commit-bot: I haz the power, 2015-02-05 19:12:01]

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

[commit-bot: I haz the power, 2015-02-05 19:17:46]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-02-05 19:17:47]

Try jobs failed on following builders:
  chromium_presubmit on tryserver.chromium.linux
(http://build.chromium.org/p/tryserver.chromium.linux/builders/chromium_presub...)

[Yoyo Zhou, 2015-02-05 19:40:16]

yoz@chromium.org changed reviewers:
+ atwilson@chromium.org

[Yoyo Zhou, 2015-02-05 19:40:17]

atwilson: can you review background_contents_service?

[Yoyo Zhou, 2015-02-06 00:10:21]

On 2015/02/05 16:17:35, kalman wrote:
> lgtm, are these events actually synchronous with starting up the processes, or
> are there other things we could look at measuring? I would expect that
starting
> up processes is the most expensive thing that the extension system does at
> chrome startup.

kalman: starting up processes and loading background pages is not on the UI
thread, so they don't go into the count here (i.e. they're measured in many
seconds, rather than sub-second total - see Extensions.BackgroundPageLoadTime
and EventPageLoadTime). I'm sure they have impact though. How do we figure the
effect of other threads / IO on startup?

[Ilya Sherman, 2015-02-06 00:13:16]

On 2015/02/06 00:10:21, Yoyo Zhou wrote:
> On 2015/02/05 16:17:35, kalman wrote:
> > lgtm, are these events actually synchronous with starting up the processes,
or
> > are there other things we could look at measuring? I would expect that
> starting
> > up processes is the most expensive thing that the extension system does at
> > chrome startup.
> 
> kalman: starting up processes and loading background pages is not on the UI
> thread, so they don't go into the count here (i.e. they're measured in many
> seconds, rather than sub-second total - see Extensions.BackgroundPageLoadTime
> and EventPageLoadTime). I'm sure they have impact though. How do we figure the
> effect of other threads / IO on startup?

Which thread are they on?  Startup is a little unusual in that pretty much all
of the named threads are under contention, and so blocking any of them is sad
times.  It's hard to directly deduce the impact on startup time, though.

[Yoyo Zhou, 2015-02-06 00:20:27]

On 2015/02/06 00:13:16, Ilya Sherman wrote:
> On 2015/02/06 00:10:21, Yoyo Zhou wrote:
> > On 2015/02/05 16:17:35, kalman wrote:
> > > lgtm, are these events actually synchronous with starting up the
processes,
> or
> > > are there other things we could look at measuring? I would expect that
> > starting
> > > up processes is the most expensive thing that the extension system does at
> > > chrome startup.
> > 
> > kalman: starting up processes and loading background pages is not on the UI
> > thread, so they don't go into the count here (i.e. they're measured in many
> > seconds, rather than sub-second total - see
Extensions.BackgroundPageLoadTime
> > and EventPageLoadTime). I'm sure they have impact though. How do we figure
the
> > effect of other threads / IO on startup?
> 
> Which thread are they on?  Startup is a little unusual in that pretty much all
> of the named threads are under contention, and so blocking any of them is sad
> times.  It's hard to directly deduce the impact on startup time, though.

Not the browser process either - it measures how long ExtensionHost takes from
creation to getting WebContentsObserver::DidStopLoading, so it's measuring the
time taken in the renderer process.

[not at google - send to devlin, 2015-02-06 00:37:51]

> kalman: starting up processes and loading background pages is not on the UI
> thread, so they don't go into the count here (i.e. they're measured in many
> seconds, rather than sub-second total - see Extensions.BackgroundPageLoadTime
> and EventPageLoadTime).

Whoa those are high. I think the measurement (potentially) has a bug though, the
timer is started on ExtensionHost construction but loading doesn't actualy start
until later. We can follow up on this separately.

[Andrew T Wilson (Slow), 2015-02-06 09:10:02]

lgtm

[Yoyo Zhou, 2015-02-06 18:59:35]

The CQ bit was checked by yoz@chromium.org

[commit-bot: I haz the power, 2015-02-06 19:00:17]

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

[commit-bot: I haz the power, 2015-02-06 19:04:12]

Committed patchset #3 (id:40001)

[commit-bot: I haz the power, 2015-02-06 19:05:05]

Patchset 3 (id:??) landed as
https://crrev.com/1c99cbefc7c06e5542c8eb7be394e16d19bed398
Cr-Commit-Position: refs/heads/master@{#315081}