Refactor Extension initialization logic. Add tracing and additional histogram.

chrome/browser/extensions/installed_loader.cc

Index: chrome/browser/extensions/installed_loader.cc
diff --git a/chrome/browser/extensions/installed_loader.cc b/chrome/browser/extensions/installed_loader.cc
index 8d72dcc3fc945b9cf3776d81a91bc21080c577b5..86d9ade4a944d8fb971c4493d5b3340cac689d7c 100644
--- a/chrome/browser/extensions/installed_loader.cc
+++ b/chrome/browser/extensions/installed_loader.cc
@@ -229,8 +229,9 @@ void InstalledLoader::Load(const ExtensionInfo& info, bool write_to_prefs) {
 }
 
 void InstalledLoader::LoadAllExtensions() {
-  TRACE_EVENT0("browser,startup", "InstalledLoader::LoadAllExtensions");
   CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));

[Alexei Svitkine (slow), 2015/02/25 16:10:53]

This should actually be a DCHECK.

+  TRACE_EVENT0("browser,startup", "InstalledLoader::LoadAllExtensions");
+  SCOPED_UMA_HISTOGRAM_TIMER("Extensions.LoadAllTime");

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

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.

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

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?

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

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.)
This is ok with me. Actually, because LoadAllTime looks faulty, you can make it
obsolete now (in another CL if you prefer).

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

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.

 
   base::TimeTicks start_time = base::TimeTicks::Now();
 
@@ -305,8 +306,10 @@ void InstalledLoader::LoadAllExtensions() {
   UMA_HISTOGRAM_COUNTS_100("Extensions.Disabled",
                            extension_registry_->disabled_extensions().size());
 
-  UMA_HISTOGRAM_TIMES("Extensions.LoadAllTime",
-                      base::TimeTicks::Now() - start_time);
+  LoadExtensionsMetrics();
+}

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

nit: new line after

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

Done.

+void InstalledLoader::LoadExtensionsMetrics() {
+  Profile* profile = extension_service_->profile();
 
   int app_user_count = 0;
   int app_external_count = 0;