[UMA] Record entity changes in DataTypeDebugInfoEmitter

This CL introduces new UMA histograms that record types of commits and
updates processed by the sync engine. For each datatype there is a
separate histogram so that the data can indicate bugs or regression in
individual data types.

Bug: 859859
Change-Id: Iaeaa7a657ebe7d9d6fbbd329152162c5acaadc01
Reviewed-on: https://chromium-review.googlesource.com/1131507
Commit-Queue: Jan Krcal <jkrcal@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Reviewed-by: Mikel Astiz <mastiz@chromium.org>
Cr-Commit-Position: refs/heads/master@{#577592}

components/sync/BUILD.gn

@@ -858,6 +858,7 @@ source_set("unit_tests") {
     "engine/ui_model_worker_unittest.cc",
     "engine_impl/apply_control_data_updates_unittest.cc",
     "engine_impl/backoff_delay_provider_unittest.cc",
+    "engine_impl/cycle/data_type_debug_info_emitter_unittest.cc",
     "engine_impl/cycle/nudge_tracker_unittest.cc",
     "engine_impl/cycle/status_controller_unittest.cc",
     "engine_impl/debug_info_event_listener_unittest.cc",

components/sync/base/data_type_histogram.cc

@@ -11,9 +11,7 @@ const char kModelTypeMemoryHistogramPrefix[] = "Sync.ModelTypeMemoryKB.";
 void SyncRecordMemoryKbHistogram(const std::string& histogram_name_prefix,
                                  syncer::ModelType model_type,
                                  size_t value) {
-  std::string type_string;
-  if (RealModelTypeToNotificationType(model_type, &type_string)) {
-    std::string full_histogram_name = histogram_name_prefix + type_string;
-    base::UmaHistogramCounts1M(full_histogram_name, value / 1024);
-  }
+  std::string type_string = ModelTypeToHistogramSuffix(model_type);
+  std::string full_histogram_name = histogram_name_prefix + type_string;
+  base::UmaHistogramCounts1M(full_histogram_name, value / 1024);
 }

components/sync/base/model_type.h

@@ -331,10 +331,14 @@ FullModelTypeSet ToFullModelTypeSet(ModelTypeSet in);
 
 // TODO(sync): The functions below badly need some cleanup.
 
-// Returns a pointer to a string with application lifetime that represents
-// the name of |model_type|.
+// Returns a string with application lifetime that represents the name of
+// |model_type|.
 const char* ModelTypeToString(ModelType model_type);
 
+// Returns a string with application lifetime that is used as the histogram
+// suffix for |model_type|.
+const char* ModelTypeToHistogramSuffix(ModelType model_type);
+
 // Some histograms take an integer parameter that represents a model type.
 // The mapping from ModelType to integer is defined here. It should match the
 // mapping from integer to labels defined in histograms.xml.

components/sync/engine_impl/cycle/data_type_debug_info_emitter.cc

@@ -4,14 +4,64 @@
 
 #include "components/sync/engine_impl/cycle/data_type_debug_info_emitter.h"
 
+#include <string>
+
+#include "base/metrics/histogram.h"
 #include "components/sync/engine/cycle/type_debug_info_observer.h"
 
 namespace syncer {
 
+namespace {
+
+const char kModelTypeEntityChangeHistogramPrefix[] =
+    "Sync.ModelTypeEntityChange.";
+
+// Values corrospond to a UMA histogram, do not modify, or delete any values.
+// Add new values only directly before COUNT.
+enum ModelTypeEntityChange {
+  LOCAL_DELETION = 0,
+  LOCAL_CREATION = 1,
+  LOCAL_UPDATE = 2,
+  REMOTE_DELETION = 3,
+  REMOTE_UPDATE = 4,
+  MODEL_TYPE_ENTITY_CHANGE_COUNT = 5
+};
+
+void EmitNewChangesToUma(int count,
+                         ModelTypeEntityChange bucket,
+                         base::HistogramBase* histogram) {
+  DCHECK_GE(count, 0);
+  if (count > 0) {
+    histogram->AddCount(bucket, count);
+  }
+}
+
+// We'll add many values in this histogram. Since the name of the histogram is
+// not static here, we cannot use the (efficient) macros that use caching of the
+// histogram object. The helper functions like UmaHistogramEnumeration are not
+// efficient and thus we need re-implement the code here, caching the resulting
+// histogram object.
+base::HistogramBase* GetModelTypeEntityChangeHistogram(ModelType type) {
+  std::string type_string = ModelTypeToHistogramSuffix(type);
+  std::string full_histogram_name =
+      kModelTypeEntityChangeHistogramPrefix + type_string;
+  return base::LinearHistogram::FactoryGet(
+      /*name=*/full_histogram_name, /*minimum=*/1,
+      /*maximum=*/MODEL_TYPE_ENTITY_CHANGE_COUNT,
+      /*bucket_count=*/MODEL_TYPE_ENTITY_CHANGE_COUNT + 1,
+      /*flagz=*/base::HistogramBase::kUmaTargetedHistogramFlag);
+}
+
+}  // namespace
+
 DataTypeDebugInfoEmitter::DataTypeDebugInfoEmitter(
     ModelType type,
     base::ObserverList<TypeDebugInfoObserver>* observers)
-    : type_(type), type_debug_info_observers_(observers) {}
+    : type_(type),
+      type_debug_info_observers_(observers),
+      histogram_(GetModelTypeEntityChangeHistogram(type)) {
+  DCHECK(histogram_);
+}
 
 DataTypeDebugInfoEmitter::~DataTypeDebugInfoEmitter() {}
 
@@ -26,6 +76,23 @@ CommitCounters* DataTypeDebugInfoEmitter::GetMutableCommitCounters() {
 void DataTypeDebugInfoEmitter::EmitCommitCountersUpdate() {
   for (auto& observer : *type_debug_info_observers_)
     observer.OnCommitCountersUpdated(type_, commit_counters_);
+
+  // Emit the newly added counts to UMA.
+  EmitNewChangesToUma(
+      /*count=*/commit_counters_.num_creation_commits_attempted -
+          emitted_commit_counters_.num_creation_commits_attempted,
+      /*bucket=*/LOCAL_CREATION, histogram_);
+  EmitNewChangesToUma(
+      /*count=*/commit_counters_.num_deletion_commits_attempted -
+          emitted_commit_counters_.num_deletion_commits_attempted,
+      /*bucket=*/LOCAL_DELETION, histogram_);
+  EmitNewChangesToUma(
+      /*count=*/commit_counters_.num_update_commits_attempted -
+          emitted_commit_counters_.num_update_commits_attempted,
+      /*bucket=*/LOCAL_UPDATE, histogram_);
+
+  // Mark the current state of the counters as uploaded to UMA.
+  emitted_commit_counters_ = commit_counters_;
 }
 
 const UpdateCounters& DataTypeDebugInfoEmitter::GetUpdateCounters() const {
@@ -39,6 +106,27 @@ UpdateCounters* DataTypeDebugInfoEmitter::GetMutableUpdateCounters() {
 void DataTypeDebugInfoEmitter::EmitUpdateCountersUpdate() {
   for (auto& observer : *type_debug_info_observers_)
     observer.OnUpdateCountersUpdated(type_, update_counters_);
+
+  // Emit the newly added counts to UMA.
+  EmitNewChangesToUma(
+      /*count=*/update_counters_.num_tombstone_updates_received -
+          emitted_update_counters_.num_tombstone_updates_received,
+      /*bucket=*/REMOTE_DELETION, histogram_);
+  // The REMOTE_UPDATE type is not explicitly stored, we need to compute it as a
+  // diff of (all - deletions).
+  int emitted_remote_updates_count =
+      emitted_update_counters_.num_updates_received -
+      emitted_update_counters_.num_tombstone_updates_received;
+  int remote_updates_count = update_counters_.num_updates_received -
+                             update_counters_.num_tombstone_updates_received;
+  EmitNewChangesToUma(
+      /*count=*/remote_updates_count - emitted_remote_updates_count,
+      /*bucket=*/REMOTE_UPDATE, histogram_);
+
+  // Mark the current state of the counters as uploaded to UMA.
+  emitted_update_counters_ = update_counters_;
 }
 
+void DataTypeDebugInfoEmitter::EmitStatusCountersUpdate() {}
+
 }  // namespace syncer

components/sync/engine_impl/cycle/data_type_debug_info_emitter.h

@@ -13,6 +13,10 @@
 #include "components/sync/engine/cycle/commit_counters.h"
 #include "components/sync/engine/cycle/update_counters.h"
 
+namespace base {
+class HistogramBase;
+}
+
 namespace syncer {
 
 class TypeDebugInfoObserver;
@@ -55,8 +59,10 @@ class DataTypeDebugInfoEmitter {
   // Triggers an update counters update to registered observers.
   void EmitUpdateCountersUpdate();
 
-  // Triggers a status counters update to registered observers.
-  virtual void EmitStatusCountersUpdate() = 0;
+  // Triggers a status counters update to registered observers. The default
+  // implementation does nothing and is present only to make this class
+  // non-abstract and thus unit-testable.
+  virtual void EmitStatusCountersUpdate();
 
  protected:
   const ModelType type_;
@@ -68,9 +74,20 @@ class DataTypeDebugInfoEmitter {
   base::ObserverList<TypeDebugInfoObserver>* type_debug_info_observers_;
 
  private:
+  // The actual up-to-date counters.
   CommitCounters commit_counters_;
   UpdateCounters update_counters_;
 
+  // The last state of the counters emitted to UMA. In the next round of
+  // emitting to UMA, we only need to upload the diff between the actual
+  // counters and the counts here.
+  CommitCounters emitted_commit_counters_;
+  UpdateCounters emitted_update_counters_;
+
+  // The histogram to record to; cached for efficiency because many histogram
+  // entries are recorded in this object during run-time.
+  base::HistogramBase* const histogram_;
+
   DISALLOW_COPY_AND_ASSIGN(DataTypeDebugInfoEmitter);
 };
 

components/sync/engine_impl/cycle/data_type_debug_info_emitter_unittest.cc

+// Copyright 2018 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 "components/sync/engine_impl/cycle/data_type_debug_info_emitter.h"
+
+#include "base/test/metrics/histogram_tester.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace syncer {
+namespace {
+
+TEST(DataTypeDebugInfoEmitterTest, ShouldEmitCommitsToUMAIfChanged) {
+  base::ObserverList<TypeDebugInfoObserver> observers;
+  DataTypeDebugInfoEmitter emitter(BOOKMARKS, &observers);
+
+  CommitCounters* counters = emitter.GetMutableCommitCounters();
+  counters->num_deletion_commits_attempted += 3;
+  counters->num_creation_commits_attempted += 2;
+  counters->num_update_commits_attempted += 1;
+
+  base::HistogramTester histogram_tester;
+  emitter.EmitCommitCountersUpdate();
+  EXPECT_EQ(
+      3, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*LOCAL_DELETION=*/0));
+  EXPECT_EQ(
+      2, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*LOCAL_CREATION=*/1));
+  EXPECT_EQ(1, histogram_tester.GetBucketCount(
+                   "Sync.ModelTypeEntityChange.BOOKMARK", /*LOCAL_UPDATE=*/2));
+}
+
+TEST(DataTypeDebugInfoEmitterTest, ShouldNotEmitCommitsToUMAIfNotChanged) {
+  base::ObserverList<TypeDebugInfoObserver> observers;
+  DataTypeDebugInfoEmitter emitter(BOOKMARKS, &observers);
+
+  base::HistogramTester histogram_tester;
+  emitter.EmitCommitCountersUpdate();
+  histogram_tester.ExpectTotalCount("Sync.ModelTypeEntityChange.BOOKMARK", 0);
+}
+
+// Tests that at each EmitCommitCountersUpdate() call, only the changes since
+// the last call to EmitCommitCountersUpdate() are reported to UMA.
+TEST(DataTypeDebugInfoEmitterTest, ShouldEmitCommitsToUMAIncrementally) {
+  base::ObserverList<TypeDebugInfoObserver> observers;
+  DataTypeDebugInfoEmitter emitter(BOOKMARKS, &observers);
+
+  CommitCounters* counters = emitter.GetMutableCommitCounters();
+  counters->num_deletion_commits_attempted += 3;
+  counters->num_creation_commits_attempted += 2;
+  counters->num_update_commits_attempted += 1;
+
+  // First emission - tested in the test above.
+  emitter.EmitCommitCountersUpdate();
+
+  counters = emitter.GetMutableCommitCounters();
+  counters->num_deletion_commits_attempted += 1;
+  counters->num_creation_commits_attempted += 2;
+  counters->num_update_commits_attempted += 3;
+
+  // Test the second emission that it only reports the increment in counters.
+  base::HistogramTester histogram_tester;
+  emitter.EmitCommitCountersUpdate();
+  EXPECT_EQ(
+      1, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*LOCAL_DELETION=*/0));
+  EXPECT_EQ(
+      2, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*LOCAL_CREATION=*/1));
+  EXPECT_EQ(3, histogram_tester.GetBucketCount(
+                   "Sync.ModelTypeEntityChange.BOOKMARK", /*LOCAL_UPDATE=*/2));
+}
+
+TEST(DataTypeDebugInfoEmitterTest, ShouldEmitUpdatesToUMAIfChanged) {
+  base::ObserverList<TypeDebugInfoObserver> observers;
+  DataTypeDebugInfoEmitter emitter(BOOKMARKS, &observers);
+
+  UpdateCounters* counters = emitter.GetMutableUpdateCounters();
+  counters->num_updates_received += 3;
+  counters->num_tombstone_updates_received += 1;
+
+  base::HistogramTester histogram_tester;
+  emitter.EmitUpdateCountersUpdate();
+  EXPECT_EQ(
+      1, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*REMOTE_DELETION=*/3));
+  EXPECT_EQ(
+      2, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*REMOTE_UPDATE=*/4));
+}
+
+TEST(DataTypeDebugInfoEmitterTest, ShouldNotEmitUpdatesToUMAIfNotChanged) {
+  base::ObserverList<TypeDebugInfoObserver> observers;
+  DataTypeDebugInfoEmitter emitter(BOOKMARKS, &observers);
+
+  base::HistogramTester histogram_tester;
+  emitter.EmitUpdateCountersUpdate();
+  histogram_tester.ExpectTotalCount("Sync.ModelTypeEntityChange.BOOKMARK", 0);
+}
+
+// Tests that at each EmitUpdateCountersUpdate() call, only the changes since
+// the last call to EmitUpdateCountersUpdate() are reported to UMA.
+TEST(DataTypeDebugInfoEmitterTest, ShouldEmitUpdatesToUMAIncrementally) {
+  base::ObserverList<TypeDebugInfoObserver> observers;
+  DataTypeDebugInfoEmitter emitter(BOOKMARKS, &observers);
+
+  UpdateCounters* counters = emitter.GetMutableUpdateCounters();
+  counters->num_updates_received += 3;
+  counters->num_tombstone_updates_received += 1;
+
+  // First emission - tested in the test above.
+  emitter.EmitUpdateCountersUpdate();
+
+  counters = emitter.GetMutableUpdateCounters();
+  counters->num_updates_received += 3;
+  counters->num_tombstone_updates_received += 2;
+
+  // Test the second emission that it only reports the increment in counters.
+  base::HistogramTester histogram_tester;
+  emitter.EmitUpdateCountersUpdate();
+  EXPECT_EQ(
+      2, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*REMOTE_DELETION=*/3));
+  EXPECT_EQ(
+      1, histogram_tester.GetBucketCount("Sync.ModelTypeEntityChange.BOOKMARK",
+                                         /*REMOTE_UPDATE=*/4));
+}
+
+}  // namespace
+}  // namespace syncer

