Refactor Extension initialization logic. Add tracing and additional histogram.

Refactor Extension initialization logic. Add tracing and an additional latency histogram.

Note, this has a functional change on the Extensions.LoadAllTime metric, which didn't have the second half of the method (the part I put in LoadExtensionsMetrics()).
I expect that this section does not take very long, and it makes sense for the LoadAllTime metric to measure the entire method. If you're unhappy of the functional change of the metric, another approach is to add a histogram for LoadExtensionsMetrics() specifically, but I feel this is excessive.

BUG=454789
Committed: https://crrev.com/a8fd8d3b8b0356cf1fb480d90eb89eb8d8b36c4c
Cr-Commit-Position: refs/heads/master@{#318120}

[rkaplow, 2015-02-24 23:52:09]

rkaplow@chromium.org changed reviewers:
+ asvitkine@chromium.org, kalman@chromium.org

[rkaplow, 2015-02-24 23:52:10]

asvitkine@chromium.org: Please review changes in 
all
kalman@chromium.org: Please review changes in 
all

[not at google - send to devlin, 2015-02-25 00:04:17]

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

[Yoyo Zhou, 2015-02-25 00:19:58]

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
File chrome/browser/extensions/extension_service.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:410: // TODO:(erikkay) this
should probably be deferred to a future point
nit: TODO style is
// TODO(erikkay): etc.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:467: 
nit: extraneous newline

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:1432:
"Extensions.ExtensionServiceNotifyReadyListenersTime");
There are two metrics related to this one:
Extensions.ProcessManagerStartupHostsTime and
Extensions.BackgroundContentsServiceStartupTime. (The functions being recorded
there are called from this function.) We could do the same for those as we do
here.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
File chrome/browser/extensions/installed_loader.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.cc:234:
SCOPED_UMA_HISTOGRAM_TIMER("Extensions.LoadAllTime");
Can we put lines 234-308 inside a scope block, so that we don't change the
meaning of this timer? While I agree that the time to record the other metrics
is probably negligible, it's still better not to change what it is we're
measuring if we are keeping the same metric name.

Alternatively we can call it LoadAllTime2 since there's some precedent for
having extension metrics with 2 in the name (thanks kalman). But in this case I
think the original metric more accurately measures the work being done.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.cc:310: }
nit: new line after

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
File chrome/browser/extensions/installed_loader.h (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.h:33: // Store metrics related to the
loaded extensions.
Store/Load seem like the wrong verbs here. How about RecordExtensionsMetrics?

[Alexei Svitkine (slow), 2015-02-25 15:17:11]

asvitkine@chromium.org changed reviewers:
+ rkaplow@chromium.org

[Alexei Svitkine (slow), 2015-02-25 15:17:11]

+rkaplow, can you do a first pass review of this?

[Alexei Svitkine (slow), 2015-02-25 15:17:35]

asvitkine@chromium.org changed reviewers:
- rkaplow@chromium.org

[Alexei Svitkine (slow), 2015-02-25 15:17:48]

Err, ignore last email. :P

[Alexei Svitkine (slow), 2015-02-25 16:10:54]

lgtm % some suggestions

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
File chrome/browser/extensions/extension_service.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:433: it !=
extensions_to_enable.end(); ++it) {
Nit: Since you're touching this code already, this would be a lot cleaner using
C++11 for-based loop, i.e.:

for (const std::string& extension : extensions_to_enable) {
}

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:443:
extension_prefs_->GetAllDelayedInstallInfo());
This should be indented 1 more. You could probably just run "git cl format".

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
File chrome/browser/extensions/installed_loader.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.cc:232:
CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
This should actually be a DCHECK.

[rkaplow, 2015-02-25 16:37:49]

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
File chrome/browser/extensions/extension_service.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:410: // TODO:(erikkay) this
should probably be deferred to a future point
On 2015/02/25 00:19:57, Yoyo Zhou wrote:
> nit: TODO style is
> // TODO(erikkay): etc.

