Delivering the FIRST_NONEMPTY_PAINT phase changing event to base/. This concludes the client-side “phased profiling” work.

I’m removing TODO items, and the DIFFS introduced by this should remind the reviewers that there are open questions that they wanted to re-raise, assuming the the CL doesn’t make it clear that the way it’s implemented is OK.

If there are still concerns, we should agree on one important thing before we resume the discussions: phase change delivery chain doesn’t go through metrics provider. It starts at the event source (FirstWebContentsProfiler), then goes to TrackingSynchronizer, then goes to base/. Once we agree on the design of this chain, it will make sense to go to more detailed discussions and open questions.
BUG=456354

Review URL: https://codereview.chromium.org/1021053003

Cr-Commit-Position: refs/heads/master@{#327143}

7 files changed, 197 insertions, 79 deletions

diff --git a/components/metrics.gypi b/components/metrics.gypi
index ddad096..45a36d1 100644
--- a/components/metrics.gypi
+++ b/components/metrics.gypi
@@ -148,6 +148,7 @@
         'metrics/profiler/profiler_metrics_provider.h',
         'metrics/profiler/tracking_synchronizer.cc',
         'metrics/profiler/tracking_synchronizer.h',
+        'metrics/profiler/tracking_synchronizer_observer.cc',
         'metrics/profiler/tracking_synchronizer_observer.h',
       ],
     },
diff --git a/components/metrics/BUILD.gn b/components/metrics/BUILD.gn
index 1c7301c..47dc5be 100644
--- a/components/metrics/BUILD.gn
+++ b/components/metrics/BUILD.gn
@@ -120,6 +120,7 @@ source_set("profiler") {
     "profiler/profiler_metrics_provider.h",
     "profiler/tracking_synchronizer.cc",
     "profiler/tracking_synchronizer.h",
+    "profiler/tracking_synchronizer_observer.cc",
     "profiler/tracking_synchronizer_observer.h",
   ]
 
diff --git a/components/metrics/profiler/tracking_synchronizer.cc b/components/metrics/profiler/tracking_synchronizer.cc
index ad36441..ac91b3d 100644
--- a/components/metrics/profiler/tracking_synchronizer.cc
+++ b/components/metrics/profiler/tracking_synchronizer.cc
@@ -180,11 +180,12 @@ base::LazyInstance
 
 // TrackingSynchronizer methods and members.
 
