Add detailed UMA metrics for v4_store, broken down by storeid.

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 {
 
+// UMA related strings.
+const char kDecodeAdditions[] = ".DecodeAdditions";

[Nathan Parker, 2016/10/11 20:51:48]

I think it'd be clearer to group these into suffixes and prefixes (or "base
metrics").

Actually, I think this is complex enough that'd it'd be good to spell out all in
comments all the metrics this file reports, in a compressed form. e.g.

SafeBrowsing.V4ProcessFullUpdate[.{soc_eng,malware,..}].{Result,Time,Decode..}
...

Or 
SafeBrowsing.${PROCESS}.${OPT_LIST}.${SUB_PROCESS}
and spell out when each of those could contain

[vakh (use Gerrit instead), 2016/10/11 23:08:05]

Done.

+const char kDecodeRemovals[] = ".DecodeRemovals";
+const char kProcessFullUpdate[] = "SafeBrowsing.V4ProcessFullUpdate";
+const char kProcessPartialUpdate[] = "SafeBrowsing.V4ProcessPartialUpdate";
+const char kReadFromDisk[] = "SafeBrowsing.V4ReadFromDisk";
+const char kResult[] = ".Result";
+const char kTime[] = ".Time";
+
 const uint32_t kFileMagic = 0x600D71FE;
-
 const uint32_t kFileVersion = 9;
 
 std::string GetUmaSuffixForStore(const base::FilePath& file_path) {
   return base::StringPrintf(
       ".%" PRIsFP, file_path.BaseName().RemoveExtension().value().c_str());
 }
 
-void RecordTimeWithAndWithoutStore(const std::string& metric,
-                                   base::TimeDelta time,
-                                   const base::FilePath& file_path) {
+void RecordTimeWithAndWithoutSuffix(const std::string& metric,
+                                    base::TimeDelta time,
+                                    const base::FilePath& file_path) {
   // The histograms below are a modified 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.
   const int kBucketCount = 100;
   base::HistogramBase* histogram = base::Histogram::FactoryTimeGet(
-      metric, base::TimeDelta::FromMilliseconds(1),
+      metric + kTime, base::TimeDelta::FromMilliseconds(1),
       base::TimeDelta::FromMinutes(1), kBucketCount,
       base::HistogramBase::kUmaTargetedHistogramFlag);
   if (histogram) {
     histogram->AddTime(time);
   }
 
   std::string suffix = GetUmaSuffixForStore(file_path);
   base::HistogramBase* histogram_suffix = base::Histogram::FactoryTimeGet(
-      metric + suffix, base::TimeDelta::FromMilliseconds(1),
+      metric + suffix + kTime, base::TimeDelta::FromMilliseconds(1),
       base::TimeDelta::FromMinutes(1), kBucketCount,
       base::HistogramBase::kUmaTargetedHistogramFlag);
   if (histogram_suffix) {
     histogram_suffix->AddTime(time);
   }
 }
 
+void RecordEnumWithAndWithoutSuffix(const std::string& metric,
+                                    int32_t value,
+                                    int32_t maximum,
+                                    const base::FilePath& file_path) {
+  // The histograms below are an expansion of the UMA_HISTOGRAM_ENUMERATION
+  // macro adapted to allow for a dynamically suffixed histogram name.
+  // Note: The factory creates and owns the histogram.
+  base::HistogramBase* histogram = base::LinearHistogram::FactoryGet(
+      metric + kResult, 1, maximum, maximum + 1,
+      base::HistogramBase::kUmaTargetedHistogramFlag);
+  if (histogram) {
+    histogram->Add(value);
+  }
+
+  std::string suffix = GetUmaSuffixForStore(file_path);
+  base::HistogramBase* histogram_suffix = base::LinearHistogram::FactoryGet(
+      metric + suffix + kResult, 1, maximum, maximum + 1,
+      base::HistogramBase::kUmaTargetedHistogramFlag);
+  if (histogram_suffix) {
+    histogram_suffix->Add(value);
+  }
+}
+
 void RecordAddUnlumpedHashesTime(base::TimeDelta time) {
-  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4AddUnlumpedHashesTime", time);
+  UMA_HISTOGRAM_LONG_TIMES("SafeBrowsing.V4AddUnlumpedHashes.Time", time);

[Nathan Parker, 2016/10/11 20:51:48]

Should this one also vary by store name?

[vakh (use Gerrit instead), 2016/10/11 23:08:05]

No, I intend to delete this histogram actually.
I'm adding it to justify its deletion.
It takes 0-1 ms per operation so probably not worth recording at all.

 }
 
-void RecordApplyUpdateResult(ApplyUpdateResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4ApplyUpdateResult", result,
-                            APPLY_UPDATE_RESULT_MAX);
+void RecordApplyUpdateResult(const std::string& base_metric,
+                             ApplyUpdateResult result,
+                             const base::FilePath& file_path) {
+  RecordEnumWithAndWithoutSuffix(base_metric + ".ApplyUpdate", result,

[Nathan Parker, 2016/10/11 20:51:48]

use a const string here too?

[vakh (use Gerrit instead), 2016/10/11 23:08:05]

Only used in this one place so defined inline.

+                                 APPLY_UPDATE_RESULT_MAX, file_path);
 }
 
-void RecordApplyUpdateResultWhenReadingFromDisk(ApplyUpdateResult result) {
-  UMA_HISTOGRAM_ENUMERATION(
-      "SafeBrowsing.V4ApplyUpdateResultWhenReadingFromDisk", result,
-      APPLY_UPDATE_RESULT_MAX);
+void RecordDecodeAdditionsResult(const std::string& base_metric,
+                                 V4DecodeResult result,
+                                 const base::FilePath& file_path) {
+  RecordEnumWithAndWithoutSuffix(base_metric + kDecodeAdditions, result,
+                                 DECODE_RESULT_MAX, file_path);
 }
 
-void RecordDecodeAdditionsResult(V4DecodeResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4DecodeAdditionsResult", result,
-                            DECODE_RESULT_MAX);
+void RecordDecodeAdditionsTime(const std::string& base_metric,
+                               base::TimeDelta time,
+                               const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutSuffix(base_metric + kDecodeAdditions, time,
+                                 file_path);
 }
 
-void RecordDecodeAdditionsTime(base::TimeDelta time,
-                               const base::FilePath& file_path) {
-  RecordTimeWithAndWithoutStore("SafeBrowsing.V4DecodeAdditionsTime", time,
-                                file_path);
+void RecordDecodeRemovalsResult(const std::string& base_metric,
+                                V4DecodeResult result,
+                                const base::FilePath& file_path) {
+  RecordEnumWithAndWithoutSuffix(base_metric + kDecodeRemovals, result,
+                                 DECODE_RESULT_MAX, file_path);
 }
 
-void RecordDecodeRemovalsResult(V4DecodeResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4DecodeRemovalsResult", result,
-                            DECODE_RESULT_MAX);
+void RecordDecodeRemovalsTime(const std::string& base_metric,
+                              base::TimeDelta time,
+                              const base::FilePath& file_path) {
+  RecordTimeWithAndWithoutSuffix(base_metric + kDecodeRemovals, time,
+                                 file_path);
 }
 
-void RecordDecodeRemovalsTime(base::TimeDelta time,
-                              const base::FilePath& file_path) {
-  RecordTimeWithAndWithoutStore("SafeBrowsing.V4DecodeRemovalsTime", time,
-                                file_path);
-}
-
-void RecordMergeUpdateTime(base::TimeDelta time,
+void RecordMergeUpdateTime(const std::string& base_metric,
+                           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);
+  RecordTimeWithAndWithoutSuffix(base_metric + ".MergeUpdate", time, file_path);

[Nathan Parker, 2016/10/11 20:51:48]

And here too? Or, are you just using constants for strings that are used > once?

[vakh (use Gerrit instead), 2016/10/11 23:08:05]

Yup, except kProcessFullUpdate but defining it at the top to keep it consistent
with kProcessPartialUpdate.

 }
 
 void RecordStoreReadResult(StoreReadResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreReadResult", result,
+  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreRead.Result", result,
                             STORE_READ_RESULT_MAX);
 }
 
 void RecordStoreWriteResult(StoreWriteResult result) {
-  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreWriteResult", result,
+  UMA_HISTOGRAM_ENUMERATION("SafeBrowsing.V4StoreWrite.Result", 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 37 matching lines @@
                             store_path_.value().c_str(), state_base64.c_str());
 }
 
 void V4Store::Reset() {
   expected_checksum_.clear();
   hash_prefix_map_.clear();
   state_ = "";
 }
 
 ApplyUpdateResult V4Store::ProcessPartialUpdateAndWriteToDisk(
+    const std::string& metric,
     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);
+  ApplyUpdateResult result =
+      ProcessUpdate(metric, hash_prefix_map_old, response);
   if (result == APPLY_UPDATE_SUCCESS) {
-    RecordProcessPartialUpdateTime(TimeTicks::Now() - before, store_path_);
+    RecordTimeWithAndWithoutSuffix(metric, 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(
+    const std::string& metric,
     std::unique_ptr<ListUpdateResponse> response) {
   TimeTicks before = TimeTicks::Now();
-  ApplyUpdateResult result = ProcessFullUpdate(response);
+  ApplyUpdateResult result = ProcessFullUpdate(metric, response);
   if (result == APPLY_UPDATE_SUCCESS) {
-    RecordProcessFullUpdateTime(TimeTicks::Now() - before, store_path_);
+    RecordTimeWithAndWithoutSuffix(metric, TimeTicks::Now() - before,
+                                   store_path_);
     RecordStoreWriteResult(WriteToDisk(std::move(response)));
   }
   return result;
 }
 
 ApplyUpdateResult V4Store::ProcessFullUpdate(
+    const std::string& metric,
     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
   // checksum. It might save some CPU cycles to store the full update as-is and
   // walk the list of hash prefixes in lexographical order only for checksum
   // calculation.
-  return ProcessUpdate(HashPrefixMap(), response);
+  return ProcessUpdate(metric, HashPrefixMap(), response);
 }
 
 ApplyUpdateResult V4Store::ProcessUpdate(
+    const std::string& metric,
     const HashPrefixMap& hash_prefix_map_old,
     const std::unique_ptr<ListUpdateResponse>& response) {
   const RepeatedField<int32>* raw_removals = nullptr;
   RepeatedField<int32> rice_removals;
   size_t removals_size = response->removals_size();
   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);
+      RecordDecodeRemovalsResult(metric, decode_result, store_path_);
       if (decode_result != DECODE_SUCCESS) {
         return RICE_DECODING_FAILURE;
       }
-      RecordDecodeRemovalsTime(TimeTicks::Now() - before, store_path_);
+      RecordDecodeRemovalsTime(metric, 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);
+  ApplyUpdateResult apply_update_result = UpdateHashPrefixMapFromAdditions(
+      metric, 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_);
+  RecordMergeUpdateTime(metric, 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(
-      new V4Store(this->task_runner_, this->store_path_));
+  std::unique_ptr<V4Store> new_store(new V4Store(task_runner_, store_path_));
   ApplyUpdateResult apply_update_result;
+  std::string metric;
   if (response->response_type() == ListUpdateResponse::PARTIAL_UPDATE) {
+    metric = kProcessPartialUpdate;
     apply_update_result = new_store->ProcessPartialUpdateAndWriteToDisk(
-        hash_prefix_map_, std::move(response));
+        metric, hash_prefix_map_, std::move(response));
   } else if (response->response_type() == ListUpdateResponse::FULL_UPDATE) {
+    metric = kProcessFullUpdate;
     apply_update_result =
-        new_store->ProcessFullUpdateAndWriteToDisk(std::move(response));
+        new_store->ProcessFullUpdateAndWriteToDisk(metric, std::move(response));
   } else {
     apply_update_result = UNEXPECTED_RESPONSE_TYPE_FAILURE;
     NOTREACHED() << "Failure: Unexpected response type: "
                  << response->response_type();
   }
 
   if (apply_update_result == APPLY_UPDATE_SUCCESS) {
     // new_store is done updating, pass it to the callback.
     callback_task_runner->PostTask(
         FROM_HERE, base::Bind(callback, base::Passed(&new_store)));
   } else {
     DVLOG(1) << "Failure: ApplyUpdate: reason: " << apply_update_result
              << "; store: " << *this;
     // new_store failed updating. Pass a nullptr to the callback.
     callback_task_runner->PostTask(FROM_HERE, base::Bind(callback, nullptr));
   }
 
-  RecordApplyUpdateResult(apply_update_result);
+  RecordApplyUpdateResult(metric, apply_update_result, store_path_);
 }
 
 ApplyUpdateResult V4Store::UpdateHashPrefixMapFromAdditions(
+    const std::string& metric,
     const RepeatedPtrField<ThreatEntrySet>& additions,
     HashPrefixMap* additions_map) {
   for (const auto& addition : additions) {
     ApplyUpdateResult apply_update_result = APPLY_UPDATE_SUCCESS;
     const CompressionType compression_type = addition.compression_type();
     if (compression_type == RAW) {
       DCHECK(addition.has_raw_hashes());
       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);
+      RecordDecodeAdditionsResult(metric, decode_result, store_path_);
       if (decode_result != DECODE_SUCCESS) {
         return RICE_DECODING_FAILURE;
       } else {
-        RecordDecodeAdditionsTime(TimeTicks::Now() - before, store_path_);
+        RecordDecodeAdditionsTime(metric, 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 269 matching lines @@
   if (file_format.version_number() != kFileVersion) {
     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);
-  RecordApplyUpdateResultWhenReadingFromDisk(apply_update_result);
+  ApplyUpdateResult apply_update_result =
+      ProcessFullUpdate(kReadFromDisk, response);
+  RecordApplyUpdateResult(kReadFromDisk, apply_update_result, store_path_);
   if (apply_update_result != APPLY_UPDATE_SUCCESS) {
     hash_prefix_map_.clear();
     return HASH_PREFIX_MAP_GENERATION_FAILURE;
   }
-  RecordReadFromDiskTime(TimeTicks::Now() - before, store_path_);
+  RecordTimeWithAndWithoutSuffix(kReadFromDisk, 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 96 matching lines @@
 
     // Find the next smallest unmerged element in the map.
     has_unmerged = GetNextSmallestUnmergedPrefix(hash_prefix_map_, iterator_map,
                                                  &next_smallest_prefix);
   }
 
   char checksum[crypto::kSHA256Length];
   checksum_ctx->Finish(checksum, sizeof(checksum));
   for (size_t i = 0; i < crypto::kSHA256Length; i++) {
     if (checksum[i] != expected_checksum_[i]) {
-      RecordApplyUpdateResultWhenReadingFromDisk(CHECKSUM_MISMATCH_FAILURE);
+      RecordApplyUpdateResult(kReadFromDisk, CHECKSUM_MISMATCH_FAILURE,
+                              store_path_);
 #if DCHECK_IS_ON()
       std::string checksum_b64, expected_checksum_b64;
       base::Base64Encode(base::StringPiece(checksum, arraysize(checksum)),
                          &checksum_b64);
       base::Base64Encode(expected_checksum_, &expected_checksum_b64);
       DVLOG(1) << "Failure: Checksum mismatch: calculated: " << checksum_b64
                << "; expected: " << expected_checksum_b64
                << "; store: " << *this;
 #endif
       return false;
     }
   }
   return true;
 }
 
 }  // namespace safe_browsing