Add histograms to record the number of writes to the prefs file

base/prefs/json_pref_store.cc

Index: base/prefs/json_pref_store.cc
diff --git a/base/prefs/json_pref_store.cc b/base/prefs/json_pref_store.cc
index 47cd424d9cc9dfa7e8051d13ce72316a6bbd78b9..aa2225615a6e6e6847ee8e22972688b23b9b226e 100644
--- a/base/prefs/json_pref_store.cc
+++ b/base/prefs/json_pref_store.cc
@@ -16,9 +16,11 @@
 #include "base/metrics/histogram.h"
 #include "base/prefs/pref_filter.h"
 #include "base/sequenced_task_runner.h"
+#include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
 #include "base/task_runner_util.h"
 #include "base/threading/sequenced_worker_pool.h"
+#include "base/time/default_clock.h"
 #include "base/values.h"
 
 // Result returned from internal read tasks.
@@ -156,7 +158,8 @@ JsonPrefStore::JsonPrefStore(
       pref_filter_(pref_filter.Pass()),
       initialized_(false),
       filtering_in_progress_(false),
-      read_error_(PREF_READ_ERROR_NONE) {
+      read_error_(PREF_READ_ERROR_NONE),
+      write_count_histogram_(writer_.commit_interval(), path_) {
   DCHECK(!path_.empty());
 }
 
@@ -174,7 +177,8 @@ JsonPrefStore::JsonPrefStore(
       pref_filter_(pref_filter.Pass()),
       initialized_(false),
       filtering_in_progress_(false),
-      read_error_(PREF_READ_ERROR_NONE) {
+      read_error_(PREF_READ_ERROR_NONE),
+      write_count_histogram_(writer_.commit_interval(), path_) {
   DCHECK(!path_.empty());
 }
 
@@ -394,6 +398,8 @@ JsonPrefStore::~JsonPrefStore() {
 bool JsonPrefStore::SerializeData(std::string* output) {
   DCHECK(CalledOnValidThread());
 
+  write_count_histogram_.RecordWriteOccured();
+
   if (pref_filter_)
     pref_filter_->FilterSerializeData(prefs_.get());
 
@@ -435,3 +441,76 @@ void JsonPrefStore::FinalizeFileRead(bool initialization_successful,
 
   return;
 }
+
+const int32_t
+    JsonPrefStore::WriteCountHistogram::kHistogramWriteReportIntervalMins = 5;

[Alexei Svitkine (slow), 2015/04/27 20:21:20]

Add a comment about this that this should not be changed without renaming the
histograms - else it would create incompatible buckets.

[raymes, 2015/04/28 00:32:58]

I did something different, but along the same lines. See the comment and DCHECKs
below :)

+
+JsonPrefStore::WriteCountHistogram::WriteCountHistogram(
+    const base::TimeDelta& commit_interval,
+    const base::FilePath& path)
+    : WriteCountHistogram(commit_interval,
+                          path,
+                          scoped_ptr<base::Clock>(new base::DefaultClock)) {
+}
+
+JsonPrefStore::WriteCountHistogram::WriteCountHistogram(
+    const base::TimeDelta& commit_interval,
+    const base::FilePath& path,
+    scoped_ptr<base::Clock> clock)
+    : commit_interval_(commit_interval),
+      path_(path),
+      clock_(clock.release()),
+      report_interval_(
+          base::TimeDelta::FromMinutes(kHistogramWriteReportIntervalMins)),
+      last_report_time_(clock_->Now()),
+      writes_since_last_report_(0) {
+}
+
+JsonPrefStore::WriteCountHistogram::~WriteCountHistogram() {
+  ReportOutstandingWrites();
+}
+
+void JsonPrefStore::WriteCountHistogram::RecordWriteOccured() {
+  ReportOutstandingWrites();
+
+  ++writes_since_last_report_;
+}
+
+void JsonPrefStore::WriteCountHistogram::ReportOutstandingWrites() {
+  base::Time current_time = clock_->Now();
+  base::TimeDelta time_since_last_report = current_time - last_report_time_;
+  base::HistogramBase* histogram = GetHistogram();
+
+  // If the time since the last report exceeds the report interval, we report
+  // all of the fully elapsed intervals up to the current time.
+  while (time_since_last_report > report_interval_) {
+    histogram->Add(writes_since_last_report_);
+
+    writes_since_last_report_ = 0;
+    last_report_time_ += report_interval_;
+    time_since_last_report = current_time - last_report_time_;

[Alexei Svitkine (slow), 2015/04/27 20:21:20]

This logic is hard to follow.

I think the effect is that it logs |writes_since_last_report_| once for the
current interval and then records 0 a bunch of extra times corresponding to how
many extra intervals elapsed.

If that's the effect, how about expressing that logic differently so that it's
easier to understand that that's what's going on (otherwise it's very difficult
- it took me maybe 5 minutes to work this through with the current loop), maybe
something like:

if (time_since_last_report <= report_interval_)
  return;
histogram->Add(writes_since_last_report_);
int num_additional_intervals_elapsed = /* calculation */;
for (int i = 0; i < num_additional_intervals_elapsed; i++)
  histogram->Add(0);
writes_since_last_report_ = 0;
last_report_time_ = /* ... */;

[raymes, 2015/04/28 00:32:57]

Done.

+  }
+}
+
+base::HistogramBase* JsonPrefStore::WriteCountHistogram::GetHistogram() {
+  std::string spaceless_basename;
+  base::ReplaceChars(path_.BaseName().MaybeAsASCII(), " ", "_",
+                     &spaceless_basename);
+  std::string histogram_name =
+      "Settings.JsonDataWriteCount." + spaceless_basename;
+
+  // The min value for a histogram is 1. The max value is the maximum number of
+  // writes that can occur in the window being recorded. The number of buckets
+  // used is the max value (plus the underflow/overflow buckets).
+  int32_t min_value = 1;
+  int32_t max_value = report_interval_ / commit_interval_;

[Alexei Svitkine (slow), 2015/04/27 20:21:20]

Add a DCHECK() that report_interval_ > commit_interval_?

[raymes, 2015/04/28 00:32:57]

I decided to do something more safe. I DCHECKed the exact values of max_value
and num_buckets to ensure that if they change, someone will update the
histogram. Most histograms hard code these values so I think it's ok and
provides a good tradeoff: it still expresses how we arrived at those numbers in
the code and the DCHECKs provide safety.

+  int32_t num_buckets = max_value + 1;
+
+  // The histogram below is an expansion of the UMA_HISTOGRAM_CUSTOM_COUNTS
+  // macro adapted to allow for a dynamically suffixed histogram name.
+  // Note: The factory creates and owns the histogram.
+  base::HistogramBase* histogram = base::Histogram::FactoryGet(
+      histogram_name, min_value, max_value, num_buckets,
+      base::HistogramBase::kUmaTargetedHistogramFlag);
+  return histogram;
+}