Omnibox: Add Histograms to Time Parts of SearchProvider

chrome/browser/autocomplete/search_provider.cc

Index: chrome/browser/autocomplete/search_provider.cc
diff --git a/chrome/browser/autocomplete/search_provider.cc b/chrome/browser/autocomplete/search_provider.cc
index 38f0b9e04c79359b98e6ef2a5f89c681b74c8eee..3871d8d12fdd9da38d2f3b07bdb36198ad5ca0fa 100644
--- a/chrome/browser/autocomplete/search_provider.cc
+++ b/chrome/browser/autocomplete/search_provider.cc
@@ -624,6 +624,8 @@ void SearchProvider::DoHistoryQuery(bool minimal_changes) {
   if (minimal_changes)
     return;
 
+  base::TimeTicks do_history_query_start_time(base::TimeTicks::Now());
+
   keyword_history_results_.clear();
   default_history_results_.clear();
 
@@ -631,10 +633,17 @@ void SearchProvider::DoHistoryQuery(bool minimal_changes) {
       input_.current_page_classification()))
     return;
 
+  base::TimeTicks start_time(base::TimeTicks::Now());
   HistoryService* const history_service =
       HistoryServiceFactory::GetForProfile(profile_, Profile::EXPLICIT_ACCESS);
+  base::TimeTicks now(base::TimeTicks::Now());

[msw, 2013/08/29 17:32:24]

eliminate |now|

+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.GetHistoryServiceTime",
+                      now - start_time);
+  start_time = now;
   history::URLDatabase* url_db = history_service ?
       history_service->InMemoryDatabase() : NULL;
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.InMemoryDatabaseTime",

[msw, 2013/08/29 17:32:24]

Is it worthwhlie to dig in beyond the overall DoHistoryQueryTime now?

+                      base::TimeTicks::Now() - start_time);
   if (!url_db)
     return;
 
@@ -650,14 +659,20 @@ void SearchProvider::DoHistoryQuery(bool minimal_changes) {
   int num_matches = kMaxMatches * 5;
   const TemplateURL* default_url = providers_.GetDefaultProviderURL();
   if (default_url) {
+    start_time = base::TimeTicks::Now();
     url_db->GetMostRecentKeywordSearchTerms(default_url->id(), input_.text(),
         num_matches, &default_history_results_);
+    UMA_HISTOGRAM_TIMES(
+        "Omnibox.SearchProvider.GetMostRecentKeywordTermsDefaultProviderTime",

[msw, 2013/08/29 17:32:24]

nit: RecentKeywordTermsTime? I guess names don't matter much anyway...

+        base::TimeTicks::Now() - start_time);
   }
   const TemplateURL* keyword_url = providers_.GetKeywordProviderURL();
   if (keyword_url) {
     url_db->GetMostRecentKeywordSearchTerms(keyword_url->id(),
         keyword_input_.text(), num_matches, &keyword_history_results_);
   }
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.DoHistoryQueryTime",
+                      base::TimeTicks::Now() - do_history_query_start_time);
 }
 
 void SearchProvider::StartOrStopSuggestQuery(bool minimal_changes) {
@@ -950,6 +965,7 @@ bool SearchProvider::ParseSuggestResults(Value* root_val, bool is_keyword) {
 void SearchProvider::ConvertResultsToAutocompleteMatches() {
   // Convert all the results to matches and add them to a map, so we can keep
   // the most relevant match for each result.
+  base::TimeTicks start_time(base::TimeTicks::Now());
   MatchMap map;
   const base::Time no_time;
   int did_not_accept_keyword_suggestion =
@@ -1014,6 +1030,8 @@ void SearchProvider::ConvertResultsToAutocompleteMatches() {
   // We will always return any verbatim matches, no matter how we obtained their
   // scores, unless we have already accepted AutocompleteResult::kMaxMatches
   // higher-scoring matches under the conditions above.
+  UMA_HISTOGRAM_CUSTOM_COUNTS(

[msw, 2013/08/29 17:32:24]

Ditto on the questionable necessity of this given the overall
ConvertResultsTime. A set of fewer high-level data points will help us narrow
our investigation once we have a top-level culprit. I'm not excited to see more
fine grained histograms added now that might just be useless.

+      "Omnibox.SearchProvider.NumMatchesToSort", matches.size(), 1, 50, 20);
   std::sort(matches.begin(), matches.end(), &AutocompleteMatch::MoreRelevant);
   matches_.clear();
 
@@ -1040,6 +1058,8 @@ void SearchProvider::ConvertResultsToAutocompleteMatches() {
 
     matches_.push_back(*i);
   }
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.ConvertResultsTime",
+                      base::TimeTicks::Now() - start_time);
 }
 
 bool SearchProvider::IsTopMatchNavigationInKeywordMode() const {
@@ -1085,6 +1105,7 @@ bool SearchProvider::HasValidDefaultMatch(
 }
 
 void SearchProvider::UpdateMatches() {
+  base::TimeTicks update_matches_start_time(base::TimeTicks::Now());
   ConvertResultsToAutocompleteMatches();
 
   // Check constraints that may be violated by suggested relevances.
@@ -1156,8 +1177,13 @@ void SearchProvider::UpdateMatches() {
     DCHECK(HasValidDefaultMatch(omnibox_will_reorder_for_legal_default_match));
   }
 
+  base::TimeTicks update_starred_start_time(base::TimeTicks::Now());
   UpdateStarredStateOfMatches();
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.UpdateStarredTime",

[msw, 2013/08/29 17:32:24]

ditto

+                      base::TimeTicks::Now() - update_starred_start_time);
   UpdateDone();
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.UpdateMatchesTime",
+                      base::TimeTicks::Now() - update_matches_start_time);
 }
 
 void SearchProvider::AddNavigationResultsToMatches(
@@ -1180,6 +1206,7 @@ void SearchProvider::AddHistoryResultsToMap(const HistoryResults& results,
   if (results.empty())
     return;
 
+  base::TimeTicks start_time(base::TimeTicks::Now());
   bool prevent_inline_autocomplete = input_.prevent_inline_autocomplete() ||
       (input_.type() == AutocompleteInput::URL);
   const string16& input_text =
@@ -1213,6 +1240,8 @@ void SearchProvider::AddHistoryResultsToMap(const HistoryResults& results,
                   did_not_accept_suggestion,
                   is_keyword, map);
   }
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.AddHistoryResultsTime",
+                      base::TimeTicks::Now() - start_time);
 }
 
 SearchProvider::SuggestResults SearchProvider::ScoreHistoryResults(