PVer4: Add UMA metrics for time taken to: load DB, do prefix check,

components/safe_browsing_db/v4_local_database_manager.cc

 // Copyright 2016 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.
 
 // This file should not be build on Android but is currently getting built.
 // TODO(vakh): Fix that: http://crbug.com/621647
 
 #include "components/safe_browsing_db/v4_local_database_manager.h"
 
 #include <vector>
 
 #include "base/bind_helpers.h"
 #include "base/callback.h"
 #include "base/memory/ptr_util.h"
 #include "base/memory/ref_counted.h"
+#include "base/metrics/histogram_macros.h"
 #include "components/safe_browsing_db/v4_feature_list.h"
 #include "content/public/browser/browser_thread.h"
 
 using content::BrowserThread;
+using base::TimeTicks;
 
 namespace safe_browsing {
 
 namespace {
 
 const ThreatSeverity kLeastSeverity =
     std::numeric_limits<ThreatSeverity>::max();
 
 ListInfos GetListInfos() {
   // NOTE(vakh): When adding a store here, add the corresponding store-specific
@@ skipping 300 matching lines @@
 }
 
 bool V4LocalDatabaseManager::GetPrefixMatches(
     const std::unique_ptr<PendingCheck>& check,
     FullHashToStoreAndHashPrefixesMap* full_hash_to_store_and_hash_prefixes) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   DCHECK(enabled_);
   DCHECK(v4_database_);
   DCHECK_GT(ClientCallbackType::CHECK_MAX, check->client_callback_type);
+  full_hash_to_store_and_hash_prefixes->clear();
 
+  const base::TimeTicks before = TimeTicks::Now();
   if (check->client_callback_type == ClientCallbackType::CHECK_BROWSE_URL) {
     std::unordered_set<FullHash> full_hashes;
     V4ProtocolManagerUtil::UrlToFullHashes(check->url, &full_hashes);
 
     StoreAndHashPrefixes matched_store_and_hash_prefixes;
     for (const auto& full_hash : full_hashes) {
       matched_store_and_hash_prefixes.clear();
       v4_database_->GetStoresMatchingFullHash(full_hash, check->stores_to_check,
                                               &matched_store_and_hash_prefixes);
       if (!matched_store_and_hash_prefixes.empty()) {
         (*full_hash_to_store_and_hash_prefixes)[full_hash] =
             matched_store_and_hash_prefixes;
       }
     }
-
-    // No hash prefixes found in the local database so that resource must be
-    // safe.
-    return !full_hash_to_store_and_hash_prefixes->empty();
+  } else {
+    NOTREACHED() << "Unexpected client_callback_type encountered";
   }
 
-  NOTREACHED() << "Unexpected client_callback_type encountered";
-  return false;
+  // TODO(vakh): Consider changing the following histogram name to be
+  // SafeBrowsing.V4GetPrefixMatches.Time once PVer3 code is removed.
+  UMA_HISTOGRAM_TIMES("SB2.FilterCheck", TimeTicks::Now() - before);

[Nathan Parker, 2016/10/21 20:21:19]

This is almost always < 1 ms.  I think we should log it like this for comparison
to pver3, but maybe also log it to your suggested new metric in microseconds. 
The latter would be useful to detect/measure any performance changes in this
code.

[vakh (use Gerrit instead), 2016/10/21 22:54:04]

Done.

+  return !full_hash_to_store_and_hash_prefixes->empty();
 }
 
 void V4LocalDatabaseManager::GetSeverestThreatTypeAndMetadata(
     SBThreatType* result_threat_type,
     ThreatMetadata* metadata,
     const std::vector<FullHashInfo>& full_hash_infos) {
   DCHECK(result_threat_type);
   DCHECK(metadata);
 
   ThreatSeverity most_severe_yet = kLeastSeverity;
@@ skipping 29 matching lines @@
 void V4LocalDatabaseManager::OnFullHashResponse(
     std::unique_ptr<PendingCheck> pending_check,
     const std::vector<FullHashInfo>& full_hash_infos) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (!enabled_) {
     DCHECK(pending_clients_.empty());
     return;
   }
 
+  // TODO(vakh): Consider changing the following histogram name to be
+  // SafeBrowsing.V4GetFullHashOverNetwork.Time once PVer3 code is removed.

[Nathan Parker, 2016/10/21 20:21:19]

an aside: There is a SafeBrowsing.GetV4HashResult.  Maybe that should be
V4GetFullHash.Result?

Feel free to lay these out in the spreadsheet. It's helpful to see them all in
one place to make it clear what the patterns are.

[vakh (use Gerrit instead), 2016/10/21 22:54:04]

Yes, I need to correct the metrics in that file. On my radar.
Ack.

+  UMA_HISTOGRAM_LONG_TIMES("SB2.Network",
+                           TimeTicks::Now() - pending_check->start);
   auto it = pending_clients_.find(pending_check->client);
   if (it == pending_clients_.end()) {
     // The check has since been cancelled.
     return;
   }
 
   // Find out the most severe threat, if any, to report to the client.
   GetSeverestThreatTypeAndMetadata(&pending_check->result_threat_type,
                                    &pending_check->url_metadata,
                                    full_hash_infos);
   pending_clients_.erase(it);
   RespondToClient(std::move(pending_check));
 }
 
 void V4LocalDatabaseManager::PerformFullHashCheck(
     std::unique_ptr<PendingCheck> check,
     const FullHashToStoreAndHashPrefixesMap&
         full_hash_to_store_and_hash_prefixes) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   DCHECK(enabled_);
   DCHECK(!full_hash_to_store_and_hash_prefixes.empty());
 
   pending_clients_.insert(check->client);
 
+  // Set the start time for the network request.
+  check->start = TimeTicks::Now();
+
   v4_get_hash_protocol_manager_->GetFullHashes(
       full_hash_to_store_and_hash_prefixes,
       base::Bind(&V4LocalDatabaseManager::OnFullHashResponse,
                  weak_factory_.GetWeakPtr(), base::Passed(std::move(check))));
 }
 
 void V4LocalDatabaseManager::ProcessQueuedChecks() {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   for (auto& it : queued_checks_) {
     FullHashToStoreAndHashPrefixesMap full_hash_to_store_and_hash_prefixes;
@@ skipping 61 matching lines @@
 }
 
 void V4LocalDatabaseManager::UpdateRequestCompleted(
     std::unique_ptr<ParsedServerResponse> parsed_server_response) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   v4_database_->ApplyUpdate(std::move(parsed_server_response),
                             db_updated_callback_);
 }
 
 }  // namespace safe_browsing