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

components/safe_browsing_db/v4_local_database_manager.cc

Index: components/safe_browsing_db/v4_local_database_manager.cc
diff --git a/components/safe_browsing_db/v4_local_database_manager.cc b/components/safe_browsing_db/v4_local_database_manager.cc
index 5798bf2af85f7031247620061388d09ce9695088..a16ddd7e87e37b264b14f94de2cfc6cc3b63655f 100644
--- a/components/safe_browsing_db/v4_local_database_manager.cc
+++ b/components/safe_browsing_db/v4_local_database_manager.cc
@@ -13,10 +13,12 @@
 #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 {
 
@@ -337,7 +339,9 @@ bool V4LocalDatabaseManager::GetPrefixMatches(
   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);
@@ -352,14 +356,18 @@ bool V4LocalDatabaseManager::GetPrefixMatches(
             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): only log SafeBrowsing.V4GetPrefixMatches.Time once PVer3 code
+  // is removed.
+  base::TimeDelta diff = TimeTicks::Now() - before;
+  UMA_HISTOGRAM_TIMES("SB2.FilterCheck", diff);
+  UMA_HISTOGRAM_CUSTOM_TIMES("SafeBrowsing.V4GetPrefixMatches.Time", diff,
+                             base::TimeDelta::FromMicroseconds(100),

[Nathan Parker, 2016/10/22 00:24:55]

Does this generate a log or linear scale of buckets?  Linear would be bad since
it'd be (20.1/50) = 402ms buckets, which doesn't help much. I _think_ it'll do
log-spaced buckets, which should be fine.

I'd put the max at 1 second, since anything above that for local memory access
is really broken and therefore uninteresting. And then the minimum could move
lower, say to 20us. If you want to tune it more carefully, you could try it on a
release build, load up cnn.com, and verify the histogram has good resolution
around the common values.

We should note that this doesn't distinguish which DBs it's searching through. 
The vast majority of the entries in this histogram will be from searching the
three BrowseURL DBs.(I don't think it's really worth logging them separately.)

[vakh (use Gerrit instead), 2016/10/22 01:34:34]

Done. The comments for UMA_HISTOGRAM_CUSTOM_TIMES suggest log scale.
UMA_HISTOGRAM_TIMES uses UMA_HISTOGRAM_CUSTOM_TIMES so it should be consistent
with the other histograms that we have.

[Scott Hess - ex-Googler, 2016/10/24 19:24:22]

Log scale unless you're doing something special.

Given log scale, IMHO be conservative about how tight you make things.  The
difference between 1s and 20s is only going to add like 5 buckets.  So if 1s is
literally "I don't even", then fine.  I usually aim to have very few hits in the
overflow bucket, simply because the improved precision is often not all that
valuable, but having to respin the entire histogram entry is annoying :-).

+                             base::TimeDelta::FromSeconds(20), 50);
+  return !full_hash_to_store_and_hash_prefixes->empty();
 }
 
 void V4LocalDatabaseManager::GetSeverestThreatTypeAndMetadata(
@@ -409,6 +417,10 @@ void V4LocalDatabaseManager::OnFullHashResponse(
     return;
   }
 
+  // TODO(vakh): Consider changing the following histogram name to be
+  // SafeBrowsing.V4GetFullHashOverNetwork.Time once PVer3 code is removed.
+  UMA_HISTOGRAM_LONG_TIMES(
+      "SB2.Network", TimeTicks::Now() - pending_check->full_hash_check_start);
   auto it = pending_clients_.find(pending_check->client);
   if (it == pending_clients_.end()) {
     // The check has since been cancelled.
@@ -434,6 +446,9 @@ void V4LocalDatabaseManager::PerformFullHashCheck(
 
   pending_clients_.insert(check->client);
 
+  // Set the start time for the network request (or the response from cache).
+  check->full_hash_check_start = TimeTicks::Now();

[Nathan Parker, 2016/10/22 00:24:55]

Ah, so this will won't distinguish network calls vs cache hits, ya? If not, you
could put this in the protocol_manager so it can log just network requests.  

[vakh (use Gerrit instead), 2016/10/22 01:34:34]

Done.

+
   v4_get_hash_protocol_manager_->GetFullHashes(
       full_hash_to_store_and_hash_prefixes,
       base::Bind(&V4LocalDatabaseManager::OnFullHashResponse,