Omnibox: Add Histograms to Time Parts of SearchProvider

chrome/browser/autocomplete/search_provider.cc

 // Copyright 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/autocomplete/search_provider.h"
 
 #include <algorithm>
 #include <cmath>
 
 #include "base/callback.h"
@@ skipping 606 matching lines @@
       listener_->OnProviderUpdate(false);
   }
 }
 
 void SearchProvider::DoHistoryQuery(bool minimal_changes) {
   // The history query results are synchronous, so if minimal_changes is true,
   // we still have the last results and don't need to do anything.
   if (minimal_changes)
     return;
 
+  base::TimeTicks do_history_query_start_time(base::TimeTicks::Now());
+
   keyword_history_results_.clear();
   default_history_results_.clear();
 
   if (OmniboxFieldTrial::SearchHistoryDisable(
       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;
 
   // Request history for both the keyword and default provider.  We grab many
   // more matches than we'll ultimately clamp to so that if there are several
   // recent multi-word matches who scores are lowered (see
   // AddHistoryResultsToMap()), they won't crowd out older, higher-scoring
   // matches.  Note that this doesn't fix the problem entirely, but merely
   // limits it to cases with a very large number of such multi-word matches; for
   // now, this seems OK compared with the complexity of a real fix, which would
   // require multiple searches and tracking of "single- vs. multi-word" in the
   // database.
   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) {
   if (!IsQuerySuitableForSuggest()) {
     StopSuggest();
     ClearAllResults();
     return;
   }
 
   // For the minimal_changes case, if we finished the previous query and still
@@ skipping 272 matching lines @@
                    comparator);
   std::stable_sort(results->navigation_results.begin(),
                    results->navigation_results.end(),
                    comparator);
   return true;
 }
 
 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 =
       keyword_results_.suggest_results.empty() ?
       TemplateURLRef::NO_SUGGESTIONS_AVAILABLE :
       TemplateURLRef::NO_SUGGESTION_CHOSEN;
 
   bool relevance_from_server;
   int verbatim_relevance = GetVerbatimRelevance(&relevance_from_server);
   int did_not_accept_default_suggestion =
@@ skipping 44 matching lines @@
   // Now add the most relevant matches to |matches_|.  We take up to kMaxMatches
   // suggest/navsuggest matches, regardless of origin.  If Instant Extended is
   // enabled and we have server-provided (and thus hopefully more accurate)
   // scores for some suggestions, we allow more of those, until we reach
   // AutocompleteResult::kMaxMatches total matches (that is, enough to fill the
   // whole popup).
   //
   // 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();
 
   size_t num_suggestions = 0;
   for (ACMatches::const_iterator i(matches.begin());
        (i != matches.end()) &&
            (matches_.size() < AutocompleteResult::kMaxMatches);
        ++i) {
     // SEARCH_OTHER_ENGINE is only used in the SearchProvider for the keyword
     // verbatim result, so this condition basically means "if this match is a
     // suggestion of some sort".
     if ((i->type != AutocompleteMatchType::SEARCH_WHAT_YOU_TYPED) &&
         (i->type != AutocompleteMatchType::SEARCH_OTHER_ENGINE)) {
       // If we've already hit the limit on non-server-scored suggestions, and
       // this isn't a server-scored suggestion we can add, skip it.
       if ((num_suggestions >= kMaxMatches) &&
           (!chrome::IsInstantExtendedAPIEnabled() ||
            (i->GetAdditionalInfo(kRelevanceFromServerKey) != kTrue))) {
         continue;
       }
 
       ++num_suggestions;
     }
 
     matches_.push_back(*i);
   }
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.ConvertResultsTime",
+                      base::TimeTicks::Now() - start_time);
 }
 
 bool SearchProvider::IsTopMatchNavigationInKeywordMode() const {
   return (!providers_.keyword_provider().empty() &&
           (matches_.front().type == AutocompleteMatchType::NAVSUGGEST));
 }
 
 bool SearchProvider::IsTopMatchScoreTooLow() const {
   // Here we use CalculateRelevanceForVerbatimIgnoringKeywordModeState()
   // rather than CalculateRelevanceForVerbatim() because the latter returns
@@ skipping 25 matching lines @@
        ++it) {
     if (it->allowed_to_be_default_match)
       return true;
     if (!autocomplete_result_will_reorder_for_default_match)
       return false;
   }
   return false;
 }
 
 void SearchProvider::UpdateMatches() {
+  base::TimeTicks update_matches_start_time(base::TimeTicks::Now());
   ConvertResultsToAutocompleteMatches();
 
   // Check constraints that may be violated by suggested relevances.
   if (!matches_.empty() &&
       (default_results_.HasServerProvidedScores() ||
        keyword_results_.HasServerProvidedScores())) {
     // These blocks attempt to repair undesirable behavior by suggested
     // relevances with minimal impact, preserving other suggested relevances.
     if (IsTopMatchNavigationInKeywordMode()) {
       // Correct the suggested relevance scores if the top match is a
@@ skipping 51 matching lines @@
       ApplyCalculatedRelevance();
       ConvertResultsToAutocompleteMatches();
     }
     DCHECK(!IsTopMatchNavigationInKeywordMode());
     DCHECK(omnibox_will_reorder_for_legal_default_match ||
         !IsTopMatchScoreTooLow());
     DCHECK(!IsTopMatchSearchWithURLInput());
     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(
     const NavigationResults& navigation_results,
     ACMatches* matches) {
   for (NavigationResults::const_iterator it = navigation_results.begin();
         it != navigation_results.end(); ++it) {
     matches->push_back(NavigationToMatch(*it));
     // In the absence of suggested relevance scores, use only the single
     // highest-scoring result.  (The results are already sorted by relevance.)
     if (!it->relevance_from_server())
       return;
   }
 }
 
 void SearchProvider::AddHistoryResultsToMap(const HistoryResults& results,
                                             bool is_keyword,
                                             int did_not_accept_suggestion,
                                             MatchMap* map) {
   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 =
       is_keyword ? keyword_input_.text() : input_.text();
   bool input_multiple_words = HasMultipleWords(input_text);
 
   SuggestResults scored_results;
   if (!prevent_inline_autocomplete && input_multiple_words) {
     // ScoreHistoryResults() allows autocompletion of multi-word, 1-visit
     // queries if the input also has multiple words.  But if we were already
@@ skipping 13 matching lines @@
     scored_results = ScoreHistoryResults(results, prevent_inline_autocomplete,
                                          input_multiple_words, input_text,
                                          is_keyword);
   for (SuggestResults::const_iterator i(scored_results.begin());
        i != scored_results.end(); ++i) {
     AddMatchToMap(i->suggestion(), input_text, i->relevance(), false,
                   AutocompleteMatchType::SEARCH_HISTORY,
                   did_not_accept_suggestion,
                   is_keyword, map);
   }
+  UMA_HISTOGRAM_TIMES("Omnibox.SearchProvider.AddHistoryResultsTime",
+                      base::TimeTicks::Now() - start_time);
 }
 
 SearchProvider::SuggestResults SearchProvider::ScoreHistoryResults(
     const HistoryResults& results,
     bool base_prevent_inline_autocomplete,
     bool input_multiple_words,
     const string16& input_text,
     bool is_keyword) {
   AutocompleteClassifier* classifier =
       AutocompleteClassifierFactory::GetForProfile(profile_);
@@ skipping 330 matching lines @@
     it->set_relevance(max_query_relevance);
     it->set_relevance_from_server(relevance_from_server);
   }
 }
 
 void SearchProvider::UpdateDone() {
   // We're done when the timer isn't running, there are no suggest queries
   // pending, and we're not waiting on Instant.
   done_ = !timer_.IsRunning() && (suggest_results_pending_ == 0);
 }