Add UMA metrics for the time it takes to read store from disk and apply update

components/safe_browsing_db/v4_store.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.
 
 #include "base/base64.h"
 #include "base/bind.h"
 #include "base/files/file_util.h"
 #include "base/memory/ptr_util.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/metrics/sparse_histogram.h"
 #include "base/stl_util.h"
 #include "base/strings/stringprintf.h"
 #include "components/safe_browsing_db/v4_rice.h"
 #include "components/safe_browsing_db/v4_store.h"
 #include "components/safe_browsing_db/v4_store.pb.h"
 #include "crypto/secure_hash.h"
 #include "crypto/sha2.h"
 
 namespace safe_browsing {
 
 namespace {
 const uint32_t kFileMagic = 0x600D71FE;
 
 const uint32_t kFileVersion = 9;
 
-void RecordStoreReadResult(StoreReadResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreReadResult", result,
-                            STORE_READ_RESULT_MAX);
-}
-
-void RecordStoreWriteResult(StoreWriteResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreWriteResult", result,
-                            STORE_WRITE_RESULT_MAX);
+void RecordAddUnlumpedHashesTime(base::TimeDelta time) {

[Nathan Parker, 2016/09/30 22:32:05]

style nit: Personally I think it's easier to follow if the UMA metric is placed
right in the code. The place where I'd use a function is if it were used more
than once, and you want to ensure consistency and type checking.

[talked offline about adding store_name to these]
So if you're adding store name, then you might want these functions, or even add
them to the class so they can access the store_id/name directly.

[vakh (use Gerrit instead), 2016/10/03 21:30:36]

Done. Added the store specific histograms for Time only for now since this CL is
adding time related metrics.
I'll add the per-store metrics for result enums as a separate CL.

+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4AddUnlumpedHashesTime", time);
 }
 
 void RecordApplyUpdateResult(ApplyUpdateResult result) {
   UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4ApplyUpdateResult", result,
                             APPLY_UPDATE_RESULT_MAX);
 }
 
+void RecordApplyUpdateResultWhenReadingFromDisk(ApplyUpdateResult result) {
+  UMA_HISTOGRAM_ENUMERATION(
+      "SafeBrowsing.V4ApplyUpdateResultWhenReadingFromDisk", result,
+      APPLY_UPDATE_RESULT_MAX);
+}
+
 void RecordDecodeAdditionsResult(V4DecodeResult result) {
   UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4DecodeAdditionsResult", result,
                             DECODE_RESULT_MAX);
 }
 
+void RecordDecodeAdditionsTime(base::TimeDelta time) {
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4DecodeAdditionsTime", time);
+}
+
 void RecordDecodeRemovalsResult(V4DecodeResult result) {
   UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4DecodeRemovalsResult", result,
                             DECODE_RESULT_MAX);
 }
 
-// TODO(vakh): Collect and record the metrics for time taken to process updates.
+void RecordDecodeRemovalsTime(base::TimeDelta time) {
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4DecodeRemovalsTime", time);
+}
 
-void RecordApplyUpdateResultWhenReadingFromDisk(ApplyUpdateResult result) {
-  UMA_HISTOGRAM_ENUMERATION(
-      "SafeBrowsing.V4ApplyUpdateResultWhenReadingFromDisk", result,
-      APPLY_UPDATE_RESULT_MAX);
+void RecordMergeUpdateTime(base::TimeDelta time) {
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4MergeUpdateTime", time);
+}
+
+void RecordProcessFullUpdateTime(base::TimeDelta time) {
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4ProcessFullUpdateTime", time);
+}
+
+void RecordProcessPartialUpdateTime(base::TimeDelta time) {
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4ProcessPartialUpdateTime", time);
+}
+
+void RecordReadFromDiskTime(base::TimeDelta time) {
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4ReadFromDiskTime", time);
+}
+
+void RecordStoreReadResult(StoreReadResult result) {
+  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreReadResult", result,
+                            STORE_READ_RESULT_MAX);
+}
+
+void RecordStoreWriteResult(StoreWriteResult result) {
+  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreWriteResult", result,
+                            STORE_WRITE_RESULT_MAX);
 }
 
 // Returns the name of the temporary file used to buffer data for
 // |filename|.  Exported for unit tests.
 const base::FilePath TemporaryFileForFilename(const base::FilePath& filename) {
   return base::FilePath(filename.value() + FILE_PATH_LITERAL("_new"));
 }
 
 }  // namespace
 
