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

base/prefs/json_pref_store.cc

 // Copyright (c) 2012 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/prefs/json_pref_store.h"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/callback.h"
 #include "base/files/file_path.h"
 #include "base/files/file_util.h"
 #include "base/json/json_file_value_serializer.h"
 #include "base/json/json_string_value_serializer.h"
 #include "base/memory/ref_counted.h"
 #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.
 struct JsonPrefStore::ReadResult {
  public:
   ReadResult();
   ~ReadResult();
 
   scoped_ptr<base::Value> value;
   PrefReadError error;
@@ skipping 117 matching lines @@
     const scoped_refptr<base::SequencedTaskRunner>& sequenced_task_runner,
     scoped_ptr<PrefFilter> pref_filter)
     : path_(filename),
       sequenced_task_runner_(sequenced_task_runner),
       prefs_(new base::DictionaryValue()),
       read_only_(false),
       writer_(filename, sequenced_task_runner),
       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());
 }
 
 JsonPrefStore::JsonPrefStore(
     const base::FilePath& filename,
     const base::FilePath& alternate_filename,
     const scoped_refptr<base::SequencedTaskRunner>& sequenced_task_runner,
     scoped_ptr<PrefFilter> pref_filter)
     : path_(filename),
       alternate_path_(alternate_filename),
       sequenced_task_runner_(sequenced_task_runner),
       prefs_(new base::DictionaryValue()),
       read_only_(false),
       writer_(filename, sequenced_task_runner),
       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());
 }
 
 bool JsonPrefStore::GetValue(const std::string& key,
                              const base::Value** result) const {
   DCHECK(CalledOnValidThread());
 
   base::Value* tmp = NULL;
   if (!prefs_->Get(key, &tmp))
     return false;
@@ skipping 199 matching lines @@
   }
 }
 
 JsonPrefStore::~JsonPrefStore() {
   CommitPendingWrite();
 }
 
 bool JsonPrefStore::SerializeData(std::string* output) {
   DCHECK(CalledOnValidThread());
 
+  write_count_histogram_.RecordWriteOccured();
+
   if (pref_filter_)
     pref_filter_->FilterSerializeData(prefs_.get());
 
   JSONStringValueSerializer serializer(output);
   // Not pretty-printing prefs shrinks pref file size by ~30%. To obtain
   // readable prefs for debugging purposes, you can dump your prefs into any
   // command-line or online JSON pretty printing tool.
   serializer.set_pretty_print(false);
   return serializer.Serialize(*prefs_);
 }
@@ skipping 21 matching lines @@
 
   if (error_delegate_ && read_error_ != PREF_READ_ERROR_NONE)
     error_delegate_->OnError(read_error_);
 
   FOR_EACH_OBSERVER(PrefStore::Observer,
                     observers_,
                     OnInitializationCompleted(true));
 
   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;
+}