components/sync/syncable/directory_backing_store.cc

@@ -280,16 +280,14 @@ void UploadModelTypeEntryCount(const int total_specifics_copies,
                                const int (&entries_counts)[MODEL_TYPE_COUNT]) {
   int total_entry_counts = 0;
   for (int i = FIRST_REAL_MODEL_TYPE; i < MODEL_TYPE_COUNT; ++i) {
-    std::string model_type;
-    if (RealModelTypeToNotificationType((ModelType)i, &model_type)) {
-      std::string full_histogram_name = "Sync.ModelTypeCount." + model_type;
-      base::HistogramBase* histogram = base::Histogram::FactoryGet(
-          full_histogram_name, 1, 1000000, 50,
-          base::HistogramBase::kUmaTargetedHistogramFlag);
-      if (histogram)
-        histogram->Add(entries_counts[i]);
-      total_entry_counts += entries_counts[i];
-    }
+    std::string model_type = ModelTypeToHistogramSuffix((ModelType)i);
+    std::string full_histogram_name = "Sync.ModelTypeCount." + model_type;
+    base::HistogramBase* histogram = base::Histogram::FactoryGet(
+        full_histogram_name, 1, 1000000, 50,
+        base::HistogramBase::kUmaTargetedHistogramFlag);
+    if (histogram)
+      histogram->Add(entries_counts[i]);
+    total_entry_counts += entries_counts[i];
   }
   UMA_HISTOGRAM_COUNTS("Sync.ModelTypeCount", total_entry_counts);
   UMA_HISTOGRAM_COUNTS("Sync.ExtraSyncDataCount",

components/sync/syncable/model_type.cc

@@ -32,7 +32,9 @@ namespace syncer {
 struct ModelTypeInfo {
   ModelType model_type;
   // Model Type notification string.
-  // This needs to match the corresponding proto message name in sync.proto
+  // This needs to match the corresponding proto message name in sync.proto. It
+  // is also used to identify the model type in the SyncModelType
+  // histogram_suffix in histograms.xml. Must always be kept in sync.
   const char* notification_type;
   // Root tag for Model Type
   // This should be the same as the model type but all lowercase.
@@ -49,8 +51,10 @@ struct ModelTypeInfo {
 };
 
 // Below struct entries are in the same order as their definition in the
-// ModelType enum. Don't forget to update the ModelType enum when you make
-// changes to this list.
+// ModelType enum. When making changes to this list, don't forget to
+//  - update the ModelType enum,
+//  - update the SyncModelTypes enum in enums.xml, and
+//  - update the SyncModelType histogram suffix in histograms.xml.
 // Struct field values should be unique across the entire map.
 const ModelTypeInfo kModelTypeInfoMap[] = {
     {UNSPECIFIED, "", "", "Unspecified", -1, 0},
@@ -493,6 +497,17 @@ const char* ModelTypeToString(ModelType model_type) {
   return "Invalid";
 }
 
+const char* ModelTypeToHistogramSuffix(ModelType model_type) {
+  if (model_type >= UNSPECIFIED && model_type < MODEL_TYPE_COUNT) {
+    // We use the same string that is used for notification types because they
+    // satisfy all we need (being stable and explanatory).
+    return kModelTypeInfoMap[model_type].notification_type;
+  }
+  NOTREACHED() << "No known suffix for model type "
+               << static_cast<int>(model_type) << ".";
+  return "Invalid";
+}
+
 // The normal rules about histograms apply here.  Always append to the bottom of
 // the list, and be careful to not reuse integer values that have already been
 // assigned.

tools/metrics/histograms/enums.xml

@@ -45705,6 +45705,18 @@ would be helpful to identify which type is being sent.
   <int value="2" label="EMPTY_FIELD"/>
 </enum>
 
+<enum name="SyncEntityChange">
+  <summary>
+    Type of change of a sync entity. Recorded once for every sync entity
+    whenever it is commited to the server or updated from the server.
+  </summary>
+  <int value="0" label="Local deletion (commited upstream)"/>
+  <int value="1" label="Local creation (commited upstream)"/>
+  <int value="2" label="Local update (commited upstream)"/>
+  <int value="3" label="Remote deletion (updated downstream)"/>
+  <int value="4" label="Remote update (updated downstream)"/>
+</enum>
+
 <enum name="SyncErrorInfobarTypes">
   <summary>Possible errors that can trigger a sync error infobar.</summary>
   <int value="1" label="Sign in needs update"/>

tools/metrics/histograms/histograms.xml

@@ -100144,6 +100144,17 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram base="true" name="Sync.ModelTypeEntityChange"
+    enum="SyncEntityChange" expires_after="2020-02-01">
+  <owner>jkrcal@chromium.org</owner>
+  <summary>
+    Recorded once for every sync entity change (whenever it is commited to the
+    server or updated from the server). This metric is used for monitoring
+    general health of sync client-side code. Note: This is only recorded with a
+    data type suffix. The base version is never recorded.
+  </summary>
+</histogram>
+
 <histogram name="Sync.ModelTypeMemoryKB" units="KB">
   <owner>pavely@chromium.org</owner>
   <summary>
@@ -126510,6 +126521,7 @@ uploading your change for review.
   <suffix name="USER_EVENT" label="USER_EVENT"/>
   <suffix name="WIFI_CREDENTIAL" label="WIFI_CREDENTIAL"/>
   <affected-histogram name="Sync.ModelTypeCount"/>
+  <affected-histogram name="Sync.ModelTypeEntityChange"/>
   <affected-histogram name="Sync.ModelTypeMemoryKB"/>
 </histogram_suffixes>