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

PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check

SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory.
SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL.
SB2.Network: The time it takes to get the full hash response from the server and parse it.

This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results:
+ SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time

+ SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time

+ SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. The PVer4 version is called: SafeBrowsing.V4GetHashNetwork.Time

Adding these metrics would allow us to do a more reasonable comparison.

BUG=543161

Review-Url: https://chromiumcodereview.appspot.com/2441923003
Cr-Commit-Position: refs/heads/master@{#426985}

components/safe_browsing_db/v4_database.cc

@@ -8,11 +8,13 @@
 #include "base/debug/leak_annotations.h"
 #include "base/files/file_util.h"
 #include "base/memory/ptr_util.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "components/safe_browsing_db/v4_database.h"
 #include "content/public/browser/browser_thread.h"
 
 using content::BrowserThread;
+using base::TimeTicks;
 
 namespace safe_browsing {
 
@@ -31,9 +33,9 @@ void V4Database::Create(
   const scoped_refptr<base::SingleThreadTaskRunner> callback_task_runner =
       base::ThreadTaskRunnerHandle::Get();
   db_task_runner->PostTask(
-      FROM_HERE,
-      base::Bind(&V4Database::CreateOnTaskRunner, db_task_runner, base_path,
-                 list_infos, callback_task_runner, new_db_callback));
+      FROM_HERE, base::Bind(&V4Database::CreateOnTaskRunner, db_task_runner,
+                            base_path, list_infos, callback_task_runner,
+                            new_db_callback, TimeTicks::Now()));
 }
 
 // static
@@ -42,7 +44,8 @@ void V4Database::CreateOnTaskRunner(
     const base::FilePath& base_path,
     const ListInfos& list_infos,
     const scoped_refptr<base::SingleThreadTaskRunner>& callback_task_runner,
-    NewDatabaseReadyCallback new_db_callback) {
+    NewDatabaseReadyCallback new_db_callback,
+    const TimeTicks create_start_time) {
   DCHECK(db_task_runner->RunsTasksOnCurrentThread());
 
   if (!factory_) {
@@ -72,6 +75,9 @@ void V4Database::CreateOnTaskRunner(
   // thread. This would unblock resource loads.
   callback_task_runner->PostTask(
       FROM_HERE, base::Bind(new_db_callback, base::Passed(&v4_database)));
+
+  UMA_HISTOGRAM_TIMES("SafeBrowsing.V4DatabaseOpen.Time",
+                      TimeTicks::Now() - create_start_time);
 }
 
 V4Database::V4Database(

components/safe_browsing_db/v4_database.h

@@ -164,7 +164,8 @@ class V4Database {
       const base::FilePath& base_path,
       const ListInfos& list_infos,
       const scoped_refptr<base::SingleThreadTaskRunner>& callback_task_runner,
-      NewDatabaseReadyCallback callback);
+      NewDatabaseReadyCallback callback,
+      const base::TimeTicks create_start_time);
 
   // Callback called when a new store has been created and is ready to be used.
   // This method updates the store_map_ to point to the new store, which causes

components/safe_browsing_db/v4_get_hash_protocol_manager.cc

@@ -171,12 +171,14 @@ FullHashCallbackInfo::FullHashCallbackInfo(
     std::unique_ptr<net::URLFetcher> fetcher,
     const FullHashToStoreAndHashPrefixesMap&
         full_hash_to_store_and_hash_prefixes,
-    const FullHashCallback& callback)
+    const FullHashCallback& callback,
+    const base::Time& network_start_time)
     : cached_full_hash_infos(cached_full_hash_infos),
       callback(callback),
       fetcher(std::move(fetcher)),
       full_hash_to_store_and_hash_prefixes(
           full_hash_to_store_and_hash_prefixes),
+      network_start_time(network_start_time),
       prefixes_requested(prefixes_requested) {}
 
 FullHashCallbackInfo::~FullHashCallbackInfo() {}
@@ -298,7 +300,7 @@ void V4GetHashProtocolManager::GetFullHashes(
   net::URLFetcher* fetcher = owned_fetcher.get();
   pending_hash_requests_[fetcher].reset(new FullHashCallbackInfo(
       cached_full_hash_infos, prefixes_to_request, std::move(owned_fetcher),
-      full_hash_to_store_and_hash_prefixes, callback));
+      full_hash_to_store_and_hash_prefixes, callback, clock_->Now()));
 
   fetcher->SetExtraRequestHeaders(headers.ToString());
   fetcher->SetLoadFlags(net::LOAD_DISABLE_CACHE);
@@ -726,6 +728,8 @@ void V4GetHashProtocolManager::OnURLFetchComplete(
   }
 
   const std::unique_ptr<FullHashCallbackInfo>& fhci = it->second;
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4GetHashNetwork.Time",
+                           clock_->Now() - fhci->network_start_time);
   UpdateCache(fhci->prefixes_requested, full_hash_infos, negative_cache_expire);
   MergeResults(fhci->full_hash_to_store_and_hash_prefixes, full_hash_infos,
                &fhci->cached_full_hash_infos);

