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/values.h"
 
 // Result returned from internal read tasks.
 struct JsonPrefStore::ReadResult {
  public:
   ReadResult();
   ~ReadResult();
 
   scoped_ptr<base::Value> value;
   PrefReadError error;
   bool no_dir;
 
  private:
   DISALLOW_COPY_AND_ASSIGN(ReadResult);
 };
 
 JsonPrefStore::ReadResult::ReadResult()
     : error(PersistentPrefStore::PREF_READ_ERROR_NONE), no_dir(false) {
 }
 
 JsonPrefStore::ReadResult::~ReadResult() {
 }
 
+// Represents a histogram which records the number of writes of the pref file
+// that occured in a given time period.
+class JsonPrefStore::WriteCountHistogram {
+ public:
+  WriteCountHistogram(
+      const base::TimeDelta& start_delay,
+      const base::TimeDelta& stop_delay,
+      const base::TimeDelta& commit_interval,
+      const base::FilePath& path,
+      const scoped_refptr<base::SequencedTaskRunner> sequenced_task_runner);

[Mattias Nissler (ping if slow), 2015/04/14 11:58:27]

Would be good to give this a name that makes it clear what it's used for (also
the member).

+  ~WriteCountHistogram();
+  void RecordWriteOccured();
+
+ private:
+  void SendMetric();
+
+  // The time at which this object was constructed
+  base::Time creation_time_;
+
+  // The delay (after creation) before starting to record writes.
+  base::TimeDelta start_delay_;
+
+  // The delay (after creation) at which to stop recording writes.
+  base::TimeDelta stop_delay_;
+
+  // The minimum delay between writes of the pref file.
+  base::TimeDelta commit_interval_;
+
+  // The path to the pref file.
+  base::FilePath path_;
+
+  scoped_refptr<base::SequencedTaskRunner> sequenced_task_runner_;
+
+  // The total number of writes of the pref file in the interval recorded by
+  // this object.
+  uint32_t write_count_;

[Mattias Nissler (ping if slow), 2015/04/14 11:58:27]

Why not a plain int?

+
+  base::WeakPtrFactory<JsonPrefStore::WriteCountHistogram> weak_factory_;
+
+  DISALLOW_COPY_AND_ASSIGN(WriteCountHistogram);
+};
+
 namespace {
 
 // Some extensions we'll tack on to copies of the Preferences files.
 const base::FilePath::CharType kBadExtension[] = FILE_PATH_LITERAL("bad");
 
+struct WriteCountHistogramInfo {
+  // The delay in minutes after startup at which to start recording write count
+  // data for this particular histogram.
+  int64_t start_delay;

[Mattias Nissler (ping if slow), 2015/04/14 11:58:27]

might want to call this start_delay_minutes for clarity?

+
+  // The delay in minutes after startup at which to stop recording write count
+  // data for this particular histogram.
+  int64_t stop_delay;
+};

[Mattias Nissler (ping if slow), 2015/04/14 11:58:27]

Could make this an unnamed struct. If you don't, put a blank line here.

+const WriteCountHistogramInfo kWriteCountHistograms[] = {
+  { 0, 1 },    // The first minute of writes.
+  { 1, 5 },    // The 2nd-5th minutes of writes.
+  { 5, 15 },   // The 6th-15th minutes of writes.
+  { 15, 60 },  // The 16th-60th minutes of writes.
+};
+
 PersistentPrefStore::PrefReadError HandleReadErrors(
     const base::Value* value,
     const base::FilePath& path,
     int error_code,
     const std::string& error_msg) {
   if (!value) {
     DVLOG(1) << "Error while loading JSON file: " << error_msg
              << ", file: " << path.value();
     switch (error_code) {
       case JSONFileValueDeserializer::JSON_ACCESS_DENIED:
@@ skipping 91 matching lines @@
     : 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) {
   DCHECK(!path_.empty());
+
+  for (size_t i = 0; i < sizeof(kWriteCountHistograms); ++i) {
+    write_count_histograms_.push_back(new WriteCountHistogram(
+      base::TimeDelta::FromMinutes(kWriteCountHistograms[i].start_delay),
+      base::TimeDelta::FromMinutes(kWriteCountHistograms[i].stop_delay),
+      writer_.commit_interval(),
+      path_,
+      sequenced_task_runner.get()));
+  }
 }
 
 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),
@@ skipping 216 matching lines @@
   }
 }
 
 JsonPrefStore::~JsonPrefStore() {
   CommitPendingWrite();
 }
 
 bool JsonPrefStore::SerializeData(std::string* output) {
   DCHECK(CalledOnValidThread());
 
+  for (WriteCountHistogram* histogram : write_count_histograms_)
+    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;
 }