Done.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:433: it !=
extensions_to_enable.end(); ++it) {
On 2015/02/25 16:10:53, Alexei Svitkine wrote:
> Nit: Since you're touching this code already, this would be a lot cleaner
using
> C++11 for-based loop, i.e.:
> 
> for (const std::string& extension : extensions_to_enable) {
> }

Done.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:443:
extension_prefs_->GetAllDelayedInstallInfo());
On 2015/02/25 16:10:53, Alexei Svitkine wrote:
> This should be indented 1 more. You could probably just run "git cl format".

Done.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:467: 
On 2015/02/25 00:19:58, Yoyo Zhou wrote:
> nit: extraneous newline

Done.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/ex...
chrome/browser/extensions/extension_service.cc:1432:
"Extensions.ExtensionServiceNotifyReadyListenersTime");
On 2015/02/25 00:19:57, Yoyo Zhou wrote:
> There are two metrics related to this one:
> Extensions.ProcessManagerStartupHostsTime and
> Extensions.BackgroundContentsServiceStartupTime. (The functions being recorded
> there are called from this function.) We could do the same for those as we do
> here.

Ok, switched to the cleaner SCOPED version there.
I added the traces as well, although that will just be tracing the method calls,
so they won't match 1:1 to the times being measured, but that is ok.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
File chrome/browser/extensions/installed_loader.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.cc:234:
SCOPED_UMA_HISTOGRAM_TIMER("Extensions.LoadAllTime");
On 2015/02/25 00:19:58, Yoyo Zhou wrote:
> Can we put lines 234-308 inside a scope block, so that we don't change the
> meaning of this timer? While I agree that the time to record the other metrics
> is probably negligible, it's still better not to change what it is we're
> measuring if we are keeping the same metric name.
> 
> Alternatively we can call it LoadAllTime2 since there's some precedent for
> having extension metrics with 2 in the name (thanks kalman). But in this case
I
> think the original metric more accurately measures the work being done.

I did mention this in my description - and I agree I wasn't sure what the
"intent" of the metric originally was.

I'll propose this: we leave LoadAllTime as it currently is, and add LoadAllTime2
as you mention. After we look at the metrics, and confirm there is no big delta,
we can obsolete LoadAllTime and just use LoadAllTime2 going forward.

Sounds good?

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.cc:310: }
On 2015/02/25 00:19:58, Yoyo Zhou wrote:
> nit: new line after

