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): 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(
     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.
+  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.
     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 (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,
                  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