components/safe_browsing_db/v4_get_hash_protocol_manager.h

@@ -106,7 +106,8 @@ struct FullHashCallbackInfo {
                        std::unique_ptr<net::URLFetcher> fetcher,
                        const FullHashToStoreAndHashPrefixesMap&
                            full_hash_to_store_and_hash_prefixes,
-                       const FullHashCallback& callback);
+                       const FullHashCallback& callback,
+                       const base::Time& network_start_time);
   ~FullHashCallbackInfo();
 
   // The FullHashInfo objects retrieved from cache. These are merged with the
@@ -125,6 +126,10 @@ struct FullHashCallbackInfo {
   // which to look for a full hash match.
   FullHashToStoreAndHashPrefixesMap full_hash_to_store_and_hash_prefixes;
 
+  // Used to measure how long did it take to fetch the full hash response from
+  // the server.
+  base::Time network_start_time;
+
   // The prefixes that were requested from the server.
   std::vector<HashPrefix> prefixes_requested;
 };

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,21 @@ 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.
+  // NOTE(vakh): This doesn't distinguish which stores it's searching through.
+  // However, the vast majority of the entries in this histogram will be from
+  // searching the three CHECK_BROWSE_URL stores.
+  base::TimeDelta diff = TimeTicks::Now() - before;
+  UMA_HISTOGRAM_TIMES("SB2.FilterCheck", diff);
+  UMA_HISTOGRAM_CUSTOM_TIMES("SafeBrowsing.V4GetPrefixMatches.Time", diff,
+                             base::TimeDelta::FromMicroseconds(20),
+                             base::TimeDelta::FromSeconds(1), 50);
+  return !full_hash_to_store_and_hash_prefixes->empty();
 }
 
 void V4LocalDatabaseManager::GetSeverestThreatTypeAndMetadata(

components/safe_browsing_db/v4_local_database_manager.h

@@ -109,6 +109,11 @@ class V4LocalDatabaseManager : public SafeBrowsingDatabaseManager {
     // The threat verdict for the URL being checked.
     SBThreatType result_threat_type;
 
+    // When the check was sent to the SafeBrowsing service. Used to record the
+    // time it takes to get the uncached full hashes from the service (or a
+    // cached full hash response).
+    base::TimeTicks full_hash_check_start;
+
     // The SafeBrowsing lists to check hash prefixes in.
     StoresToCheck stores_to_check;
 

tools/metrics/histograms/histograms.xml

@@ -51794,6 +51794,14 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="SafeBrowsing.V4DatabaseOpen.Time" units="ms">
+  <owner>vakh@chromium.org</owner>
+  <summary>
+    The time it takes to parse and load the SafeBrowsing database from disk, in
+    milliseconds.
+  </summary>
+</histogram>
+
 <histogram name="SafeBrowsing.V4DecodeAdditionsResult"
     enum="SafeBrowsingV4DecodeResult">
   <obsolete>
@@ -51856,6 +51864,22 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   <summary>Track get hash response hits for V4 full hash requests.</summary>
 </histogram>
 
+<histogram name="SafeBrowsing.V4GetHashNetwork.Time" units="ms">
+  <owner>vakh@chromium.org</owner>
+  <summary>
+    The time that it took to receive a response from the Google SafeBrowsing
+    servers for a full hash request.
+  </summary>
+</histogram>
+
+<histogram name="SafeBrowsing.V4GetPrefixMatches.Time" units="ms">
+  <owner>vakh@chromium.org</owner>
+  <summary>
+    The time that it took to check a URL against our in-memory database. It is
+    dominated by the time to perform checks for CheckBrowseUrl.
+  </summary>
+</histogram>
+
 <histogram name="SafeBrowsing.V4MergeUpdateTime" units="ms">
   <obsolete>
     Replaced by SafeBrowsing.V4*.MergeUpdate.Time.