Done.

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
File chrome/browser/extensions/installed_loader.h (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.h:33: // Store metrics related to the
loaded extensions.
On 2015/02/25 00:19:58, Yoyo Zhou wrote:
> Store/Load seem like the wrong verbs here. How about RecordExtensionsMetrics?

sounds better.

[rkaplow, 2015-02-25 16:38:28]

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

[rkaplow, 2015-02-25 16:38:28]

atwilson@chromium.org: Please review changes in 

browser/background

[Andrew T Wilson (Slow), 2015-02-25 17:49:31]

lgtm

[Alexei Svitkine (slow), 2015-02-25 18:05:15]

lgtm

[Yoyo Zhou, 2015-02-25 19:34:29]

LGTM

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
File chrome/browser/extensions/installed_loader.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.cc:234:
SCOPED_UMA_HISTOGRAM_TIMER("Extensions.LoadAllTime");
On 2015/02/25 16:37:49, rkaplow wrote:
> On 2015/02/25 00:19:58, Yoyo Zhou wrote:
> > Can we put lines 234-308 inside a scope block, so that we don't change the
> > meaning of this timer? While I agree that the time to record the other
metrics
> > is probably negligible, it's still better not to change what it is we're
> > measuring if we are keeping the same metric name.
> > 
> > Alternatively we can call it LoadAllTime2 since there's some precedent for
> > having extension metrics with 2 in the name (thanks kalman). But in this
case
> I
> > think the original metric more accurately measures the work being done.
> 
> I did mention this in my description - and I agree I wasn't sure what the
> "intent" of the metric originally was.

Ah, I see why it's confusing. It seemed intuitive to me - measure just the time
it takes to load all extensions here - but it does appear to be buggy either
way. (Ideally, that call to Now() should come before all the rest of the
metrics, i.e. at line 294.)

> I'll propose this: we leave LoadAllTime as it currently is, and add
LoadAllTime2
> as you mention. After we look at the metrics, and confirm there is no big
delta,
> we can obsolete LoadAllTime and just use LoadAllTime2 going forward.
> 
> Sounds good?

This is ok with me. Actually, because LoadAllTime looks faulty, you can make it
obsolete now (in another CL if you prefer).

https://codereview.chromium.org/959513002/diff/20001/chrome/browser/extension...
File chrome/browser/extensions/installed_loader.cc (right):

https://codereview.chromium.org/959513002/diff/20001/chrome/browser/extension...
chrome/browser/extensions/installed_loader.cc:232:
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
DCHECK_CURRENTLY_ON()

[rkaplow, 2015-02-25 19:59:50]

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
File chrome/browser/extensions/installed_loader.cc (right):

https://codereview.chromium.org/959513002/diff/1/chrome/browser/extensions/in...
chrome/browser/extensions/installed_loader.cc:234:
SCOPED_UMA_HISTOGRAM_TIMER("Extensions.LoadAllTime");
On 2015/02/25 19:34:29, Yoyo Zhou wrote:
> On 2015/02/25 16:37:49, rkaplow wrote:
> > On 2015/02/25 00:19:58, Yoyo Zhou wrote:
> > > Can we put lines 234-308 inside a scope block, so that we don't change the
> > > meaning of this timer? While I agree that the time to record the other
> metrics
> > > is probably negligible, it's still better not to change what it is we're
> > > measuring if we are keeping the same metric name.
> > > 
> > > Alternatively we can call it LoadAllTime2 since there's some precedent for
> > > having extension metrics with 2 in the name (thanks kalman). But in this
> case
> > I
> > > think the original metric more accurately measures the work being done.
> > 
> > I did mention this in my description - and I agree I wasn't sure what the
> > "intent" of the metric originally was.
> 
> Ah, I see why it's confusing. It seemed intuitive to me - measure just the
time
> it takes to load all extensions here - but it does appear to be buggy either
> way. (Ideally, that call to Now() should come before all the rest of the
> metrics, i.e. at line 294.)
> 
> > I'll propose this: we leave LoadAllTime as it currently is, and add
> LoadAllTime2
> > as you mention. After we look at the metrics, and confirm there is no big
> delta,
> > we can obsolete LoadAllTime and just use LoadAllTime2 going forward.
> > 
> > Sounds good?
> 
> This is ok with me. Actually, because LoadAllTime looks faulty, you can make
it
> obsolete now (in another CL if you prefer).

Ok. Added a TODO. Will follow up - just want to see if there is any measurable
difference. Either way - will clean up in the short term.

https://codereview.chromium.org/959513002/diff/20001/chrome/browser/extension...
File chrome/browser/extensions/installed_loader.cc (right):

https://codereview.chromium.org/959513002/diff/20001/chrome/browser/extension...
chrome/browser/extensions/installed_loader.cc:232:
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
On 2015/02/25 19:34:29, Yoyo Zhou wrote:
> DCHECK_CURRENTLY_ON()

Done.

[rkaplow, 2015-02-25 20:22:37]

The CQ bit was checked by rkaplow@chromium.org

[rkaplow, 2015-02-25 20:22:38]

The patchset sent to the CQ was uploaded after l-g-t-m from
asvitkine@chromium.org, yoz@chromium.org, atwilson@chromium.org
Link to the patchset: https://codereview.chromium.org/959513002/#ps40001 (title:
"yoz comments")

[commit-bot: I haz the power, 2015-02-25 20:23:42]

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

[commit-bot: I haz the power, 2015-02-25 21:28:13]

Committed patchset #3 (id:40001)

[commit-bot: I haz the power, 2015-02-25 21:28:53]

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