-TrackingSynchronizer::TrackingSynchronizer(base::TimeTicks now)
-    : last_used_sequence_number_(kNeverUsableSequenceNumber), start_time_(now) {
+TrackingSynchronizer::TrackingSynchronizer(scoped_ptr<base::TickClock> clock)
+    : last_used_sequence_number_(kNeverUsableSequenceNumber),
+      clock_(clock.Pass()) {
   DCHECK(!g_tracking_synchronizer);
   g_tracking_synchronizer = this;
-  phase_start_times_.push_back(now);
+  phase_start_times_.push_back(clock_->NowTicks());
 
 #if !defined(OS_IOS)
   // TODO: This ifdef and other ifdefs for OS_IOS in this file are only
@@ -227,6 +228,20 @@ void TrackingSynchronizer::FetchProfilerDataAsynchronously(
       base::TimeDelta::FromMinutes(1));
 }
 
+// static
+void TrackingSynchronizer::OnProfilingPhaseCompleted(
+    ProfilerEventProto::ProfilerEvent profiling_event) {
+  DCHECK_CURRENTLY_ON(BrowserThread::UI);
+
+  if (!g_tracking_synchronizer) {
+    // System teardown is happening.
+    return;
+  }
+
+  g_tracking_synchronizer->NotifyAllProcessesOfProfilingPhaseCompletion(
+      profiling_event);
+}
+
 void TrackingSynchronizer::OnPendingProcesses(int sequence_number,
                                               int pending_processes,
                                               bool end) {
@@ -261,24 +276,63 @@ int TrackingSynchronizer::RegisterAndNotifyAllProcesses(
   // Increment pending process count for sending browser's profiler data.
   request->IncrementProcessesPending();
 
+  const int current_profiling_phase = phase_completion_events_sequence_.size();
+
 #if !defined(OS_IOS)
   // Get profiler data from renderer and browser child processes.
-  content::ProfilerController::GetInstance()->GetProfilerData(sequence_number);
+  content::ProfilerController::GetInstance()->GetProfilerData(
+      sequence_number, current_profiling_phase);
 #endif
 
   // Send process data snapshot from browser process.
   tracked_objects::ProcessDataSnapshot process_data_snapshot;
-  tracked_objects::ThreadData::Snapshot(&process_data_snapshot);
+  tracked_objects::ThreadData::Snapshot(current_profiling_phase,
+                                        &process_data_snapshot);
+
   DecrementPendingProcessesAndSendData(sequence_number, process_data_snapshot,
                                        content::PROCESS_TYPE_BROWSER);
 
   return sequence_number;
 }
 
+void TrackingSynchronizer::RegisterPhaseCompletion(
+    ProfilerEventProto::ProfilerEvent profiling_event) {
+  phase_completion_events_sequence_.push_back(profiling_event);
+  phase_start_times_.push_back(clock_->NowTicks());
+}
+
+void TrackingSynchronizer::NotifyAllProcessesOfProfilingPhaseCompletion(
+    ProfilerEventProto::ProfilerEvent profiling_event) {
+  DCHECK_CURRENTLY_ON(BrowserThread::UI);
+
+  if (variations::GetVariationParamValue("UMALogPhasedProfiling",
+                                         "send_split_profiles") == "false") {
+    return;
+  }
+
+  int profiling_phase = phase_completion_events_sequence_.size();
+
+  // If you hit this check, stop and think. You just added a new profiling
+  // phase. Each profiling phase takes additional memory in DeathData's list of
+  // snapshots. We cannot grow it indefinitely. Consider collapsing older phases
+  // after they were sent to UMA server, or other ways to save memory.
+  DCHECK_LT(profiling_phase, 1);
+
+  RegisterPhaseCompletion(profiling_event);
+
+#if !defined(OS_IOS)
+  // Notify renderer and browser child processes.
+  content::ProfilerController::GetInstance()->OnProfilingPhaseCompleted(
+      profiling_phase);
+#endif
+
+  // Notify browser process.
+  tracked_objects::ThreadData::OnProfilingPhaseCompleted(profiling_phase);
+}
+
 void TrackingSynchronizer::SendData(
     const tracked_objects::ProcessDataSnapshot& profiler_data,
     content::ProcessType process_type,
-    base::TimeTicks now,
     TrackingSynchronizerObserver* observer) const {
   // We are going to loop though past profiling phases and notify the request
   // about each phase that is contained in profiler_data. past_events
@@ -290,20 +344,19 @@ void TrackingSynchronizer::SendData(
   // comparison.
   for (size_t phase = 0; phase <= phase_completion_events_sequence_.size();
        ++phase) {
-    auto it = profiler_data.phased_process_data_snapshots.find(phase);
+    auto it = profiler_data.phased_snapshots.find(phase);
 
-    if (it != profiler_data.phased_process_data_snapshots.end()) {
+    if (it != profiler_data.phased_snapshots.end()) {
       // If the phase is contained in the received snapshot, notify the
       // request.
-      const base::TimeDelta phase_start =
-          phase_start_times_[phase] - start_time_;
-      const base::TimeDelta phase_finish =
-          (phase + 1 < phase_start_times_.size() ? phase_start_times_[phase + 1]
-                                                 : now) -
-          start_time_;
-      observer->ReceivedProfilerData(it->second, profiler_data.process_id,
-                                     process_type, phase, phase_start,
-                                     phase_finish, past_events);
+      const base::TimeTicks phase_start = phase_start_times_[phase];
+      const base::TimeTicks phase_finish = phase + 1 < phase_start_times_.size()
+                                               ? phase_start_times_[phase + 1]
+                                               : clock_->NowTicks();
+      observer->ReceivedProfilerData(
+          ProfilerDataAttributes(phase, profiler_data.process_id, process_type,
+                                 phase_start, phase_finish),
+          it->second, past_events);
     }
 
     if (phase < phase_completion_events_sequence_.size()) {
@@ -324,7 +377,7 @@ void TrackingSynchronizer::DecrementPendingProcessesAndSendData(
 
   TrackingSynchronizerObserver* observer = request->callback_object_.get();
   if (observer)
-    SendData(profiler_data, process_type, base::TimeTicks::Now(), observer);
+    SendData(profiler_data, process_type, observer);
 
   // Delete request if we have heard back from all child processes.
   request->DecrementProcessesPending();
diff --git a/components/metrics/profiler/tracking_synchronizer.h b/components/metrics/profiler/tracking_synchronizer.h
index 590f3c3..f7158cb 100644
--- a/components/metrics/profiler/tracking_synchronizer.h
+++ b/components/metrics/profiler/tracking_synchronizer.h
@@ -13,6 +13,7 @@
 #include "base/lazy_instance.h"
 #include "base/memory/ref_counted.h"
 #include "base/memory/weak_ptr.h"
+#include "base/time/tick_clock.h"
 #include "base/time/time.h"
 #include "components/metrics/proto/chrome_user_metrics_extension.pb.h"
 #include "content/public/browser/profiler_subscriber.h"
@@ -43,9 +44,9 @@ class TrackingSynchronizer
   // Construction also sets up the global singleton instance. This instance is
   // used to communicate between the IO and UI thread, and is destroyed only as
   // the main thread (browser_main) terminates, which means the IO thread has
-  // already completed, and will not need this instance any further. |now| is
-  // the current time, but can be something else in tests.
-  explicit TrackingSynchronizer(base::TimeTicks now);
+  // already completed, and will not need this instance any further.
+  // |clock| is a clock used for durations of profiling phases.
+  explicit TrackingSynchronizer(scoped_ptr<base::TickClock> clock);
 
   // Contact all processes, and get them to upload to the browser any/all
   // changes to profiler data. It calls |callback_object|'s SetData method with
@@ -54,6 +55,11 @@ class TrackingSynchronizer
   static void FetchProfilerDataAsynchronously(
       const base::WeakPtr<TrackingSynchronizerObserver>& callback_object);
 
+  // Called when a profiling phase completes. |profiling_event| is the event
+  // that triggered the completion of the current phase, and begins a new phase.
+  static void OnProfilingPhaseCompleted(
+      ProfilerEventProto::ProfilerEvent profiling_event);
+
   // ------------------------------------------------------
   // ProfilerSubscriber methods for browser child processes
   // ------------------------------------------------------
@@ -64,15 +70,24 @@ class TrackingSynchronizer
                           int pending_processes,
                           bool end) override;
 
+ protected:
+  ~TrackingSynchronizer() override;
+
+  // Update the sequence of completed phases with a new phase completion info.
+  void RegisterPhaseCompletion(
+      ProfilerEventProto::ProfilerEvent profiling_event);
+
+  // Notify |observer| about |profiler_data| received from process of type
+  // |process_type|.
+  void SendData(const tracked_objects::ProcessDataSnapshot& profiler_data,
+                content::ProcessType process_type,
+                TrackingSynchronizerObserver* observer) const;
+
  private:
   friend class base::RefCountedThreadSafe<TrackingSynchronizer>;
-  // TODO(vadimt): Remove friending TrackingSynchronizerTest_ProfilerData_Test.
-  friend class TrackingSynchronizerTest_ProfilerData_Test;
 
   class RequestContext;
 
-  ~TrackingSynchronizer() override;
-
   // Send profiler_data back to callback_object_ by calling
   // DecrementPendingProcessesAndSendData which records that we are waiting
   // for one less profiler data from renderer or browser child process for the
@@ -89,13 +104,10 @@ class TrackingSynchronizer
   int RegisterAndNotifyAllProcesses(
       const base::WeakPtr<TrackingSynchronizerObserver>& callback_object);
 
-  // Notify |observer| about |profiler_data| received from process of type
-  // |process_type|. |now| is the current time, but can be something else in
-  // tests.
-  void SendData(const tracked_objects::ProcessDataSnapshot& profiler_data,
-                content::ProcessType process_type,
-                base::TimeTicks now,
-                TrackingSynchronizerObserver* observer) const;
+  // Notifies all processes of a completion of a profiling phase.
+  // |profiling_event| is the event associated with the phase change.
+  void NotifyAllProcessesOfProfilingPhaseCompletion(
+      ProfilerEventProto::ProfilerEvent profiling_event);
 
   // It finds the RequestContext for the given |sequence_number| and notifies
   // the RequestContext's |callback_object_| about the |value|. This is called
@@ -127,10 +139,8 @@ class TrackingSynchronizer
   std::vector<ProfilerEventProto::ProfilerEvent>
       phase_completion_events_sequence_;
 
-  // TODO(vadimt): consider moving 2 fields below to metrics service.
-  // Time of the profiling start. Used to calculate times of phase change
-  // moments relative to this value.
-  const base::TimeTicks start_time_;
+  // Clock for profiling phase durations.
+  const scoped_ptr<base::TickClock> clock_;
 
   // Times of starts of all profiling phases, including the current phase. The
   // index in the vector is the phase number.
diff --git a/components/metrics/profiler/tracking_synchronizer_observer.cc b/components/metrics/profiler/tracking_synchronizer_observer.cc
new file mode 100644
index 0000000..39309d3
--- /dev/null
+++ b/components/metrics/profiler/tracking_synchronizer_observer.cc
@@ -0,0 +1,22 @@
+// Copyright (c) 2015 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 "components/metrics/profiler/tracking_synchronizer_observer.h"
+
+namespace metrics {
+
+ProfilerDataAttributes::ProfilerDataAttributes(
+    int profiling_phase,
+    base::ProcessId process_id,
+    content::ProcessType process_type,
+    base::TimeTicks phase_start,
+    base::TimeTicks phase_finish)
+    : profiling_phase(profiling_phase),
+      process_id(process_id),
+      process_type(process_type),
+      phase_start(phase_start),
+      phase_finish(phase_finish) {
+}
+
+}  // namespace metrics
diff --git a/components/metrics/profiler/tracking_synchronizer_observer.h b/components/metrics/profiler/tracking_synchronizer_observer.h
index 0e94350..c9f88a7 100644
--- a/components/metrics/profiler/tracking_synchronizer_observer.h
+++ b/components/metrics/profiler/tracking_synchronizer_observer.h
@@ -8,6 +8,7 @@
 #include <vector>
 
 #include "base/process/process_handle.h"
+#include "base/time/time.h"
 #include "components/metrics/proto/chrome_user_metrics_extension.pb.h"
 #include "content/public/common/process_type.h"
 
@@ -26,31 +27,46 @@ namespace metrics {
 // efficient.
 typedef std::vector<ProfilerEventProto::ProfilerEvent> ProfilerEvents;
 
+// Attributes of profiler data passed to
+// TrackingSynchronizerObserver::ReceivedProfilerData.
+struct ProfilerDataAttributes {
+  ProfilerDataAttributes(int profiling_phase,
+                         base::ProcessId process_id,
+                         content::ProcessType process_type,
+                         base::TimeTicks phase_start,
+                         base::TimeTicks phase_finish);
+
+  // 0-indexed profiling phase number.
+  const int profiling_phase;
+
+  // ID of the process that reported the data.
+  const base::ProcessId process_id;
+
+  // Type of the process that reported the data.
+  const content::ProcessType process_type;
+
+  // Time of the profiling phase start.
+  const base::TimeTicks phase_start;
+
+  // Time of the profiling phase finish.
+  const base::TimeTicks phase_finish;
+};
+
 // Observer for notifications from the TrackingSynchronizer class.
 class TrackingSynchronizerObserver {
  public:
-  // TODO(vadimt): Consider isherman@ idea: I'd change the phase_start and
-  // phase_finish from TimeDeltas to TimeTicks.  And I'd omit the |past_events|
-  // list -- either in favor of a single ProfilerEvent that corresponds to the
-  // phase, or a method on the TrackingSynchronizer that can translate a
-  // profiling_phase to a ProfilerEvent.
-
-  // Received |process_data_phase| for profiling phase |profiling_phase| from a
-  // single process of |process_type|. The phase start and finish times,
-  // relative to the start time are |phase_start| and
-  // |phase_finish|. All profiling phases prior to the reported one have already
-  // completed, and each completion was associated with an instance of
-  // ProfilerEventProto::ProfilerEvent. |past_events| contains events associated
-  // with completions of phases prior to the reported one.
+  // Received |process_data_phase| for profiling phase and process defined by
+  // |attributes|.
+  // Each completed phase is associated with an event that triggered the
+  // completion of the phase. |past_events| contains the set of events that
+  // completed prior to the reported phase. This data structure is useful for
+  // quickly computing the full set of profiled traces that occurred before or
+  // after a given event.
   // The observer should assume there might be more data coming until
   // FinishedReceivingData() is called.
   virtual void ReceivedProfilerData(
+      const ProfilerDataAttributes& attributes,
       const tracked_objects::ProcessDataPhaseSnapshot& process_data_phase,
-      base::ProcessId process_id,
-      content::ProcessType process_type,
-      int profiling_phase,
-      base::TimeDelta phase_start,
-      base::TimeDelta phase_finish,
       const ProfilerEvents& past_events) = 0;
 
   // The observer should not expect any more calls to |ReceivedProfilerData()|
diff --git a/components/metrics/profiler/tracking_synchronizer_unittest.cc b/components/metrics/profiler/tracking_synchronizer_unittest.cc
index a597a47..7e02937 100644
--- a/components/metrics/profiler/tracking_synchronizer_unittest.cc
+++ b/components/metrics/profiler/tracking_synchronizer_unittest.cc
@@ -3,6 +3,7 @@
 // found in the LICENSE file.
 
 #include "base/memory/ref_counted.h"
+#include "base/test/simple_test_tick_clock.h"
 #include "base/tracked_objects.h"
 #include "components/metrics/profiler/tracking_synchronizer.h"
 #include "components/metrics/profiler/tracking_synchronizer_observer.h"
@@ -26,24 +27,23 @@ class TestObserver : public TrackingSynchronizerObserver {
   }
 
   void ReceivedProfilerData(
+      const ProfilerDataAttributes& attributes,
       const tracked_objects::ProcessDataPhaseSnapshot& process_data_phase,
-      base::ProcessId process_id,
-      content::ProcessType process_type,
-      int profiling_phase,
-      base::TimeDelta phase_start,
-      base::TimeDelta phase_finish,
       const ProfilerEvents& past_events) override {
-    EXPECT_EQ(static_cast<base::ProcessId>(239), process_id);
-    EXPECT_EQ(content::ProcessType::PROCESS_TYPE_PLUGIN, process_type);
+    EXPECT_EQ(static_cast<base::ProcessId>(239), attributes.process_id);
+    EXPECT_EQ(content::ProcessType::PROCESS_TYPE_PLUGIN,
+              attributes.process_type);
     ASSERT_EQ(1u, process_data_phase.tasks.size());
 
-    switch (profiling_phase) {
+    switch (attributes.profiling_phase) {
       case 0:
         EXPECT_FALSE(got_phase_0_);
         got_phase_0_ = true;
 
-        EXPECT_EQ(base::TimeDelta::FromMilliseconds(0), phase_start);
-        EXPECT_EQ(base::TimeDelta::FromMilliseconds(222), phase_finish);
+        EXPECT_EQ(base::TimeTicks() + base::TimeDelta::FromMilliseconds(111),
+                  attributes.phase_start);
+        EXPECT_EQ(base::TimeTicks() + base::TimeDelta::FromMilliseconds(333),
+                  attributes.phase_finish);
 
         EXPECT_EQ("death_thread0",
                   process_data_phase.tasks[0].death_thread_name);
@@ -54,8 +54,10 @@ class TestObserver : public TrackingSynchronizerObserver {
         EXPECT_FALSE(got_phase_1_);
         got_phase_1_ = true;
 
-        EXPECT_EQ(base::TimeDelta::FromMilliseconds(222), phase_start);
-        EXPECT_EQ(base::TimeDelta::FromMilliseconds(666), phase_finish);
+        EXPECT_EQ(base::TimeTicks() + base::TimeDelta::FromMilliseconds(333),
+                  attributes.phase_start);
+        EXPECT_EQ(base::TimeTicks() + base::TimeDelta::FromMilliseconds(777),
+                  attributes.phase_finish);
 
         EXPECT_EQ("death_thread1",
                   process_data_phase.tasks[0].death_thread_name);
@@ -77,9 +79,17 @@ class TestObserver : public TrackingSynchronizerObserver {
   DISALLOW_COPY_AND_ASSIGN(TestObserver);
 };
 
-base::TimeTicks TestTimeFromMs(int64 ms) {
-  return base::TimeTicks() + base::TimeDelta::FromMilliseconds(ms);
-}
+class TestTrackingSynchronizer : public TrackingSynchronizer {
+ public:
+  explicit TestTrackingSynchronizer(scoped_ptr<base::TickClock> clock)
+      : TrackingSynchronizer(clock.Pass()) {}
+
+  using TrackingSynchronizer::RegisterPhaseCompletion;
+  using TrackingSynchronizer::SendData;
+
+ private:
+  ~TestTrackingSynchronizer() override {}
+};
 
 }  // namespace
 
@@ -88,13 +98,18 @@ TEST(TrackingSynchronizerTest, ProfilerData) {
 #if !defined(OS_IOS)
   content::TestBrowserThreadBundle thread_bundle;
 #endif
-  scoped_refptr<TrackingSynchronizer> tracking_synchronizer =
-      new TrackingSynchronizer(TestTimeFromMs(111));
 
-  // Mimic a phase change event.
-  tracking_synchronizer->phase_completion_events_sequence_.push_back(
+  auto clock = new base::SimpleTestTickClock();  // Will be owned by
+                                                 // |tracking_synchronizer|.
+  clock->Advance(base::TimeDelta::FromMilliseconds(111));
+
+  scoped_refptr<TestTrackingSynchronizer> tracking_synchronizer =
+      new TestTrackingSynchronizer(make_scoped_ptr(clock));
+
+  clock->Advance(base::TimeDelta::FromMilliseconds(222));
+
+  tracking_synchronizer->RegisterPhaseCompletion(
       ProfilerEventProto::EVENT_FIRST_NONEMPTY_PAINT);
-  tracking_synchronizer->phase_start_times_.push_back(TestTimeFromMs(333));
 
   tracked_objects::ProcessDataSnapshot profiler_data;
   ProcessDataPhaseSnapshot snapshot0;
@@ -102,17 +117,17 @@ TEST(TrackingSynchronizerTest, ProfilerData) {
   task_snapshot0.death_thread_name = "death_thread0";
   snapshot0.tasks.push_back(task_snapshot0);
   ProcessDataPhaseSnapshot snapshot1;
-  profiler_data.phased_process_data_snapshots[0] = snapshot0;
+  profiler_data.phased_snapshots[0] = snapshot0;
   tracked_objects::TaskSnapshot task_snapshot1;
   task_snapshot1.death_thread_name = "death_thread1";
   snapshot1.tasks.push_back(task_snapshot1);
-  profiler_data.phased_process_data_snapshots[1] = snapshot1;
+  profiler_data.phased_snapshots[1] = snapshot1;
   profiler_data.process_id = 239;
 
+  clock->Advance(base::TimeDelta::FromMilliseconds(444));
   TestObserver test_observer;
-  tracking_synchronizer->SendData(profiler_data,
-                                  content::ProcessType::PROCESS_TYPE_PLUGIN,
-                                  TestTimeFromMs(777), &test_observer);
+  tracking_synchronizer->SendData(
+      profiler_data, content::ProcessType::PROCESS_TYPE_PLUGIN, &test_observer);
 }
 
 }  // namespace metrics