+
+JsonPrefStore::WriteCountHistogram::WriteCountHistogram(
+    const base::TimeDelta& start_delay,
+    const base::TimeDelta& stop_delay,
+    const base::TimeDelta& commit_interval,
+    const base::FilePath& path,
+    const scoped_refptr<base::SequencedTaskRunner> sequenced_task_runner)
+    : creation_time_(base::Time::Now()),
+      start_delay_(start_delay),
+      stop_delay_(stop_delay),
+      commit_interval_(commit_interval),
+      path_(path),
+      sequenced_task_runner_(sequenced_task_runner),
+      write_count_(0),
+      weak_factory_(this) {
+  sequenced_task_runner_->PostDelayedTask(FROM_HERE, base::Bind(
+      &JsonPrefStore::WriteCountHistogram::SendMetric,
+      weak_factory_.GetWeakPtr()), stop_delay_);
+}
+
+JsonPrefStore::WriteCountHistogram::~WriteCountHistogram() {}
+
+void JsonPrefStore::WriteCountHistogram::RecordWriteOccured() {
+  base::Time current_time = base::Time::Now();
+  base::Time time_to_start = creation_time_ + start_delay_;
+  base::Time time_to_stop = creation_time_ + stop_delay_;
+  if (current_time >= time_to_start && current_time < time_to_stop)
+    ++write_count_;

[Alexei Svitkine (slow), 2015/04/15 16:41:23]

Can you add a DCHECK to ensure this doesn't get hit after SendMetric is hit?

Or perhaps you can make it so that this method is responsible for doing the
SendMetric once it gets called after stop_delay_ - then it eliminates the
potential race (i.e. if for some reason delayed task runs before this hits).
Would also simplify things because then you don't need the post task or weak
pointer factory.

[raymes, 2015/04/21 07:22:38]

The design changed so this isn't an issue now.

+}
+
+void JsonPrefStore::WriteCountHistogram::SendMetric() {
+  std::string spaceless_basename;
+  base::ReplaceChars(path_.BaseName().MaybeAsASCII(), " ", "_",
+                     &spaceless_basename);
+
+  std::string histogram_name =
+      "Settings.JsonDataWriteCount." + spaceless_basename + "_" +

[Alexei Svitkine (slow), 2015/04/15 16:41:23]

Please document these histograms in histograms.xml. You can use
histogram_suffixes entries to avoid repeating multiple histogram definitions.

[raymes, 2015/04/21 07:22:38]

Done.

+      base::IntToString(start_delay_.InMinutes()) + "-" +
+      base::IntToString(stop_delay_.InMinutes());
+
+  // 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 max number of
+  // buckets used is 30 (plus the underflow/overflow buckets).
+  int32_t min_value = 1;
+  int32_t max_value = (stop_delay_ - start_delay_) / commit_interval_;

[Mattias Nissler (ping if slow), 2015/04/14 11:58:27]

This calculation doesn't work in the presence of
PrefService::CommitPendingWrite(). Maybe a sparse histogram is a better choice
here?

+  int32_t num_buckets = std::min(max_value, 30) + 2;
+
+  // 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);
+  histogram->Add(write_count_);
+}