[parkable_image] Add metrics for read/write to disk for ParkableImage.

This is a follow-up to https://chromium-review.googlesource.com/c/chromium/src/+/2628026,
which added logic for reading/writing ParkableImages to disk.

Bug: 1154976
Change-Id: Ie1fac8246538bec235f517c5537023b4efd34ac1
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2693316
Reviewed-by: Jesse Doherty <jwd@chromium.org>
Reviewed-by: Benoit L <lizeb@chromium.org>
Reviewed-by: Kentaro Hara <haraken@chromium.org>
Commit-Queue: Thiabaud Engelbrecht <thiabaud@google.com>
Cr-Commit-Position: refs/heads/master@{#857318}

third_party/blink/renderer/platform/graphics/parkable_image.cc

@@ -6,6 +6,9 @@
 
 #include "base/debug/stack_trace.h"
 #include "base/memory/ref_counted.h"
+#include "base/metrics/histogram_functions.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/timer/elapsed_timer.h"
 #include "base/trace_event/trace_event.h"
 #include "third_party/blink/renderer/platform/graphics/parkable_image_manager.h"
 #include "third_party/blink/renderer/platform/image-decoders/segment_reader.h"
@@ -17,6 +20,46 @@
 
 namespace blink {
 
+namespace {
+
+void RecordReadStatistics(size_t size, base::TimeDelta duration) {
+  size_t throughput_mb_s =
+      static_cast<size_t>(size / duration.InSecondsF()) / (1024 * 1024);
+  size_t size_kb = size / 1024;  // in KiB
+
+  // Size should be <1MiB in most cases.
+  base::UmaHistogramCounts10000("Memory.ParkableImage.Read.Size", size_kb);
+  // Size is usually >1KiB, and at most ~10MiB, and throughput ranges from
+  // single-digit MB/s to ~1000MiB/s depending on the CPU/disk, hence the
+  // ranges.
+  base::UmaHistogramCustomMicrosecondsTimes(
+      "Memory.ParkableImage.Read.Latency", duration,
+      base::TimeDelta::FromMicroseconds(500), base::TimeDelta::FromSeconds(1),
+      100);
+  base::UmaHistogramCounts1000("Memory.ParkableImage.Read.Throughput",
+                               throughput_mb_s);
+}
+
+void RecordWriteStatistics(size_t size, base::TimeDelta duration) {
+  size_t throughput_mb_s =
+      static_cast<size_t>(size / duration.InSecondsF()) / (1024 * 1024);
+  size_t size_kb = size / 1024;
+
+  // Size should be <1MiB in most cases.
+  base::UmaHistogramCounts10000("Memory.ParkableImage.Write.Size", size_kb);
+  // Size is usually >1KiB, and at most ~10MiB, and throughput ranges from
+  // single-digit MB/s to ~1000MiB/s depending on the CPU/disk, hence the
+  // ranges.
+  base::UmaHistogramCustomMicrosecondsTimes(
+      "Memory.ParkableImage.Write.Latency", duration,
+      base::TimeDelta::FromMicroseconds(500), base::TimeDelta::FromSeconds(1),
+      100);
+  base::UmaHistogramCounts1000("Memory.ParkableImage.Write.Throughput",
+                               throughput_mb_s);
+}
+
+}  // namespace
+
 void ParkableImage::Append(WTF::SharedBuffer* buffer, size_t offset) {
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
   MutexLocker lock(lock_);
@@ -117,8 +160,10 @@ void ParkableImage::WriteToDiskInBackground(
   // Release the lock while writing, so we don't block for too long.
   parkable_image->lock_.unlock();
 
+  base::ElapsedTimer timer;
   auto metadata = ParkableImageManager::Instance().data_allocator().Write(
       vector.data(), vector.size());
+  base::TimeDelta elapsed = timer.Elapsed();
 
   // Acquire the lock again after writing.
   parkable_image->lock_.lock();
@@ -130,6 +175,8 @@ void ParkableImage::WriteToDiskInBackground(
   if (!parkable_image->on_disk_metadata_) {
     parkable_image->background_task_in_progress_ = false;
   } else {
+    RecordWriteStatistics(parkable_image->on_disk_metadata_->size(), elapsed);
+    ParkableImageManager::Instance().RecordDiskWriteTime(elapsed);
     PostCrossThreadTask(*callback_task_runner, FROM_HERE,
                         CrossThreadBindOnce(&ParkableImage::MaybeDiscardData,
                                             std::move(parkable_image)));
@@ -198,8 +245,14 @@ void ParkableImage::Unpark() {
 
   DCHECK(on_disk_metadata_);
   WTF::Vector<uint8_t> vector(size());
+
+  base::ElapsedTimer timer;
   ParkableImageManager::Instance().data_allocator().Read(*on_disk_metadata_,
                                                          vector.data());
+  base::TimeDelta elapsed = timer.Elapsed();
+
+  RecordReadStatistics(on_disk_metadata_->size(), elapsed);
+  ParkableImageManager::Instance().RecordDiskReadTime(elapsed);
 
   ParkableImageManager::Instance().OnReadFromDisk(this);
 

third_party/blink/renderer/platform/graphics/parkable_image_manager.cc

@@ -83,6 +83,8 @@ void ParkableImageManager::ResetForTesting() {
   unparked_images_.clear();
   on_disk_images_.clear();
   allocator_for_testing_ = nullptr;
+  total_disk_read_time_ = base::TimeDelta();
+  total_disk_write_time_ = base::TimeDelta();
 }
 
 void ParkableImageManager::Add(ParkableImage* image) {
@@ -116,7 +118,25 @@ void ParkableImageManager::RecordStatisticsAfter5Minutes() const {
   Statistics stats = ComputeStatistics();
 
   base::UmaHistogramCounts100000("Memory.ParkableImage.TotalSize.5min",
-                                 stats.total_size / 1024);  // Record in KiB.
+                                 stats.total_size / 1024);  // in KiB
+  base::UmaHistogramCounts100000("Memory.ParkableImage.OnDiskSize.5min",
+                                 stats.on_disk_size / 1024);  // in KiB
+  base::UmaHistogramCounts100000("Memory.ParkableImage.UnparkedSize.5min",
+                                 stats.unparked_size / 1024);  // in KiB
+
+  // Metrics related to parking only should be recorded if the feature is
+  // enabled.
+  if (IsParkableImagesToDiskEnabled()) {
+    base::UmaHistogramBoolean("Memory.ParkableImage.DiskIsUsable.5min",
+                              data_allocator().may_write());
+    // These metrics only make sense if the disk allocator is used.
+    if (data_allocator().may_write()) {
+      base::UmaHistogramTimes("Memory.ParkableImage.TotalWriteTime.5min",
+                              total_disk_write_time_);
+      base::UmaHistogramTimes("Memory.ParkableImage.TotalReadTime.5min",
+                              total_disk_read_time_);
+    }
+  }
 }
 
 void ParkableImageManager::Remove(ParkableImage* image) {

third_party/blink/renderer/platform/graphics/parkable_image_manager.h

@@ -64,6 +64,16 @@ class PLATFORM_EXPORT ParkableImageManager
                  WTF::HashSet<ParkableImage*>* to)
       EXCLUSIVE_LOCKS_REQUIRED(lock_);
 
+  void RecordDiskWriteTime(base::TimeDelta write_time) LOCKS_EXCLUDED(lock_) {
+    MutexLocker lock(lock_);
+    total_disk_write_time_ += write_time;
+  }
+
+  void RecordDiskReadTime(base::TimeDelta read_time) LOCKS_EXCLUDED(lock_) {
+    MutexLocker lock(lock_);
+    total_disk_read_time_ += read_time;
+  }
+
   // Keeps track of whether the image is unparked or on disk. ParkableImage
   // should call these when written to or read from disk.
   void OnWrittenToDisk(ParkableImage* image) LOCKS_EXCLUDED(lock_);
@@ -101,6 +111,9 @@ class PLATFORM_EXPORT ParkableImageManager
   bool has_pending_parking_task_ GUARDED_BY(lock_) = false;
   bool has_posted_accounting_task_ = false;
 
+  base::TimeDelta total_disk_read_time_ GUARDED_BY(lock_) = base::TimeDelta();
+  base::TimeDelta total_disk_write_time_ GUARDED_BY(lock_) = base::TimeDelta();
+
   std::unique_ptr<DiskDataAllocator> allocator_for_testing_;
 };
 

third_party/blink/renderer/platform/graphics/parkable_image_test.cc

@@ -3,6 +3,7 @@
 // found in the LICENSE file.
 
 #include "third_party/blink/renderer/platform/graphics/parkable_image.h"
+#include "base/test/metrics/histogram_tester.h"
 #include "base/test/scoped_feature_list.h"
 #include "base/test/task_environment.h"
 #include "testing/gtest/include/gtest/gtest.h"
@@ -41,6 +42,12 @@ class ParkableImageBaseTest : public ::testing::Test {
     task_env_.FastForwardBy(ParkableImageManager::kDelayedParkingInterval);
   }
 
+  // To aid in testing that the "Memory.ParkableImage.*.5min" metrics are
+  // correctly recorded.
+  void Wait5MinForStatistics() {
+    task_env_.FastForwardBy(base::TimeDelta::FromMinutes(5));
+  }
+
   void DescribeCurrentTasks() { task_env_.DescribeCurrentTasks(); }
 
   void RunPostedTasks() { task_env_.RunUntilIdle(); }
@@ -92,6 +99,42 @@ class ParkableImageBaseTest : public ::testing::Test {
     return true;
   }
 
+  // This checks that the "Memory.ParkableImage.Write.*" statistics from
+  // |RecordReadStatistics()| are recorded correctly, namely
+  // "Memory.ParkableImage.Write.Latency",
+  // "Memory.ParkableImage.Write.Throughput", and
+  // "Memory.ParkableImage.Write.Size".
+  //
+  // Checks the counts for all 3 metrics, but only checks the value for
+  // "Memory.ParkableImage.Write.Size", since the others can't be easily tested.
+  void ExpectWriteStatistics(base::HistogramBase::Sample sample,
+                             base::HistogramBase::Count expected_count) {
+    histogram_tester_.ExpectTotalCount("Memory.ParkableImage.Write.Latency",
+                                       expected_count);
+    histogram_tester_.ExpectTotalCount("Memory.ParkableImage.Write.Throughput",
+                                       expected_count);
+    histogram_tester_.ExpectBucketCount("Memory.ParkableImage.Write.Size",
+                                        sample, expected_count);
+  }
+
+  // This checks that the "Memory.ParkableImage.Read.*" statistics from
+  // |RecordReadStatistics()| are recorded correctly, namely
+  // "Memory.ParkableImage.Read.Latency",
+  // "Memory.ParkableImage.Read.Throughput", and
+  // "Memory.ParkableImage.Read.Size".
+  //
+  // Checks the counts for all 3 metrics, but only checks the value for
+  // "Memory.ParkableImage.Read.Size", since the others can't be easily tested.
+  void ExpectReadStatistics(base::HistogramBase::Sample sample,
+                            base::HistogramBase::Count expected_count) {
+    histogram_tester_.ExpectTotalCount("Memory.ParkableImage.Read.Latency",
+                                       expected_count);
+    histogram_tester_.ExpectTotalCount("Memory.ParkableImage.Read.Throughput",
+                                       expected_count);
+  }
+
+  base::HistogramTester histogram_tester_;
+
  private:
   base::test::TaskEnvironment task_env_;
 };
@@ -218,6 +261,9 @@ TEST_F(ParkableImageTest, ParkAndUnpark) {
 
   // Make sure content is the same after unparking.
   EXPECT_TRUE(IsSameContent(pi, data, kDataSize));
+
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 1);
 }
 
 // Tests that trying to park multiple times doesn't add any extra tasks.
@@ -254,6 +300,9 @@ TEST_F(ParkableImageTest, ParkTwiceAndUnpark) {
 
   // Make sure content is the same after unparking.
   EXPECT_TRUE(IsSameContent(pi, data, kDataSize));
+
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 1);
 }
 
 // Tests that we can park to disk synchronously after the data is stored on
@@ -294,6 +343,9 @@ TEST_F(ParkableImageTest, ParkAndUnparkSync) {
 
   Unpark(pi);
 
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 1);
+
   // Unparking blocks until it is read from disk, so we expect it to no longer
   // be on disk after unparking.
   EXPECT_FALSE(is_on_disk(pi));
@@ -316,6 +368,12 @@ TEST_F(ParkableImageTest, ParkAndUnparkSync) {
 
   // Make sure content is the same after unparking.
   EXPECT_TRUE(IsSameContent(pi, data, kDataSize));
+
+  // One extra read than write. We discard the data twice, but we only need to
+  // write to disk once. Because we've discarded it twice, we need to do two
+  // reads.
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 2);
 }
 
 // Tests that creating a snapshot partway through writing correctly aborts
@@ -357,6 +415,14 @@ TEST_F(ParkableImageTest, ParkAndUnparkAborted) {
   // Make sure content is the same.
   EXPECT_TRUE(IsSameContent(pi, data, kDataSize));
 
+  // We still expect a write to be done in this case, since the only thing
+  // preventing it from being parked is the snapshot. However, the data is not
+  // discarded here, since we need for the snapshot.
+  //
+  // Since the data was never discarded, we expect 0 reads however.
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 0);
+
   // Since we have a snapshot alive, we can't park.
   EXPECT_FALSE(MaybePark(pi));
 
@@ -378,6 +444,9 @@ TEST_F(ParkableImageTest, ParkAndUnparkAborted) {
 
   // Make sure content is the same.
   EXPECT_TRUE(IsSameContent(pi, data, kDataSize));
+
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 1);
 }
 
 // Tests that a frozen image will be written to disk by the manager.
@@ -412,6 +481,9 @@ TEST_F(ParkableImageTest, ManagerSimple) {
   // Even though we unparked earlier, a new delayed parking task should park the
   // image still.
   EXPECT_TRUE(is_on_disk(pi));
+
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 1);
 }
 
 // Tests that the manager can correctly handle multiple parking tasks being