@@ skipping 41 matching lines @@
   state_ = "";
   return true;
 }
 
 ApplyUpdateResult V4Store::ProcessPartialUpdateAndWriteToDisk(
     const HashPrefixMap& hash_prefix_map_old,
     std::unique_ptr<ListUpdateResponse> response) {
   DCHECK(response->has_response_type());
   DCHECK_EQ(ListUpdateResponse::PARTIAL_UPDATE, response->response_type());
 
+  base::TimeTicks before = base::TimeTicks::Now();

[Nathan Parker, 2016/09/30 22:32:05]

I'd add a 
using base::TimeTicks
to simplify all of this.

[vakh (use Gerrit instead), 2016/10/03 21:30:36]

Done.

   ApplyUpdateResult result = ProcessUpdate(hash_prefix_map_old, response);
+  base::TimeTicks after = base::TimeTicks::Now();
   if (result == APPLY_UPDATE_SUCCESS) {
+    RecordProcessPartialUpdateTime(after - before);

[Nathan Parker, 2016/09/30 22:32:05]

nit: You can skip the |afer| and just do TimeTicks::Now() - before. Less
verbiage.  Here and elsewhere.

[vakh (use Gerrit instead), 2016/10/03 21:30:36]

Done.

     // TODO(vakh): Create a ListUpdateResponse containing RICE encoded
     // hash prefixes and response_type as FULL_UPDATE, and write that to disk.
   }
   return result;
 }
 
 ApplyUpdateResult V4Store::ProcessFullUpdateAndWriteToDisk(
     std::unique_ptr<ListUpdateResponse> response) {
+  base::TimeTicks before = base::TimeTicks::Now();
   ApplyUpdateResult result = ProcessFullUpdate(response);
+  base::TimeTicks after = base::TimeTicks::Now();
   if (result == APPLY_UPDATE_SUCCESS) {
     RecordStoreWriteResult(WriteToDisk(std::move(response)));
+    RecordProcessFullUpdateTime(after - before);
   }
   return result;
 }
 
 ApplyUpdateResult V4Store::ProcessFullUpdate(
     const std::unique_ptr<ListUpdateResponse>& response) {
   DCHECK(response->has_response_type());
   DCHECK_EQ(ListUpdateResponse::FULL_UPDATE, response->response_type());
   // TODO(vakh): For a full update, we don't need to process the update in
   // lexographical order to store it, but we do need to do that for calculating
@@ skipping 12 matching lines @@
   DCHECK_LE(removals_size, 1u);
   if (removals_size == 1) {
     const ThreatEntrySet& removal = response->removals().Get(0);
     const CompressionType compression_type = removal.compression_type();
     if (compression_type == RAW) {
       raw_removals = &removal.raw_indices().indices();
     } else if (compression_type == RICE) {
       DCHECK(removal.has_rice_indices());
 
       const RiceDeltaEncoding& rice_indices = removal.rice_indices();
+      base::TimeTicks before = base::TimeTicks::Now();
       V4DecodeResult decode_result = V4RiceDecoder::DecodeIntegers(
           rice_indices.first_value(), rice_indices.rice_parameter(),
           rice_indices.num_entries(), rice_indices.encoded_data(),
           &rice_removals);
+      base::TimeTicks after = base::TimeTicks::Now();
+
       RecordDecodeRemovalsResult(decode_result);
       if (decode_result != DECODE_SUCCESS) {
         return RICE_DECODING_FAILURE;
-      } else {
-        raw_removals = &rice_removals;
       }
+      RecordDecodeRemovalsTime(after - before);
+      raw_removals = &rice_removals;
     } else {
       NOTREACHED() << "Unexpected compression_type type: " << compression_type;
       return UNEXPECTED_COMPRESSION_TYPE_REMOVALS_FAILURE;
     }
   }
 
   HashPrefixMap hash_prefix_map;
   ApplyUpdateResult apply_update_result =
       UpdateHashPrefixMapFromAdditions(response->additions(), &hash_prefix_map);
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     return apply_update_result;
   }
 
   std::string expected_checksum;
   if (response->has_checksum() && response->checksum().has_sha256()) {
     expected_checksum = response->checksum().sha256();
   }
 
+  base::TimeTicks before = base::TimeTicks::Now();
   apply_update_result = MergeUpdate(hash_prefix_map_old, hash_prefix_map,
                                     raw_removals, expected_checksum);
+  base::TimeTicks after = base::TimeTicks::Now();
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     return apply_update_result;
   }
