Refactor Extension initialization logic. Add tracing and additional histogram.

chrome/browser/extensions/installed_loader.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chrome/browser/extensions/installed_loader.h"
 
 #include "base/files/file_path.h"
 #include "base/metrics/histogram.h"
 #include "base/metrics/sparse_histogram.h"
 #include "base/strings/stringprintf.h"
@@ skipping 211 matching lines @@
     return;
   }
 
   if (write_to_prefs)
     extension_prefs_->UpdateManifest(extension.get());
 
   extension_service_->AddExtension(extension.get());
 }
 
 void 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");
-  CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  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();
 
   Profile* profile = extension_service_->profile();
   scoped_ptr<ExtensionPrefs::ExtensionsInfo> extensions_info(
       extension_prefs_->GetInstalledExtensionsInfo());
 
   std::vector<int> reload_reason_counts(NUM_MANIFEST_RELOAD_REASONS, 0);
   bool should_write_prefs = false;
 
@@ skipping 54 matching lines @@
   UMA_HISTOGRAM_COUNTS_100("Extensions.ManifestReloadUnpackedDir",
                            reload_reason_counts[UNPACKED_DIR]);
   UMA_HISTOGRAM_COUNTS_100("Extensions.ManifestReloadNeedsRelocalization",
                            reload_reason_counts[NEEDS_RELOCALIZATION]);
 
   UMA_HISTOGRAM_COUNTS_100("Extensions.LoadAll",
                            extension_registry_->enabled_extensions().size());
   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;
   int hosted_app_count = 0;
   int legacy_packaged_app_count = 0;
   int platform_app_count = 0;
   int user_script_count = 0;
   int content_pack_count = 0;
   int extension_user_count = 0;
   int extension_external_count = 0;
@@ skipping 257 matching lines @@
 int InstalledLoader::GetCreationFlags(const ExtensionInfo* info) {
   int flags = extension_prefs_->GetCreationFlags(info->extension_id);
   if (!Manifest::IsUnpackedLocation(info->extension_location))
     flags |= Extension::REQUIRE_KEY;
   if (extension_prefs_->AllowFileAccess(info->extension_id))
     flags |= Extension::ALLOW_FILE_ACCESS;
   return flags;
 }
 
 }  // namespace extensions