@@ -447,6 +519,9 @@ TEST_F(ParkableImageTest, ManagerTwo) {
   // Even though we unparked earlier, a new delayed parking task should park the
   // image still.
   EXPECT_TRUE(is_on_disk(pi));
+
+  ExpectWriteStatistics(kDataSize / 1024, 1);
+  ExpectReadStatistics(kDataSize / 1024, 1);
 }
 
 // Test that a non-frozen image will not be written to disk.
@@ -471,6 +546,11 @@ TEST_F(ParkableImageTest, ManagerNonFrozen) {
 
   // Can't park because it is not frozen.
   EXPECT_FALSE(is_on_disk(pi));
+
+  // No read or write was done, so we expect no metrics to be recorded for
+  // reading/writing.
+  ExpectWriteStatistics(0, 0);
+  ExpectReadStatistics(0, 0);
 }
 
 // Check that trying to unpark a ParkableImage when parking is disabled has no
@@ -490,6 +570,67 @@ TEST_F(ParkableImageNoParkingTest, Unpark) {
   Unpark(pi);
 
   EXPECT_TRUE(IsSameContent(pi, data, kDataSize));
+
+  // No data should be written or read when parking is disabled.
+  ExpectWriteStatistics(kDataSize / 1024, 0);
+  ExpectReadStatistics(kDataSize / 1024, 0);
+}
+
+// Tests that the ParkableImageManager is correctly recording statistics after 5
+// minutes.
+TEST_F(ParkableImageTest, ManagerStatistics5min) {
+  const size_t kDataSize = 3.5 * 4096;
+  char data[kDataSize];
+  PrepareReferenceData(data, kDataSize);
+
+  auto pi = MakeParkableImageForTesting(data, kDataSize);
+  pi->Freeze();
+
+  Wait5MinForStatistics();
+
+  // We expect "Memory.ParkableImage.OnDiskFootprintKb.5min" not to be emitted,
+  // since we've mocked the DiskDataAllocator for testing (and therefore cannot
+  // actually write to disk).
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.DiskIsUsable.5min",
+                                     1);
+  histogram_tester_.ExpectTotalCount(
+      "Memory.ParkableImage.OnDiskFootprintKb.5min", 0);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.OnDiskSize.5min", 1);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.TotalReadTime.5min",
+                                     1);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.TotalSize.5min", 1);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.TotalWriteTime.5min",
+                                     1);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.UnparkedSize.5min",
+                                     1);
+}
+
+// Tests that the ParkableImageManager is correctly recording statistics after 5
+// minutes, even when parking is disabled. Only bookkeeping metrics should be
+// recorded in this case, since no reads/writes will happen.
+TEST_F(ParkableImageNoParkingTest, ManagerStatistics5min) {
+  const size_t kDataSize = 3.5 * 4096;
+  char data[kDataSize];
+  PrepareReferenceData(data, kDataSize);
+
+  auto pi = MakeParkableImageForTesting(data, kDataSize);
+  pi->Freeze();
+
+  Wait5MinForStatistics();
+
+  // Note that we expect 0 counts of some of these metrics.
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.DiskIsUsable.5min",
+                                     0);
+  histogram_tester_.ExpectTotalCount(
+      "Memory.ParkableImage.OnDiskFootprintKb.5min", 0);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.OnDiskSize.5min", 1);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.TotalReadTime.5min",
+                                     0);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.TotalSize.5min", 1);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.TotalWriteTime.5min",
+                                     0);
+  histogram_tester_.ExpectTotalCount("Memory.ParkableImage.UnparkedSize.5min",
+                                     1);
 }
 
 // Tests that the manager doesn't try to park any images when parking is
@@ -518,6 +659,10 @@ TEST_F(ParkableImageNoParkingTest, ManagerSimple) {
   EXPECT_FALSE(is_on_disk(pi));
 
   EXPECT_TRUE(IsSameContent(pi, data, kDataSize));
+
+  // No data should be written or read when parking is disabled.
+  ExpectWriteStatistics(kDataSize / 1024, 0);
+  ExpectReadStatistics(kDataSize / 1024, 0);
 }
 
 }  // namespace blink