+  RecordMergeUpdateTime(after - before);
 
   state_ = response->new_client_state();
   return APPLY_UPDATE_SUCCESS;
 }
 
 void V4Store::ApplyUpdate(
     std::unique_ptr<ListUpdateResponse> response,
     const scoped_refptr<base::SingleThreadTaskRunner>& callback_task_runner,
     UpdatedStoreReadyCallback callback) {
   std::unique_ptr<V4Store> new_store(
@@ skipping 37 matching lines @@
       DCHECK(addition.raw_hashes().has_raw_hashes());
 
       apply_update_result =
           AddUnlumpedHashes(addition.raw_hashes().prefix_size(),
                             addition.raw_hashes().raw_hashes(), additions_map);
     } else if (compression_type == RICE) {
       DCHECK(addition.has_rice_hashes());
 
       const RiceDeltaEncoding& rice_hashes = addition.rice_hashes();
       std::vector<uint32_t> raw_hashes;
+      base::TimeTicks before = base::TimeTicks::Now();
       V4DecodeResult decode_result = V4RiceDecoder::DecodePrefixes(
           rice_hashes.first_value(), rice_hashes.rice_parameter(),
           rice_hashes.num_entries(), rice_hashes.encoded_data(), &raw_hashes);
+      base::TimeTicks after = base::TimeTicks::Now();
       RecordDecodeAdditionsResult(decode_result);
       if (decode_result != DECODE_SUCCESS) {
         return RICE_DECODING_FAILURE;
       } else {
+        RecordDecodeAdditionsTime(after - before);
         char* raw_hashes_start = reinterpret_cast<char*>(raw_hashes.data());
         size_t raw_hashes_size = sizeof(uint32_t) * raw_hashes.size();
 
         // Rice-Golomb encoding is used to send compressed compressed 4-byte
         // hash prefixes. Hash prefixes longer than 4 bytes will not be
         // compressed, and will be served in raw format instead.
         // Source: https://developers.google.com/safe-browsing/v4/compression
         const PrefixSize kPrefixSize = 4;
         apply_update_result = AddUnlumpedHashes(kPrefixSize, raw_hashes_start,
                                                 raw_hashes_size, additions_map);
@@ skipping 30 matching lines @@
     return PREFIX_SIZE_TOO_SMALL_FAILURE;
   }
   if (prefix_size > kMaxHashPrefixLength) {
     NOTREACHED();
     return PREFIX_SIZE_TOO_LARGE_FAILURE;
   }
   if (raw_hashes_length % prefix_size != 0) {
     return ADDITIONS_SIZE_UNEXPECTED_FAILURE;
   }
 
+  base::TimeTicks before = base::TimeTicks::Now();

[Nathan Parker, 2016/09/30 22:32:05]

What is this recording?  The copying of the string?  Does UMA record time with
sufficient precision to make this an actionable metric?

[vakh (use Gerrit instead), 2016/10/03 21:30:36]

My goal is to remove the TODO.
If UMA shows that this operation doesn't take any considerable amount of time,
that would be an argument for removing the TODO.

The other concern would be to reuse memory but since this operation happens
~once per list every ~15-30 mins, it is probably not worth optimizing.

   // TODO(vakh): Figure out a way to avoid the following copy operation.
   (*additions_map)[prefix_size] =
       std::string(raw_hashes_begin, raw_hashes_begin + raw_hashes_length);
+  base::TimeTicks after = base::TimeTicks::Now();
+  RecordAddUnlumpedHashesTime(after - before);
   return APPLY_UPDATE_SUCCESS;
 }
 
 // static
 bool V4Store::GetNextSmallestUnmergedPrefix(
     const HashPrefixMap& hash_prefix_map,
     const IteratorMap& iterator_map,
     HashPrefix* smallest_hash_prefix) {
   HashPrefix current_hash_prefix;
   bool has_unmerged = false;
@@ skipping 157 matching lines @@
       return CHECKSUM_MISMATCH_FAILURE;
     }
   }
 
   return APPLY_UPDATE_SUCCESS;
 }
 
 StoreReadResult V4Store::ReadFromDisk() {
   DCHECK(task_runner_->RunsTasksOnCurrentThread());
 
+  base::TimeTicks before = base::TimeTicks::Now();
   std::string contents;
   bool read_success = base::ReadFileToString(store_path_, &contents);
   if (!read_success) {
     return FILE_UNREADABLE_FAILURE;
   }
 
   if (contents.empty()) {
     return FILE_EMPTY_FAILURE;
   }
 
@@ skipping 12 matching lines @@
     return FILE_VERSION_INCOMPATIBLE_FAILURE;
   }
 
   if (!file_format.has_list_update_response()) {
     return HASH_PREFIX_INFO_MISSING_FAILURE;
   }
 
   std::unique_ptr<ListUpdateResponse> response(new ListUpdateResponse);
   response->Swap(file_format.mutable_list_update_response());
   ApplyUpdateResult apply_update_result = ProcessFullUpdate(response);
+  base::TimeTicks after = base::TimeTicks::Now();
   RecordApplyUpdateResultWhenReadingFromDisk(apply_update_result);
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     hash_prefix_map_.clear();
     return HASH_PREFIX_MAP_GENERATION_FAILURE;
   }
+  RecordReadFromDiskTime(after - before);
 
   return READ_SUCCESS;
 }
 
 StoreWriteResult V4Store::WriteToDisk(
     std::unique_ptr<ListUpdateResponse> response) const {
   // Do not write partial updates to the disk.
   // After merging the updates, the ListUpdateResponse passed to this method
   // should be a FULL_UPDATE.
   if (!response->has_response_type() ||
@@ skipping 60 matching lines @@
   if (result == 0) {
     return true;
   } else if (result < 0) {
     return HashPrefixMatches(hash_prefix, begin, mid);
   } else {
     return HashPrefixMatches(hash_prefix, mid + prefix_size, end);
   }
 }
 
 }  // namespace safe_browsing