RC: RenderProcessProbe: record UMA metrics for measurements.

Bug: 755840
Change-Id: Ia43352a67cb170ffa8d8177de0ba00ff8dbd6c68
Reviewed-on: https://chromium-review.googlesource.com/1158967
Commit-Queue: Sigurður Ásgeirsson <siggi@chromium.org>
Reviewed-by: Robert Kaplow (slow) <rkaplow@chromium.org>
Reviewed-by: Chris Hamilton <chrisha@chromium.org>
Cr-Commit-Position: refs/heads/master@{#580262}

chrome/browser/resource_coordinator/render_process_probe.cc

@@ -7,6 +7,7 @@
 #include <vector>
 
 #include "base/bind.h"
+#include "base/metrics/histogram_macros.h"
 #include "build/build_config.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/render_process_host.h"
@@ -92,34 +93,7 @@ void RenderProcessProbeImpl::RegisterAliveRenderProcessesOnUIThread() {
 
   ++current_gather_cycle_;
 
-  for (content::RenderProcessHost::iterator rph_iter =
-           content::RenderProcessHost::AllHostsIterator();
-       !rph_iter.IsAtEnd(); rph_iter.Advance()) {
-    content::RenderProcessHost* host = rph_iter.GetCurrentValue();
-    // Process may not be valid yet.
-    if (!host->GetProcess().IsValid()) {
-      continue;
-    }
-
-    auto& render_process_info = render_process_info_map_[host->GetID()];
-    render_process_info.last_gather_cycle_active = current_gather_cycle_;
-    if (render_process_info.metrics.get() == nullptr) {
-      DCHECK(!render_process_info.process.IsValid());
-
-      // Duplicate the process to retain ownership of it through the thread
-      // bouncing.
-      render_process_info.process = host->GetProcess().Duplicate();
-
-#if defined(OS_MACOSX)
-      render_process_info.metrics = base::ProcessMetrics::CreateProcessMetrics(
-          render_process_info.process.Handle(),
-          content::BrowserChildProcessHost::GetPortProvider());
-#else
-      render_process_info.metrics = base::ProcessMetrics::CreateProcessMetrics(
-          render_process_info.process.Handle());
-#endif
-    }
-  }
+  RegisterRenderProcesses();
 
   is_gathering_ = true;
 
@@ -138,13 +112,7 @@ void RenderProcessProbeImpl::
 
   base::TimeTicks collection_start_time = base::TimeTicks::Now();
 
-  // Dispatch the memory collection request.
-  memory_instrumentation::MemoryInstrumentation::GetInstance()
-      ->RequestPrivateMemoryFootprint(
-          base::kNullProcessId,
-          base::BindRepeating(&RenderProcessProbeImpl::
-                                  ProcessGlobalMemoryDumpAndDispatchOnIOThread,
-                              base::Unretained(this), collection_start_time));
+  StartMemoryMeasurement(collection_start_time);
 
   RenderProcessInfoMap::iterator iter = render_process_info_map_.begin();
   while (iter != render_process_info_map_.end()) {
@@ -181,12 +149,23 @@ void RenderProcessProbeImpl::ProcessGlobalMemoryDumpAndDispatchOnIOThread(
     mojom::ProcessResourceMeasurementPtr measurement =
         mojom::ProcessResourceMeasurement::New();
 
-    measurement->pid = render_process_info.process.Pid();
+    measurement->pid =
+        GetProcessId(render_process_info_map_entry.first, render_process_info);
     measurement->cpu_usage = render_process_info.cpu_usage;
 
     batch->measurements.push_back(std::move(measurement));
   }
 
+  // Record the overall outcome of the measurement.
+  MeasurementOutcome outcome = MeasurementOutcome::kMeasurementSuccess;
+  if (!global_success)
+    outcome = MeasurementOutcome::kMeasurementPartialSuccess;
+  if (!dump)
+    outcome = MeasurementOutcome::kMeasurementFailure;
+
+  UMA_HISTOGRAM_ENUMERATION("ResourceCoordinator.Measurement.Memory.Outcome",
+                            outcome);
+
   if (dump) {
     // Then amend the ones we have memory metrics for with their private
     // footprint. The global dump may contain non-renderer processes, it may
@@ -195,22 +174,51 @@ void RenderProcessProbeImpl::ProcessGlobalMemoryDumpAndDispatchOnIOThread(
     // This may happen due to the inherent race between the request and
     // starting/stopping renderers, or because of other failures
     // This may therefore provide incomplete information.
+    size_t num_non_measured_processes = batch->measurements.size();
+    size_t num_unexpected_processes = 0;
     for (const auto& dump_entry : dump->process_dumps()) {
       base::ProcessId pid = dump_entry.pid();
 
+      bool used_entry = false;
       for (const auto& measurement : batch->measurements) {
-        if (measurement->pid == pid) {
+        if (measurement->pid != pid)
+          continue;
+
+        used_entry = true;
+
+        // The only way this could fail is if there are multiple measurements
+        // for the same PID in the memory dump.
+        DCHECK_LT(0u, num_non_measured_processes);
+        --num_non_measured_processes;
+
         measurement->private_footprint_kb =
             dump_entry.os_dump().private_footprint_kb;
         break;
       }
+
+      if (!used_entry)
+        ++num_unexpected_processes;
     }
-    }
+
+    // Record the number of processes we unexpectedly did or didn't get memory
+    // measurements for.
+    UMA_HISTOGRAM_COUNTS_1000(
+        "ResourceCoordinator.Measurement.Memory.UnmeasuredProcesses",
+        num_non_measured_processes);
+    // TODO(siggi): will this count extension/utility/background worker
+    //     processes?
+    UMA_HISTOGRAM_COUNTS_1000(
+        "ResourceCoordinator.Measurement.Memory.ExtraProcesses",
+        num_unexpected_processes);
   } else {
     // We should only get a nullptr in case of failure.
     DCHECK(!global_success);
   }
 
+  // Record the number of processes encountered.
+  UMA_HISTOGRAM_COUNTS_1000("ResourceCoordinator.Measurement.TotalProcesses",
+                            batch->measurements.size());
+
   // TODO(siggi): Because memory dump requests may be combined with earlier,
   //     in-progress requests, this is an upper bound for the start time.
   //     It would be more accurate to get the start time from the memory dump
@@ -218,6 +226,11 @@ void RenderProcessProbeImpl::ProcessGlobalMemoryDumpAndDispatchOnIOThread(
   batch->batch_started_time = collection_start_time;
   batch->batch_ended_time = base::TimeTicks::Now();
 
+  // Record the duration of the measurement process.
+  UMA_HISTOGRAM_TIMES("ResourceCoordinator.Measurement.Duration",
+                      batch->batch_ended_time - batch->batch_started_time);
+
+  // TODO(siggi): UMA record measurement time.
   bool should_restart = DispatchMetrics(std::move(batch));
   content::BrowserThread::PostTask(
       content::BrowserThread::UI, FROM_HERE,
@@ -237,6 +250,56 @@ void RenderProcessProbeImpl::FinishCollectionOnUIThread(bool restart_cycle) {
   } else {
     is_gather_cycle_started_ = false;
   }
+
+  AfterFinishCollectionOnUIThread();
+}
+
+void RenderProcessProbeImpl::RegisterRenderProcesses() {
+  for (content::RenderProcessHost::iterator rph_iter =
+           content::RenderProcessHost::AllHostsIterator();
+       !rph_iter.IsAtEnd(); rph_iter.Advance()) {
+    content::RenderProcessHost* host = rph_iter.GetCurrentValue();
+    // Process may not be valid yet.
+    if (!host->GetProcess().IsValid()) {
+      continue;
+    }
+
+    auto& render_process_info = render_process_info_map_[host->GetID()];
+    render_process_info.last_gather_cycle_active = current_gather_cycle_;
+    if (render_process_info.metrics.get() == nullptr) {
+      DCHECK(!render_process_info.process.IsValid());
+
+      // Duplicate the process to retain ownership of it through the thread
+      // bouncing.
+      render_process_info.process = host->GetProcess().Duplicate();
+    }
+
+#if defined(OS_MACOSX)
+    render_process_info.metrics = base::ProcessMetrics::CreateProcessMetrics(
+        render_process_info.process.Handle(),
+        content::BrowserChildProcessHost::GetPortProvider());
+#else
+    render_process_info.metrics = base::ProcessMetrics::CreateProcessMetrics(
+        render_process_info.process.Handle());
+#endif
+  }
+}
+
+void RenderProcessProbeImpl::StartMemoryMeasurement(
+    base::TimeTicks collection_start_time) {
+  // Dispatch the memory collection request.
+  memory_instrumentation::MemoryInstrumentation::GetInstance()
+      ->RequestPrivateMemoryFootprint(
+          base::kNullProcessId,
+          base::BindRepeating(&RenderProcessProbeImpl::
+                                  ProcessGlobalMemoryDumpAndDispatchOnIOThread,
+                              base::Unretained(this), collection_start_time));
+}
+
+base::ProcessId RenderProcessProbeImpl::GetProcessId(
+    int /*host_id*/,
+    const RenderProcessInfo& info) {
+  return info.process.Pid();
 }
 
 void RenderProcessProbeImpl::UpdateWithFieldTrialParams() {

chrome/browser/resource_coordinator/render_process_probe.h

@@ -52,6 +52,16 @@ class RenderProcessProbeImpl : public RenderProcessProbe {
   void StartSingleGather() override;
 
  protected:
+  // These values are persisted to logs. Entries should not be renumbered and
+  // numeric values should never be reused.
+  enum class MeasurementOutcome {
+    kMeasurementSuccess = 0,
+    kMeasurementPartialSuccess = 1,
+    kMeasurementFailure = 2,
+
+    kMaxValue = kMeasurementFailure,
+  };
+
   static constexpr base::TimeDelta kUninitializedCPUTime =
       base::TimeDelta::FromMicroseconds(-1);
 
@@ -84,8 +94,14 @@ class RenderProcessProbeImpl : public RenderProcessProbe {
   // (4) Initiate the next render process metrics collection cycle if the
   // cycle has been started and |restart_cycle| is true, which consists of a
   // delayed call to perform (1) via a timer.
-  // Virtual for testing.
-  virtual void FinishCollectionOnUIThread(bool restart_cycle);
+  void FinishCollectionOnUIThread(bool restart_cycle);
+
+  // Test seams.
+  virtual void AfterFinishCollectionOnUIThread() {}
+  virtual void RegisterRenderProcesses();
+  virtual void StartMemoryMeasurement(base::TimeTicks collection_start_time);
+  virtual base::ProcessId GetProcessId(int host_id,
+                                       const RenderProcessInfo& info);
 
   // Allows FieldTrial parameters to override defaults.
   void UpdateWithFieldTrialParams();

chrome/browser/resource_coordinator/render_process_probe_browsertest.cc

@@ -23,6 +23,7 @@
 #include "url/gurl.h"
 
 namespace resource_coordinator {
+namespace {
 
 class TestingRenderProcessProbe : public RenderProcessProbeImpl {
  public:
@@ -40,9 +41,7 @@ class TestingRenderProcessProbe : public RenderProcessProbeImpl {
     return false;
   }
 
-  void FinishCollectionOnUIThread(bool restart_cycle) override {
-    RenderProcessProbeImpl::FinishCollectionOnUIThread(restart_cycle);
-
+  void AfterFinishCollectionOnUIThread() override {
     current_run_loop_->QuitWhenIdle();
   }
 
@@ -94,6 +93,8 @@ class TestingRenderProcessProbe : public RenderProcessProbeImpl {
   DISALLOW_COPY_AND_ASSIGN(TestingRenderProcessProbe);
 };
 
+}  // namespace
+
 class RenderProcessProbeBrowserTest : public InProcessBrowserTest {
  public:
   RenderProcessProbeBrowserTest() = default;

chrome/browser/resource_coordinator/render_process_probe_unittest.cc

+// Copyright 2018 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 "chrome/browser/resource_coordinator/render_process_probe.h"
+#include "base/process/process.h"
+#include "base/process/process_metrics.h"
+#include "base/test/metrics/histogram_tester.h"
+#include "content/public/browser/browser_thread.h"
+#include "content/public/test/test_browser_thread_bundle.h"
+#include "services/resource_coordinator/public/cpp/memory_instrumentation/global_memory_dump.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace resource_coordinator {
+
+namespace {
+
+class TestingRenderProcessProbe : public RenderProcessProbeImpl {
+ public:
+  // Expose for testing.
+  using RenderProcessProbeImpl::MeasurementOutcome;
+
+  void SetMeasurementResults(
+      bool global_success,
+      std::unique_ptr<memory_instrumentation::GlobalMemoryDump> dump) {
+    global_success_ = global_success;
+    dump_ = std::move(dump);
+  }
+
+ protected:
+  bool global_success_;
+  std::unique_ptr<memory_instrumentation::GlobalMemoryDump> dump_;
+
+  // Overridden for testing.
+  void RegisterRenderProcesses() override;
+  void StartMemoryMeasurement(base::TimeTicks collection_start_time) override;
+  base::ProcessId GetProcessId(int host_id,
+                               const RenderProcessInfo& info) override;
+};
+
+void TestingRenderProcessProbe::RegisterRenderProcesses() {
+  // Register 4 renderer processes, all of which refer to this process.
+  for (int id = 1; id < 5; ++id) {
+    auto& render_process_info = render_process_info_map_[id];
+    render_process_info.last_gather_cycle_active = current_gather_cycle_;
+    render_process_info.process = base::Process::Current();
+    render_process_info.metrics =
+        base::ProcessMetrics::CreateCurrentProcessMetrics();
+  }
+}
+
+void TestingRenderProcessProbe::StartMemoryMeasurement(
+    base::TimeTicks collection_start_time) {
+  // Post the stored results to the completion function.
+  content::BrowserThread::PostTask(
+      content::BrowserThread::IO, FROM_HERE,
+      base::BindOnce(&TestingRenderProcessProbe::
+                         ProcessGlobalMemoryDumpAndDispatchOnIOThread,
+                     base::Unretained(this), collection_start_time,
+                     global_success_, std::move(dump_)));
+}
+
+base::ProcessId TestingRenderProcessProbe::GetProcessId(
+    int host_id,
+    const RenderProcessInfo& /* info */) {
+  // Use the host ID for PID for the purposes of this test.
+  return static_cast<base::ProcessId>(host_id);
+}
+
+class RenderProcessProbeTest : public testing::Test {
+ protected:
+  void RunGatherCycle(
+      bool global_success,
+      std::unique_ptr<memory_instrumentation::GlobalMemoryDump> dump);
+
+  std::unique_ptr<memory_instrumentation::GlobalMemoryDump> CreateMemoryDump(
+      int first_pid,
+      int num_pids);
+
+  content::TestBrowserThreadBundle browser_thread_bundle_;
+  TestingRenderProcessProbe probe_;
+};
+
+void RenderProcessProbeTest::RunGatherCycle(
+    bool global_success,
+    std::unique_ptr<memory_instrumentation::GlobalMemoryDump> dump) {
+  probe_.SetMeasurementResults(global_success, std::move(dump));
+  probe_.StartSingleGather();
+  browser_thread_bundle_.RunUntilIdle();
+}
+
+std::unique_ptr<memory_instrumentation::GlobalMemoryDump>
+RenderProcessProbeTest::CreateMemoryDump(int first_pid, int num_pids) {
+  memory_instrumentation::mojom::GlobalMemoryDumpPtr global_dump =
+      memory_instrumentation::mojom::GlobalMemoryDump::New();
+
+  for (int pid = first_pid; pid < first_pid + num_pids; ++pid) {
+    memory_instrumentation::mojom::ProcessMemoryDumpPtr process_dump =
+        memory_instrumentation::mojom::ProcessMemoryDump::New();
+
+    process_dump->os_dump = memory_instrumentation::mojom::OSMemDump::New();
+    process_dump->os_dump->private_footprint_kb = pid * 100;
+
+    process_dump->process_type =
+        memory_instrumentation::mojom::ProcessType::RENDERER;
+    process_dump->pid = pid;
+
+    global_dump->process_dumps.push_back(std::move(process_dump));
+  }
+
+  return memory_instrumentation::GlobalMemoryDump::MoveFrom(
+      std::move(global_dump));
+}
+
+}  // namespace
+
+TEST_F(RenderProcessProbeTest, FailureMetrics) {
+  base::HistogramTester tester;
+
+  // Full failure with a null dump.
+  RunGatherCycle(false, nullptr);
+
+  tester.ExpectTotalCount("ResourceCoordinator.Measurement.Duration", 1);
+
+  tester.ExpectUniqueSample("ResourceCoordinator.Measurement.TotalProcesses", 4,
+                            1);
+  tester.ExpectUniqueSample(
+      "ResourceCoordinator.Measurement.Memory.Outcome",
+      TestingRenderProcessProbe::MeasurementOutcome::kMeasurementFailure, 1);
+  tester.ExpectTotalCount(
+      "ResourceCoordinator.Measurement.Memory.UnmeasuredProcesses", 0);
+  tester.ExpectTotalCount(
+      "ResourceCoordinator.Measurement.Memory.ExtraProcesses", 0);
+}
+
+TEST_F(RenderProcessProbeTest, PartialSuccessMetrics) {
+  base::HistogramTester tester;
+
+  // Partial failure with a full dump.
+  RunGatherCycle(false, CreateMemoryDump(1, 4));
+
+  tester.ExpectTotalCount("ResourceCoordinator.Measurement.Duration", 1);
+
+  tester.ExpectUniqueSample("ResourceCoordinator.Measurement.TotalProcesses", 4,
+                            1);
+  tester.ExpectUniqueSample(
+      "ResourceCoordinator.Measurement.Memory.Outcome",
+      TestingRenderProcessProbe::MeasurementOutcome::kMeasurementPartialSuccess,
+      1);
+  tester.ExpectUniqueSample(
+      "ResourceCoordinator.Measurement.Memory.UnmeasuredProcesses", 0, 1);
+  tester.ExpectUniqueSample(
+      "ResourceCoordinator.Measurement.Memory.ExtraProcesses", 0, 1);
+}
+
+TEST_F(RenderProcessProbeTest, SuccessMetrics) {
+  base::HistogramTester tester;
+
+  // Full success with a skewed dump, missing one process while contributing
+  // an extra.
+  RunGatherCycle(true, CreateMemoryDump(2, 4));
+
+  tester.ExpectTotalCount("ResourceCoordinator.Measurement.Duration", 1);
+
+  tester.ExpectUniqueSample("ResourceCoordinator.Measurement.TotalProcesses", 4,
+                            1);
+  tester.ExpectUniqueSample(
+      "ResourceCoordinator.Measurement.Memory.Outcome",
+      TestingRenderProcessProbe::MeasurementOutcome::kMeasurementSuccess, 1);
+  tester.ExpectUniqueSample(
+      "ResourceCoordinator.Measurement.Memory.UnmeasuredProcesses", 1, 1);
+  tester.ExpectUniqueSample(
+      "ResourceCoordinator.Measurement.Memory.ExtraProcesses", 1, 1);
+}
+
+}  // namespace resource_coordinator

chrome/test/BUILD.gn

@@ -3026,6 +3026,7 @@ test("unit_tests") {
       "../browser/resource_coordinator/local_site_characteristics_webcontents_observer_unittest.cc",
       "../browser/resource_coordinator/page_signal_receiver_unittest.cc",
       "../browser/resource_coordinator/performance_measurement_manager_unittest.cc",
+      "../browser/resource_coordinator/render_process_probe_unittest.cc",
       "../browser/resource_coordinator/session_restore_policy_unittest.cc",
       "../browser/resource_coordinator/tab_activity_watcher_unittest.cc",
       "../browser/resource_coordinator/tab_lifecycle_unit_source_unittest.cc",

services/resource_coordinator/observers/page_signal_generator_impl.cc

@@ -234,7 +234,9 @@ void PageSignalGeneratorImpl::OnSystemEventReceived(
       PageData* data = &entry.second;
       // TODO(siggi): Figure "recency" here, to avoid firing a measurement event
       //     for state transitions that happened "too long" before a
-      //     measurement started.
+      //     measurement started. Alternatively perhaps this bit of policy is
+      //     better done in the observer, in which case it needs the time stamps
+      //     involved.
       if (data->GetLoadIdleState() == kLoadedAndIdle &&
           !data->performance_estimate_issued &&
           data->last_state_change < measurement_start) {

tools/metrics/histograms/enums.xml

@@ -31434,6 +31434,12 @@ Called by update_use_counter_css.py.-->
   <int value="3" label="Exceeded Cache Size"/>
 </enum>
 
+<enum name="MemoryMeasurementOutcome">
+  <int value="0" label="kMeasurementSuccess"/>
+  <int value="1" label="kMeasurementPartialSuccess"/>
+  <int value="2" label="kMeasurementFailure"/>
+</enum>
+
 <enum name="MemoryPressureLevel">
   <int value="0" label="No memory pressure"/>
   <int value="1" label="Moderate memory pressure"/>

tools/metrics/histograms/histograms.xml

@@ -82534,6 +82534,47 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="ResourceCoordinator.Measurement.Duration" units="ms">
+  <owner>siggi@chromium.org</owner>
+  <summary>The amount of wall-clock time a measurement cycle occupied.</summary>
+</histogram>
+
+<histogram name="ResourceCoordinator.Measurement.Memory.ExtraProcesses"
+    units="processes">
+  <owner>siggi@chromium.org</owner>
+  <summary>
+    The number of unexpected processes encountered during memory measurement.
+    This is expected to be non-zero as new processes can be created after a
+    measurement cycle is initiated, plus non-renderer processes are counted here
+    at the moment.
+  </summary>
+</histogram>
+
+<histogram name="ResourceCoordinator.Measurement.Memory.Outcome"
+    enum="MemoryMeasurementOutcome">
+  <owner>siggi@chromium.org</owner>
+  <summary>
+    An enumeration indicating the outcome of each memory measurement attempt.
+  </summary>
+</histogram>
+
+<histogram name="ResourceCoordinator.Measurement.Memory.UnmeasuredProcesses"
+    units="processes">
+  <owner>siggi@chromium.org</owner>
+  <summary>
+    The number of processes that didn't get a memory measurement. This can
+    happen if processes die as or after measurement is initiated.
+  </summary>
+</histogram>
+
+<histogram name="ResourceCoordinator.Measurement.TotalProcesses"
+    units="processes">
+  <owner>siggi@chromium.org</owner>
+  <summary>
+    The number of processes that were measured for CPU at least.
+  </summary>
+</histogram>
+
 <histogram name="ResourceLoadingHints.CountBlockedSubresourcePatterns"
     units="pattern count">
   <owner>tbansal@chromium.org</owner>