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"
 
+using base::TimeTicks;
+
 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);
+std::string GetUmaSuffixForStore(const base::FilePath& file_path) {
+  return base::StringPrintf(
+      ".%" PRIsFP, file_path.BaseName().RemoveExtension().value().c_str());

[Nathan Parker, 2016/10/04 20:30:43]

[no action required] Is this just a way to convert to UTF8?  I think we're
assuming the filename is ASCII anyway. You might be able to use MaybeAsASCII().

[vakh (use Gerrit instead), 2016/10/04 21:05:15]

The file is always ASCII since we chose the name for it.
The current implementation is consistent with the DebugString so it might be
good to keep it as is.

 }
 
-void RecordStoreWriteResult(StoreWriteResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreWriteResult", result,
-                            STORE_WRITE_RESULT_MAX);
+void RecordTimeWithAndWithoutStore(const std::string& metric,
+                                   base::TimeDelta time,
+                                   const base::FilePath& file_path) {
+  std::string suffix = GetUmaSuffixForStore(file_path);
+
+  // The histograms below are an expansion of the UMA_HISTOGRAM_LONG_TIMES
+  // macro adapted to allow for a dynamically suffixed histogram name.
+  // Note: The factory creates and owns the histogram.
+  base::HistogramBase* histogram = base::Histogram::FactoryTimeGet(
+      metric, base::TimeDelta::FromMilliseconds(1),
+      base::TimeDelta::FromHours(1), 50,

[Nathan Parker, 2016/10/04 20:30:44]

What bucket values does this produce? I'm guessing we don't care about precision
above, say 30 seconds.  Might as well use that precision down lower in the few
ms range.

[vakh (use Gerrit instead), 2016/10/04 21:05:15]

The bucket count is 50. It's the same as UMA_HISTOGRAM_LONG_TIMES.
I could change the bucket count to 100 and reduce the maximum to 1 minute (just
to be safe). WDYT?

+      base::HistogramBase::kUmaTargetedHistogramFlag);
+  if (histogram) {
+    histogram->AddTime(time);
+  }
+
+  base::HistogramBase* histogram_suffix = base::Histogram::FactoryTimeGet(
+      metric + suffix, base::TimeDelta::FromMilliseconds(1),
+      base::TimeDelta::FromHours(1), 50,
+      base::HistogramBase::kUmaTargetedHistogramFlag);
+  if (histogram_suffix) {
+    histogram_suffix->AddTime(time);
+  }
+}
+
+void RecordAddUnlumpedHashesTime(base::TimeDelta time) {
+  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,
+                               const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutStore("SafeBrowsing.V4DecodeAdditionsTime", time,
+                                file_path);
+}
+
 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,
+                              const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutStore("SafeBrowsing.V4DecodeRemovalsTime", time,
+                                file_path);
+}
 
-void RecordApplyUpdateResultWhenReadingFromDisk(ApplyUpdateResult result) {
-  UMA_HISTOGRAM_ENUMERATION(
-      "SafeBrowsing.V4ApplyUpdateResultWhenReadingFromDisk", result,
-      APPLY_UPDATE_RESULT_MAX);
+void RecordMergeUpdateTime(base::TimeDelta time,
+                           const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutStore("SafeBrowsing.V4MergeUpdateTime", time,
+                                file_path);
+}
+
+void RecordProcessFullUpdateTime(base::TimeDelta time,
+                                 const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutStore("SafeBrowsing.V4ProcessFullUpdateTime", time,
+                                file_path);
+}
+
+void RecordProcessPartialUpdateTime(base::TimeDelta time,
+                                    const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutStore("SafeBrowsing.V4ProcessPartialUpdateTime", time,
+                                file_path);
+}
+
+void RecordReadFromDiskTime(base::TimeDelta time,
+                            const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutStore("SafeBrowsing.V4ReadFromDiskTime", time,
+                                file_path);
+}
+
+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());
 
+  TimeTicks before = TimeTicks::Now();
   ApplyUpdateResult result = ProcessUpdate(hash_prefix_map_old, response);
   if (result == APPLY_UPDATE_SUCCESS) {
+    RecordProcessPartialUpdateTime(TimeTicks::Now() - before, store_path_);
     // 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) {
+  TimeTicks before = TimeTicks::Now();
   ApplyUpdateResult result = ProcessFullUpdate(response);
   if (result == APPLY_UPDATE_SUCCESS) {
     RecordStoreWriteResult(WriteToDisk(std::move(response)));
+    RecordProcessFullUpdateTime(TimeTicks::Now() - before, store_path_);
   }
   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();
+      TimeTicks before = 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);
+
       RecordDecodeRemovalsResult(decode_result);
       if (decode_result != DECODE_SUCCESS) {
         return RICE_DECODING_FAILURE;
-      } else {
-        raw_removals = &rice_removals;
       }
+      RecordDecodeRemovalsTime(TimeTicks::Now() - before, store_path_);
+      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();
   }
 
+  TimeTicks before = TimeTicks::Now();
   apply_update_result = MergeUpdate(hash_prefix_map_old, hash_prefix_map,
                                     raw_removals, expected_checksum);
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     return apply_update_result;
   }
+  RecordMergeUpdateTime(TimeTicks::Now() - before, store_path_);
 
   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;
+      TimeTicks before = 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);
       RecordDecodeAdditionsResult(decode_result);
       if (decode_result != DECODE_SUCCESS) {
         return RICE_DECODING_FAILURE;
       } else {
+        RecordDecodeAdditionsTime(TimeTicks::Now() - before, store_path_);
         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;
   }
 
+  TimeTicks before = TimeTicks::Now();
   // 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);
+  RecordAddUnlumpedHashesTime(TimeTicks::Now() - 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());
 
+  TimeTicks before = 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 17 matching lines @@
   }
 
   std::unique_ptr<ListUpdateResponse> response(new ListUpdateResponse);
   response->Swap(file_format.mutable_list_update_response());
   ApplyUpdateResult apply_update_result = ProcessFullUpdate(response);
   RecordApplyUpdateResultWhenReadingFromDisk(apply_update_result);
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     hash_prefix_map_.clear();
     return HASH_PREFIX_MAP_GENERATION_FAILURE;
   }
+  RecordReadFromDiskTime(TimeTicks::Now() - before, store_path_);
 
   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