[self_freeze] Add compaction time metric

This CL adds a metric to keep track of how long self-compaction takes.

Bug: 344550156
Change-Id: I4b2b9ba225b646ec587f4c35502e650e969c905f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/6282171
Commit-Queue: Thiabaud Engelbrecht <thiabaud@google.com>
Reviewed-by: Benoit Lize <lizeb@chromium.org>
Cr-Commit-Position: refs/heads/main@{#1425777}

base/android/pre_freeze_background_memory_trimmer.cc

@@ -306,7 +306,7 @@ void PreFreezeBackgroundMemoryTrimmer::CompactionMetric::
     return;
   }
 
-  if (!ShouldContinueSelfCompaction(started_at_)) {
+  if (!ShouldContinueSelfCompaction(self_compaction_triggered_at_)) {
     return;
   }
 
@@ -329,7 +329,7 @@ void PreFreezeBackgroundMemoryTrimmer::CompactionMetric::
 
 void PreFreezeBackgroundMemoryTrimmer::CompactionMetric::RecordSmapsRollup(
     std::optional<debug::SmapsRollup>* target) {
-  if (!ShouldContinueSelfCompaction(started_at_)) {
+  if (!ShouldContinueSelfCompaction(self_compaction_triggered_at_)) {
     return;
   }
 
@@ -470,10 +470,10 @@ bool PreFreezeBackgroundMemoryTrimmer::SelfCompactionIsSupported() {
 
 // static
 bool PreFreezeBackgroundMemoryTrimmer::ShouldContinueSelfCompaction(
-    base::TimeTicks self_compaction_started_at) {
+    base::TimeTicks self_compaction_triggered_at) {
   base::AutoLock locker(lock());
   return Instance().self_compaction_last_cancelled_ <
-         self_compaction_started_at;
+         self_compaction_triggered_at;
 }
 
 void PreFreezeBackgroundMemoryTrimmer::MaybePostSelfCompactionTask(
@@ -481,18 +481,18 @@ void PreFreezeBackgroundMemoryTrimmer::MaybePostSelfCompactionTask(
     std::vector<debug::MappedMemoryRegion> regions,
     scoped_refptr<CompactionMetric> metric,
     uint64_t max_size,
-    base::TimeTicks started_at) {
+    base::TimeTicks triggered_at) {
   TRACE_EVENT0("base", "MaybePostSelfCompactionTask");
-  if (ShouldContinueSelfCompaction(started_at) && !regions.empty()) {
+  if (ShouldContinueSelfCompaction(triggered_at) && !regions.empty()) {
     task_runner->PostDelayedTask(
         FROM_HERE,
         // |base::Unretained| is safe here because we never destroy |this|.
         base::BindOnce(&PreFreezeBackgroundMemoryTrimmer::SelfCompactionTask,
                        base::Unretained(this), task_runner, std::move(regions),
-                       std::move(metric), max_size, started_at),
+                       std::move(metric), max_size, triggered_at),
         GetDelayBetweenSelfCompaction());
   } else {
-    FinishSelfCompaction(std::move(metric), started_at);
+    FinishSelfCompaction(std::move(metric), triggered_at);
   }
 }
 
@@ -501,8 +501,8 @@ void PreFreezeBackgroundMemoryTrimmer::SelfCompactionTask(
     std::vector<debug::MappedMemoryRegion> regions,
     scoped_refptr<CompactionMetric> metric,
     uint64_t max_size,
-    base::TimeTicks started_at) {
-  if (!ShouldContinueSelfCompaction(started_at)) {
+    base::TimeTicks triggered_at) {
+  if (!ShouldContinueSelfCompaction(triggered_at)) {
     return;
   }
 
@@ -511,15 +511,16 @@ void PreFreezeBackgroundMemoryTrimmer::SelfCompactionTask(
   CompactMemory(&regions, max_size);
 
   MaybePostSelfCompactionTask(std::move(task_runner), std::move(regions),
-                              std::move(metric), max_size, started_at);
+                              std::move(metric), max_size, triggered_at);
 }
 
 void PreFreezeBackgroundMemoryTrimmer::StartSelfCompaction(
     scoped_refptr<base::SequencedTaskRunner> task_runner,
     std::vector<debug::MappedMemoryRegion> regions,
-    scoped_refptr<CompactionMetric> metric,
     uint64_t max_bytes,
-    base::TimeTicks started_at) {
+    base::TimeTicks triggered_at) {
+  scoped_refptr<CompactionMetric> metric =
+      MakeRefCounted<CompactionMetric>(triggered_at, base::TimeTicks::Now());
   TRACE_EVENT0("base", "StartSelfCompaction");
   base::trace_event::EmitNamedTrigger("start-self-compaction");
   {
@@ -533,19 +534,17 @@ void PreFreezeBackgroundMemoryTrimmer::StartSelfCompaction(
   }
   metric->RecordBeforeMetrics();
   MaybePostSelfCompactionTask(std::move(task_runner), std::move(regions),
-                              std::move(metric), max_bytes, started_at);
+                              std::move(metric), max_bytes, triggered_at);
 }
 
 void PreFreezeBackgroundMemoryTrimmer::FinishSelfCompaction(
     scoped_refptr<CompactionMetric> metric,
-    base::TimeTicks started_at) {
+    base::TimeTicks triggered_at) {
   TRACE_EVENT0("base", "FinishSelfCompaction");
-  if (ShouldContinueSelfCompaction(started_at)) {
+  if (ShouldContinueSelfCompaction(triggered_at)) {
     metric->RecordDelayedMetrics();
     base::AutoLock locker(lock());
-    UmaHistogramMediumTimes(
-        "Memory.SelfCompact2.Renderer.TimeSinceLastCancel",
-        base::TimeTicks::Now() - self_compaction_last_cancelled_);
+    metric->RecordTimeMetrics(self_compaction_last_cancelled_);
   }
 }
 
@@ -569,7 +568,7 @@ void PreFreezeBackgroundMemoryTrimmer::MaybeCancelSelfCompactionInternal(
   process_compacted_metadata_.reset();
   // Check for the last time cancelled here in order to avoid recording this
   // metric multiple times.
-  if (self_compaction_last_cancelled_ < self_compaction_last_started_) {
+  if (self_compaction_last_cancelled_ < self_compaction_last_triggered_) {
     UmaHistogramEnumeration("Memory.SelfCompact2.Renderer.CancellationReason",
                             cancellation_reason);
   }
@@ -579,14 +578,14 @@ void PreFreezeBackgroundMemoryTrimmer::MaybeCancelSelfCompactionInternal(
 // static
 void PreFreezeBackgroundMemoryTrimmer::CompactSelf(
     scoped_refptr<base::SequencedTaskRunner> task_runner,
-    base::TimeTicks started_at) {
+    base::TimeTicks triggered_at) {
   // MADV_PAGEOUT was only added in Linux 5.4, so do nothing in earlier
   // versions.
   if (!SelfCompactionIsSupported()) {
     return;
   }
 
-  if (!ShouldContinueSelfCompaction(started_at)) {
+  if (!ShouldContinueSelfCompaction(triggered_at)) {
     return;
   }
 
@@ -607,9 +606,8 @@ void PreFreezeBackgroundMemoryTrimmer::CompactSelf(
   }
 
   Instance().StartSelfCompaction(std::move(task_runner), std::move(regions),
-                                 MakeRefCounted<CompactionMetric>(started_at),
                                  MiBToBytes(kShouldFreezeSelfMaxSize.Get()),
-                                 started_at);
+                                 triggered_at);
 }
 
 // static
@@ -691,16 +689,16 @@ void PreFreezeBackgroundMemoryTrimmer::OnSelfFreeze() {
 
 void PreFreezeBackgroundMemoryTrimmer::OnSelfFreezeInternal(
     scoped_refptr<SequencedTaskRunner> task_runner) {
-  const auto started_at = base::TimeTicks::Now();
+  const auto triggered_at = base::TimeTicks::Now();
   base::AutoLock locker(lock());
-  self_compaction_last_started_ = started_at;
+  self_compaction_last_triggered_ = triggered_at;
   if (base::FeatureList::IsEnabled(kShouldFreezeSelf)) {
     RunPreFreezeTasks();
   }
   task_runner->PostDelayedTask(
       FROM_HERE,
       base::BindOnce(&PreFreezeBackgroundMemoryTrimmer::CompactSelf,
-                     base::Unretained(this), task_runner, started_at),
+                     base::Unretained(this), task_runner, triggered_at),
       base::Seconds(kShouldFreezeSelfDelayAfterPreFreezeTasks.Get()));
 }
 
@@ -908,8 +906,10 @@ PreFreezeBackgroundMemoryTrimmer::PreFreezeMetric::PreFreezeMetric(
 PreFreezeBackgroundMemoryTrimmer::PreFreezeMetric::~PreFreezeMetric() = default;
 
 PreFreezeBackgroundMemoryTrimmer::CompactionMetric::CompactionMetric(
+    base::TimeTicks triggered_at,
     base::TimeTicks started_at)
-    : started_at_(started_at) {}
+    : self_compaction_triggered_at_(triggered_at),
+      self_compaction_started_at_(started_at) {}
 PreFreezeBackgroundMemoryTrimmer::CompactionMetric::~CompactionMetric() =
     default;
 
@@ -925,4 +925,13 @@ void PreFreezeBackgroundMemoryTrimmer::CompactionMetric::
   RecordSmapsRollupWithDelay(&smaps_after_60s_, base::Seconds(60));
 }
 
+void PreFreezeBackgroundMemoryTrimmer::CompactionMetric::RecordTimeMetrics(
+    base::TimeTicks self_compaction_last_cancelled) {
+  const auto now = base::TimeTicks::Now();
+  UmaHistogramMediumTimes("Memory.SelfCompact2.Renderer.SelfCompactionTime",
+                          now - self_compaction_started_at_);
+  UmaHistogramMediumTimes("Memory.SelfCompact2.Renderer.TimeSinceLastCancel",
+                          now - self_compaction_last_cancelled);
+}
+
 }  // namespace base::android

base/android/pre_freeze_background_memory_trimmer.h

@@ -125,7 +125,7 @@ class BASE_EXPORT PreFreezeBackgroundMemoryTrimmer {
 
   // Compacts the memory for the process.
   void CompactSelf(scoped_refptr<SequencedTaskRunner> task_runner,
-                   base::TimeTicks started_at);
+                   base::TimeTicks triggered_at);
 
   // If we are currently running self compaction, cancel it. If it was running,
   // record a metric with the reason for the cancellation.
@@ -208,9 +208,10 @@ class BASE_EXPORT PreFreezeBackgroundMemoryTrimmer {
  private:
   class CompactionMetric : public RefCountedThreadSafe<CompactionMetric> {
    public:
-    explicit CompactionMetric(base::TimeTicks started_at);
+    CompactionMetric(base::TimeTicks triggered_at, base::TimeTicks started_at);
 
     void RecordDelayedMetrics();
+    void RecordTimeMetrics(base::TimeTicks self_compaction_last_cancelled);
 
     void RecordBeforeMetrics();
     void MaybeRecordCompactionMetrics() LOCKS_EXCLUDED(lock());
@@ -222,7 +223,14 @@ class BASE_EXPORT PreFreezeBackgroundMemoryTrimmer {
         LOCKS_EXCLUDED(lock());
     void RecordSmapsRollupWithDelay(std::optional<debug::SmapsRollup>* target,
                                     base::TimeDelta delay);
-    base::TimeTicks started_at_;
+    // When the self compaction was first triggered. There is a delay between
+    // this time and when we actually begin the compaction.
+    base::TimeTicks self_compaction_triggered_at_;
+    // When the self compaction first started. This should generally be
+    // |self_compaction_triggered_at_ +
+    // kShouldFreezeSelfDelayAfterPreFreezeTasks.Get()|, but may be longer if
+    // the task was delayed.
+    base::TimeTicks self_compaction_started_at_;
     // We use std::optional here because:
     // - We record these incrementally.
     // - We may stop recording at some point.
@@ -240,26 +248,26 @@ class BASE_EXPORT PreFreezeBackgroundMemoryTrimmer {
 
   void StartSelfCompaction(scoped_refptr<base::SequencedTaskRunner> task_runner,
                            std::vector<debug::MappedMemoryRegion> regions,
-                           scoped_refptr<CompactionMetric> metric,
                            uint64_t max_size,
-                           base::TimeTicks started_at) LOCKS_EXCLUDED(lock());
+                           base::TimeTicks triggered_at) LOCKS_EXCLUDED(lock());
   static base::TimeDelta GetDelayBetweenSelfCompaction();
   void MaybePostSelfCompactionTask(
       scoped_refptr<base::SequencedTaskRunner> task_runner,
       std::vector<debug::MappedMemoryRegion> regions,
       scoped_refptr<CompactionMetric> metric,
       uint64_t max_size,
-      base::TimeTicks started_at) LOCKS_EXCLUDED(lock());
+      base::TimeTicks triggered_at) LOCKS_EXCLUDED(lock());
   void SelfCompactionTask(scoped_refptr<base::SequencedTaskRunner> task_runner,
                           std::vector<debug::MappedMemoryRegion> regions,
                           scoped_refptr<CompactionMetric> metric,
                           uint64_t max_size,
-                          base::TimeTicks started_at) LOCKS_EXCLUDED(lock());
+                          base::TimeTicks triggered_at) LOCKS_EXCLUDED(lock());
   void FinishSelfCompaction(scoped_refptr<CompactionMetric> metric,
-                            base::TimeTicks started_at) LOCKS_EXCLUDED(lock());
+                            base::TimeTicks triggered_at)
+      LOCKS_EXCLUDED(lock());
 
   static bool ShouldContinueSelfCompaction(
-      base::TimeTicks compaction_started_at) LOCKS_EXCLUDED(lock());
+      base::TimeTicks self_compaction_triggered_at) LOCKS_EXCLUDED(lock());
 
   static std::optional<uint64_t> CompactMemory(
       std::vector<debug::MappedMemoryRegion>* regions,
@@ -325,8 +333,8 @@ class BASE_EXPORT PreFreezeBackgroundMemoryTrimmer {
   //     frozen by App Freezer.
   base::TimeTicks self_compaction_last_cancelled_ GUARDED_BY(lock()) =
       base::TimeTicks::Min();
-  // When we last started self compaction. Used to record metrics.
-  base::TimeTicks self_compaction_last_started_ GUARDED_BY(lock()) =
+  // When we last triggered self compaction. Used to record metrics.
+  base::TimeTicks self_compaction_last_triggered_ GUARDED_BY(lock()) =
       base::TimeTicks::Min();
   std::optional<base::ScopedSampleMetadata> process_compacted_metadata_
       GUARDED_BY(lock());

base/android/pre_freeze_background_memory_trimmer_unittest.cc

@@ -827,14 +827,10 @@ TEST_F(PreFreezeSelfCompactionTest, Cancel) {
 
   ASSERT_EQ(regions.size(), 4u);
 
-  {
-    const auto started_at = base::TimeTicks::Now();
-    PreFreezeBackgroundMemoryTrimmer::Instance().StartSelfCompaction(
-        task_environment_.GetMainThreadTaskRunner(), std::move(regions),
-        base::MakeRefCounted<
-            PreFreezeBackgroundMemoryTrimmer::CompactionMetric>(started_at),
-        1, started_at);
-  }
+  const auto started_at = base::TimeTicks::Now();
+  PreFreezeBackgroundMemoryTrimmer::Instance().StartSelfCompaction(
+      task_environment_.GetMainThreadTaskRunner(), std::move(regions), 1,
+      started_at);
 
   EXPECT_EQ(task_environment_.GetPendingMainThreadTaskCount(), 1u);
 
@@ -885,14 +881,10 @@ TEST_F(PreFreezeSelfCompactionTest, NotCanceled) {
 
   ASSERT_EQ(regions.size(), 4u);
 
-  {
-    const auto started_at = base::TimeTicks::Now();
-    PreFreezeBackgroundMemoryTrimmer::Instance().StartSelfCompaction(
-        task_environment_.GetMainThreadTaskRunner(), std::move(regions),
-        base::MakeRefCounted<
-            PreFreezeBackgroundMemoryTrimmer::CompactionMetric>(started_at),
-        1, started_at);
-  }
+  const auto started_at = base::TimeTicks::Now();
+  PreFreezeBackgroundMemoryTrimmer::Instance().StartSelfCompaction(
+      task_environment_.GetMainThreadTaskRunner(), std::move(regions), 1,
+      started_at);
 
   // We should have 4 sections here, based on the sizes mapped above.
   // |StartSelfCompaction| doesn't run right away, but rather schedules a task.
@@ -932,7 +924,7 @@ TEST_F(PreFreezeSelfCompactionTest, NotCanceled) {
   // We also check that no other histograms (other than the ones expected above)
   // were recorded.
   EXPECT_EQ(histograms.GetTotalCountsForPrefix("Memory.SelfCompact2").size(),
-            46);
+            47);
 
   for (size_t i = 1; i < 5; i++) {
     size_t len = i * base::GetPageSize();
@@ -985,7 +977,7 @@ TEST_F(PreFreezeSelfCompactionTest, Disabled) {
   // We also check that no other histograms (other than the ones expected above)
   // were recorded.
   EXPECT_EQ(histograms.GetTotalCountsForPrefix("Memory.SelfCompact2").size(),
-            46);
+            47);
 }
 
 TEST_F(PreFreezeSelfCompactionTest, OnSelfFreezeCancel) {

tools/metrics/histograms/metadata/memory/histograms.xml

@@ -2202,6 +2202,15 @@ chromium-metrics-reviews@google.com.
   </summary>
 </histogram>
 
+<histogram name="Memory.SelfCompact2.Renderer.SelfCompactionTime" units="ms"
+    expires_after="2025-10-06">
+  <owner>thiabaud@google.com</owner>
+  <owner>lizeb@google.com</owner>
+  <summary>
+    How long self-compaction took. Recorded after self-compaction has finished.
+  </summary>
+</histogram>
+
 <histogram name="Memory.SelfCompact2.Renderer.TimeSinceLastCancel" units="ms"
     expires_after="2025-10-06">
   <owner>thiabaud@google.com</owner>