Record metrics on time to serialize important files

To investigate crbug.com/1132866 this CL introduces a metric on how much
time is spent on serializing the preferences into a string. This time is
critical as it happens on the UI sequence.

Bug: 1132866
Change-Id: Ib514f45b55cdc0d04feec2251d1ae2a2d7e117b0
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2562184Reviewed-by: Gabriel Charette <gab@chromium.org>
Reviewed-by: Brian White <bcwhite@chromium.org>
Commit-Queue: Dominic Battré <battre@chromium.org>
Cr-Commit-Position: refs/heads/master@{#833004}

base/files/important_file_writer.cc

@@ -76,6 +76,19 @@ void UmaHistogramExactLinearWithSuffix(const char* histogram_name,
                           static_cast<int>(max_sample));
 }
 
+void UmaHistogramTimesWithSuffix(const char* histogram_name,
+                                 StringPiece histogram_suffix,
+                                 base::TimeDelta sample) {
+  DCHECK(histogram_name);
+  std::string histogram_full_name(histogram_name);
+  if (!histogram_suffix.empty()) {
+    histogram_full_name.append(".");
+    histogram_full_name.append(histogram_suffix.data(),
+                               histogram_suffix.length());
+  }
+  UmaHistogramTimes(histogram_full_name, sample);
+}
+
 void LogFailure(const FilePath& path,
                 StringPiece histogram_suffix,
                 TempFileFailure failure_code,
@@ -298,7 +311,7 @@ bool ImportantFileWriter::WriteFileAtomicallyImpl(const FilePath& path,
 ImportantFileWriter::ImportantFileWriter(
     const FilePath& path,
     scoped_refptr<SequencedTaskRunner> task_runner,
-    const char* histogram_suffix)
+    StringPiece histogram_suffix)
     : ImportantFileWriter(path,
                           std::move(task_runner),
                           kDefaultCommitInterval,
@@ -308,12 +321,12 @@ ImportantFileWriter::ImportantFileWriter(
     const FilePath& path,
     scoped_refptr<SequencedTaskRunner> task_runner,
     TimeDelta interval,
-    const char* histogram_suffix)
+    StringPiece histogram_suffix)
     : path_(path),
       task_runner_(std::move(task_runner)),
       serializer_(nullptr),
       commit_interval_(interval),
-      histogram_suffix_(histogram_suffix ? histogram_suffix : "") {
+      histogram_suffix_(histogram_suffix) {
   DCHECK(task_runner_);
   ImportantFileWriterCleaner::AddDirectory(path.DirName());
 }
@@ -378,7 +391,13 @@ void ImportantFileWriter::DoScheduledWrite() {
   // from tiny to very large.
   data->reserve(previous_data_size_ + 1024);
 
-  if (serializer_->SerializeData(data.get())) {
+  const TimeTicks serialization_start = TimeTicks::Now();
+  const bool success = serializer_->SerializeData(data.get());
+  const TimeDelta serialization_duration =
+      TimeTicks::Now() - serialization_start;
+  if (success) {
+    UmaHistogramTimesWithSuffix("ImportantFile.SerializationDuration",
+                                histogram_suffix_, serialization_duration);
     previous_data_size_ = data->size();
     WriteNow(std::move(data));
   } else {

base/files/important_file_writer.h

@@ -65,13 +65,13 @@ class BASE_EXPORT ImportantFileWriter {
   // All non-const methods, ctor and dtor must be called on the same thread.
   ImportantFileWriter(const FilePath& path,
                       scoped_refptr<SequencedTaskRunner> task_runner,
-                      const char* histogram_suffix = nullptr);
+                      StringPiece histogram_suffix = StringPiece());
 
   // Same as above, but with a custom commit interval.
   ImportantFileWriter(const FilePath& path,
                       scoped_refptr<SequencedTaskRunner> task_runner,
                       TimeDelta interval,
-                      const char* histogram_suffix = nullptr);
+                      StringPiece histogram_suffix = StringPiece());
 
   // You have to ensure that there are no pending writes at the moment
   // of destruction.

base/files/important_file_writer_unittest.cc

@@ -314,6 +314,7 @@ TEST_F(ImportantFileWriterTest, ScheduleWrite_WriteNow) {
 }
 
 TEST_F(ImportantFileWriterTest, DoScheduledWrite_FailToSerialize) {
+  base::HistogramTester histogram_tester;
   MockOneShotTimer timer;
   ImportantFileWriter writer(file_, ThreadTaskRunnerHandle::Get());
   writer.SetTimerForTesting(&timer);
@@ -327,6 +328,8 @@ TEST_F(ImportantFileWriterTest, DoScheduledWrite_FailToSerialize) {
   EXPECT_FALSE(writer.HasPendingWrite());
   RunLoop().RunUntilIdle();
   EXPECT_FALSE(PathExists(writer.path()));
+  // We don't record metrics in case the serialization fails.
+  histogram_tester.ExpectTotalCount("ImportantFile.SerializationDuration", 0);
 }
 
 TEST_F(ImportantFileWriterTest, WriteFileAtomicallyHistogramSuffixTest) {
@@ -360,4 +363,28 @@ TEST_F(ImportantFileWriterTest, WriteLargeFile) {
   EXPECT_EQ(large_data, actual);
 }
 
+// Verify that a UMA metric for the serialization duration is recorded.
+TEST_F(ImportantFileWriterTest, SerializationDuration) {
+  base::HistogramTester histogram_tester;
+  ImportantFileWriter writer(file_, ThreadTaskRunnerHandle::Get());
+  DataSerializer serializer("foo");
+  writer.ScheduleWrite(&serializer);
+  writer.DoScheduledWrite();
+  RunLoop().RunUntilIdle();
+  histogram_tester.ExpectTotalCount("ImportantFile.SerializationDuration", 1);
+}
+
+// Verify that a UMA metric for the serialization duration is recorded if the
+// ImportantFileWriter has a custom histogram suffix.
+TEST_F(ImportantFileWriterTest, SerializationDurationWithCustomSuffix) {
+  base::HistogramTester histogram_tester;
+  ImportantFileWriter writer(file_, ThreadTaskRunnerHandle::Get(), "Foo");
+  DataSerializer serializer("foo");
+  writer.ScheduleWrite(&serializer);
+  writer.DoScheduledWrite();
+  RunLoop().RunUntilIdle();
+  histogram_tester.ExpectTotalCount("ImportantFile.SerializationDuration.Foo",
+                                    1);
+}
+
 }  // namespace base

components/prefs/json_pref_store.cc

@@ -20,6 +20,7 @@
 #include "base/macros.h"
 #include "base/memory/ref_counted.h"
 #include "base/metrics/histogram.h"
+#include "base/ranges/algorithm.h"
 #include "base/sequenced_task_runner.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
@@ -131,6 +132,17 @@ std::unique_ptr<JsonPrefStore::ReadResult> ReadPrefsFromDisk(
   return read_result;
 }
 
+// Returns the a histogram suffix for a few allowlisted JsonPref files.
+const char* GetHistogramSuffix(const base::FilePath& path) {
+  std::string spaceless_basename;
+  base::ReplaceChars(path.BaseName().MaybeAsASCII(), " ", "_",
+                     &spaceless_basename);
+  static constexpr std::array<const char*, 3> kAllowList{
+      "Secure_Preferences", "Preferences", "Local_State"};
+  const char* const* it = base::ranges::find(kAllowList, spaceless_basename);
+  return it != kAllowList.end() ? *it : "";
+}
+
 }  // namespace
 
 JsonPrefStore::JsonPrefStore(
@@ -141,7 +153,9 @@ JsonPrefStore::JsonPrefStore(
       file_task_runner_(std::move(file_task_runner)),
       prefs_(new base::DictionaryValue()),
       read_only_(false),
-      writer_(pref_filename, file_task_runner_),
+      writer_(pref_filename,
+              file_task_runner_,
+              GetHistogramSuffix(pref_filename)),
       pref_filter_(std::move(pref_filter)),
       initialized_(false),
       filtering_in_progress_(false),

tools/metrics/histograms/histograms_xml/histogram_suffixes_list.xml

@@ -7517,6 +7517,9 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
 <histogram_suffixes name="ImportantFileWriterSuffix" separator=".">
   <suffix name="BookmarkStorage" label=""/>
   <suffix name="FeedbackReport" label=""/>
+  <suffix name="Local_State" label="Local State file"/>
+  <suffix name="Preferences" label="Preferences file"/>
+  <suffix name="Secure_Preferences" label="Secure Preferences file"/>
   <affected-histogram name="ImportantFile.DeleteOnCloseError"/>
   <affected-histogram name="ImportantFile.FileCreateError"/>
   <affected-histogram name="ImportantFile.FileDeleteError"/>
@@ -7526,6 +7529,7 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   <affected-histogram name="ImportantFile.FileOpenError"/>
   <affected-histogram name="ImportantFile.FileRenameError"/>
   <affected-histogram name="ImportantFile.FileWriteError"/>
+  <affected-histogram name="ImportantFile.SerializationDuration"/>
   <affected-histogram name="ImportantFile.TempFileFailures"/>
   <affected-histogram name="ImportantFile.TimeToWrite"/>
 </histogram_suffixes>

tools/metrics/histograms/histograms_xml/others/histograms.xml

@@ -6774,6 +6774,13 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="ImportantFile.SerializationDuration" units="ms"
+    expires_after="M92">
+  <owner>battre@chromium.org</owner>
+  <owner>gab@chromium.org</owner>
+  <summary>CPU time used to serialize preferences into a JSON string.</summary>
+</histogram>
+
 <histogram name="ImportantFile.TempFileFailures" enum="TempFileFailure"
     expires_after="2021-03-21">
   <owner>grt@chromium.org</owner>