Add histograms to measure new SafeBrowsing performance.

Review URL: http://codereview.chromium.org/10712

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@5423 0039d316-1c4b-4281-b951-d872f2087c98

6 files changed, 81 insertions, 14 deletions

diff --git a/chrome/browser/safe_browsing/protocol_manager.cc b/chrome/browser/safe_browsing/protocol_manager.cc
index bc37759..af0194f 100644
--- a/chrome/browser/safe_browsing/protocol_manager.cc
+++ b/chrome/browser/safe_browsing/protocol_manager.cc
@@ -309,6 +309,10 @@ bool SafeBrowsingProtocolManager::HandleServiceResponse(const GURL& url,
       break;
     }
     case CHUNK_REQUEST: {
+      if (sb_service_->new_safe_browsing())
+        UMA_HISTOGRAM_TIMES(L"SB2.ChunkRequest",
+                            base::Time::Now() - chunk_request_start_);
+
       const ChunkUrl chunk_url = chunk_request_urls_.front();
       bool re_key = false;
       std::deque<SBChunk>* chunks = new std::deque<SBChunk>;
@@ -446,6 +450,7 @@ void SafeBrowsingProtocolManager::IssueChunkRequest() {
   request_.reset(new URLFetcher(chunk_url, URLFetcher::GET, this));
   request_->set_load_flags(net::LOAD_DISABLE_CACHE);
   request_->set_request_context(Profile::GetDefaultRequestContext());
+  chunk_request_start_ = base::Time::Now();
   request_->Start();
 }
 
@@ -514,7 +519,11 @@ void SafeBrowsingProtocolManager::OnChunkInserted() {
   chunk_pending_to_write_ = false;
 
   if (chunk_request_urls_.empty()) {
-    UMA_HISTOGRAM_LONG_TIMES(L"SB.Update", Time::Now() - last_update_);
+    // Don't pollute old implementation histograms with new implemetation data.
+    if (sb_service_->new_safe_browsing())
+      UMA_HISTOGRAM_LONG_TIMES(L"SB2.Update", Time::Now() - last_update_);
+    else
+      UMA_HISTOGRAM_LONG_TIMES(L"SB.Update", Time::Now() - last_update_);
     sb_service_->UpdateFinished(true);
   } else {
     IssueChunkRequest();
diff --git a/chrome/browser/safe_browsing/protocol_manager.h b/chrome/browser/safe_browsing/protocol_manager.h
index ae89319..bb64f67 100644
--- a/chrome/browser/safe_browsing/protocol_manager.h
+++ b/chrome/browser/safe_browsing/protocol_manager.h
@@ -204,6 +204,9 @@ class SafeBrowsingProtocolManager : public URLFetcher::Delegate {
   // Current product version sent in each request.
   std::string version_;
 
+  // Used for measuring chunk request latency.
+  base::Time chunk_request_start_;
+
   DISALLOW_COPY_AND_ASSIGN(SafeBrowsingProtocolManager);
 };
 
diff --git a/chrome/browser/safe_browsing/safe_browsing_database_bloom.cc b/chrome/browser/safe_browsing/safe_browsing_database_bloom.cc
index 77aff53..e87ad4a 100644
--- a/chrome/browser/safe_browsing/safe_browsing_database_bloom.cc
+++ b/chrome/browser/safe_browsing/safe_browsing_database_bloom.cc
@@ -9,6 +9,7 @@
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/platform_thread.h"
+#include "base/process_util.h"
 #include "base/sha2.h"
 #include "base/stats_counters.h"
 #include "base/string_util.h"
@@ -88,8 +89,10 @@ void SafeBrowsingDatabaseBloom::LoadBloomFilter() {
     return;
 
   if (!file_util::GetFileSize(bloom_filter_filename_, &size_64) ||
-      size_64 == 0)
+      size_64 == 0) {
+    UMA_HISTOGRAM_COUNTS(L"SB2.FilterMissing", 1);
     return;
+  }
 
   // We have a bloom filter file, so use that as our filter.
   int size = static_cast<int>(size_64);
@@ -223,6 +226,7 @@ bool SafeBrowsingDatabaseBloom::CreateTables() {
 
   transaction.Commit();
   add_count_ = 0;
+
   return true;
 }
 
@@ -363,6 +367,8 @@ void SafeBrowsingDatabaseBloom::InsertChunks(const std::string& list_name,
   if (chunks->empty())
     return;
 
+  base::Time insert_start = base::Time::Now();
+
   int list_id = GetListId(list_name);
   ChunkType chunk_type = chunks->front().is_add ? ADD_CHUNK : SUB_CHUNK;
 
@@ -400,6 +406,8 @@ void SafeBrowsingDatabaseBloom::InsertChunks(const std::string& list_name,
     chunks->pop_front();
   }
 
+  UMA_HISTOGRAM_TIMES(L"SB2.ChunkInsert", base::Time::Now() - insert_start);
+
   delete chunks;
 
   if (chunk_inserted_callback_.get())
@@ -892,8 +900,8 @@ bool SafeBrowsingDatabaseBloom::BuildAddPrefixList(SBPair* adds) {
 
 bool SafeBrowsingDatabaseBloom::RemoveSubs(
     SBPair* adds, std::vector<bool>* adds_removed, 
-    HashCache* add_cache, HashCache* sub_cache) {
-  DCHECK(add_cache && sub_cache);
+    HashCache* add_cache, HashCache* sub_cache, int* subs) {
+  DCHECK(add_cache && sub_cache && subs);
 
   // Read through sub_prefix and zero out add_prefix entries that match.
   SQLITE_UNIQUE_STATEMENT(sub_prefix, *statement_cache_,
@@ -935,6 +943,7 @@ bool SafeBrowsingDatabaseBloom::RemoveSubs(
   }
 
   SBPair sub;
+  int sub_count = 0;
   while (true) {
     int rv = sub_prefix->step();
     if (rv != SQLITE_ROW) {
@@ -975,9 +984,11 @@ bool SafeBrowsingDatabaseBloom::RemoveSubs(
       }
       DCHECK(rv == SQLITE_DONE);
       sub_prefix_tmp->reset();
+      ++sub_count;
     }
   }
 
+  *subs = sub_count;
   return true;
 }
 
@@ -1260,6 +1271,15 @@ bool SafeBrowsingDatabaseBloom::BuildSubFullHashCache(HashCache* sub_cache) {
 // TODO(erikkay): should we call WaitAfterResume() inside any of the loops here?
 // This is a pretty fast operation and it would be nice to let it finish.
 void SafeBrowsingDatabaseBloom::BuildBloomFilter() {
+#if defined(OS_WIN)
+  // For measuring the amount of IO during the bloom filter build.
+  IoCounters io_before, io_after;
+  ProcessHandle handle = Process::Current().handle();
+  scoped_ptr<process_util::ProcessMetrics> metric;
+  metric.reset(process_util::ProcessMetrics::CreateProcessMetrics(handle));
+  metric->GetIOCounters(&io_before);
+#endif
+
   Time before = Time::Now();
 
   // Get all the pending GetHash results and write them to disk.
@@ -1298,7 +1318,8 @@ void SafeBrowsingDatabaseBloom::BuildBloomFilter() {
   adds_removed.resize(add_count_, false);
 
   // Flag any add as removed if there is a matching sub.
-  if (!RemoveSubs(adds, &adds_removed, add_cache.get(), sub_cache.get()))
+  int subs = 0;
+  if (!RemoveSubs(adds, &adds_removed, add_cache.get(), sub_cache.get(), &subs))
     return;
 
   // Prepare the database for writing out our remaining add and sub prefixes.
@@ -1324,15 +1345,10 @@ void SafeBrowsingDatabaseBloom::BuildBloomFilter() {
   int rv = insert_transaction_->Commit();
   if (rv != SQLITE_OK) {
     NOTREACHED() << "SafeBrowsing update transaction failed to commit.";
+    UMA_HISTOGRAM_COUNTS(L"SB2.FailedUpdate", 1);
     return;
   }
 
-  TimeDelta bloom_gen = Time::Now() - before;
-  SB_DLOG(INFO) << "SafeBrowsingDatabaseImpl built bloom filter in "
-                << bloom_gen.InMilliseconds()
-                << " ms total.  prefix count: "<< add_count_;
-  UMA_HISTOGRAM_LONG_TIMES(L"SB.BuildBloom", bloom_gen);
-
   // Swap in the newly built filter and cache. If there were any matching subs,
   // the size (add_count_) will be smaller.
   {
@@ -1342,8 +1358,36 @@ void SafeBrowsingDatabaseBloom::BuildBloomFilter() {
     hash_cache_.swap(add_cache);
   }
 
+  TimeDelta bloom_gen = Time::Now() - before;
+
   // Persist the bloom filter to disk.
   WriteBloomFilter();
+
+  // Gather statistics.
+#if defined(OS_WIN)
+  metric->GetIOCounters(&io_after);
+  UMA_HISTOGRAM_COUNTS(L"SB2.BuildReadBytes",
+                       static_cast<int>(io_after.ReadTransferCount -
+                                        io_before.ReadTransferCount));
+  UMA_HISTOGRAM_COUNTS(L"SB2.BuildWriteBytes",
+                       static_cast<int>(io_after.WriteTransferCount -
+                                        io_before.WriteTransferCount));
+  UMA_HISTOGRAM_COUNTS(L"SB2.BuildReadOperations",
+                       static_cast<int>(io_after.ReadOperationCount -
+                                        io_before.ReadOperationCount));
+  UMA_HISTOGRAM_COUNTS(L"SB2.BuildWriteOperations",
+                       static_cast<int>(io_after.WriteOperationCount -
+                                        io_before.WriteOperationCount));
+#endif
+  SB_DLOG(INFO) << "SafeBrowsingDatabaseImpl built bloom filter in "
+                << bloom_gen.InMilliseconds()
+                << " ms total.  prefix count: "<< add_count_;
+  UMA_HISTOGRAM_LONG_TIMES(L"SB2.BuildFilter", bloom_gen);
+  UMA_HISTOGRAM_COUNTS(L"SB2.AddPrefixes", add_count_);
+  UMA_HISTOGRAM_COUNTS(L"SB2.SubPrefixes", subs);
+  int64 size_64;
+  if (file_util::GetFileSize(filename_, &size_64))
+    UMA_HISTOGRAM_COUNTS(L"SB2.DatabaseBytes", static_cast<int>(size_64));
 }
 
 void SafeBrowsingDatabaseBloom::GetCachedFullHashes(
diff --git a/chrome/browser/safe_browsing/safe_browsing_database_bloom.h b/chrome/browser/safe_browsing/safe_browsing_database_bloom.h
index 3f3f1a2..a7db0f2 100644
--- a/chrome/browser/safe_browsing/safe_browsing_database_bloom.h
+++ b/chrome/browser/safe_browsing/safe_browsing_database_bloom.h
@@ -137,7 +137,8 @@ class SafeBrowsingDatabaseBloom : public SafeBrowsingDatabase {
   bool RemoveSubs(SBPair* adds,
                   std::vector<bool>* adds_removed,
                   HashCache* add_cache,
-                  HashCache* sub_cache);
+                  HashCache* sub_cache,
+                  int* subs);
 
   bool UpdateTables();
   bool WritePrefixes(SBPair* adds, const std::vector<bool>& adds_removed,
@@ -242,7 +243,7 @@ class SafeBrowsingDatabaseBloom : public SafeBrowsingDatabase {
   base::hash_set<int> sub_del_cache_;
 
   // The number of entries in the add_prefix table. Used to pick the correct
-  // size for the bloom filter.
+  // size for the bloom filter and stats gathering.
   int add_count_;
 
   // Set to true if the machine just resumed out of a sleep.  When this happens,
diff --git a/chrome/browser/safe_browsing/safe_browsing_service.cc b/chrome/browser/safe_browsing/safe_browsing_service.cc
index c09806d..a2c62a2 100644
--- a/chrome/browser/safe_browsing/safe_browsing_service.cc
+++ b/chrome/browser/safe_browsing/safe_browsing_service.cc
@@ -202,9 +202,13 @@ bool SafeBrowsingService::CheckUrlNew(const GURL& url, Client* client) {
   std::string list;
   std::vector<SBPrefix> prefix_hits;
   std::vector<SBFullHashResult> full_hits;
+  base::Time check_start = base::Time::Now();
   bool prefix_match = database_->ContainsUrl(url, &list, &prefix_hits,
                                              &full_hits,
                                              protocol_manager_->last_update());
+  
+  UMA_HISTOGRAM_TIMES(L"SB2.FilterCheck", base::Time::Now() - check_start);
+
   if (!prefix_match)
     return true;  // URL is okay.
 
@@ -406,8 +410,12 @@ void SafeBrowsingService::HandleGetHashResults(
 
   DCHECK(enabled_);
 
+  if (new_safe_browsing_)
+    UMA_HISTOGRAM_LONG_TIMES(L"SB2.Network", Time::Now() - check->start);
+  else
+    UMA_HISTOGRAM_LONG_TIMES(L"SB.Network", Time::Now() - check->start);
+
   std::vector<SBPrefix> prefixes = check->prefix_hits;
-  UMA_HISTOGRAM_LONG_TIMES(L"SB.Network", Time::Now() - check->start);
   OnHandleGetHashResults(check, full_hashes);  // 'check' is deleted here.
 
   if (can_cache) {
diff --git a/chrome/browser/safe_browsing/safe_browsing_service.h b/chrome/browser/safe_browsing/safe_browsing_service.h
index 9c07636..485819f 100644
--- a/chrome/browser/safe_browsing/safe_browsing_service.h
+++ b/chrome/browser/safe_browsing/safe_browsing_service.h
@@ -174,6 +174,8 @@ class SafeBrowsingService
   void OnSuspend();
   void OnResume();
 
+  bool new_safe_browsing() const { return new_safe_browsing_; }
+
  private:
   // Should only be called on db thread as SafeBrowsingDatabase is not
   // threadsafe.