Delivering the FIRST_NONEMPTY_PAINT phase changing event to base/. This...

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}

chrome/browser/chrome_browser_main.cc

@@ -34,6 +34,7 @@
 #include "base/strings/utf_string_conversions.h"
 #include "base/sys_info.h"
 #include "base/threading/platform_thread.h"
+#include "base/time/default_tick_clock.h"
 #include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "base/values.h"
@@ -993,8 +994,8 @@ int ChromeBrowserMainParts::PreCreateThreadsImpl() {
 #endif  // defined(OS_LINUX) || defined(OS_OPENBSD) || defined(OS_MACOSX)
 
   // Initialize tracking synchronizer system.
-  tracking_synchronizer_ =
-      new metrics::TrackingSynchronizer(base::TimeTicks::Now());
+  tracking_synchronizer_ = new metrics::TrackingSynchronizer(
+      make_scoped_ptr(new base::DefaultTickClock()));
 
 #if defined(OS_MACOSX)
   // Get the Keychain API to register for distributed notifications on the main

chrome/browser/metrics/chrome_metrics_service_client.cc

@@ -117,6 +117,7 @@ ChromeMetricsServiceClient::ChromeMetricsServiceClient(
       google_update_metrics_provider_(nullptr),
 #endif
       drive_metrics_provider_(nullptr),
+      start_time_(base::TimeTicks::Now()),
       weak_ptr_factory_(this) {
   DCHECK(thread_checker_.CalledOnValidThread());
   RecordCommandLineMetrics();
@@ -395,19 +396,14 @@ void ChromeMetricsServiceClient::OnInitTaskGotGoogleUpdateData() {
       weak_ptr_factory_.GetWeakPtr());
 }
 
-// TODO(vadimt): Consider wrapping params in a struct after the list of params
-// to ReceivedProfilerData settles. crbug/456354.
 void ChromeMetricsServiceClient::ReceivedProfilerData(
+    const metrics::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 metrics::ProfilerEvents& past_events) {
   profiler_metrics_provider_->RecordProfilerData(
-      process_data_phase, process_id, process_type, profiling_phase,
-      phase_start, phase_finish, past_events);
+      process_data_phase, attributes.process_id, attributes.process_type,
+      attributes.profiling_phase, attributes.phase_start - start_time_,
+      attributes.phase_finish - start_time_, past_events);
 }
 
 void ChromeMetricsServiceClient::FinishedReceivingProfilerData() {

chrome/browser/metrics/chrome_metrics_service_client.h

@@ -97,12 +97,8 @@ class ChromeMetricsServiceClient
 
   // TrackingSynchronizerObserver:
   void ReceivedProfilerData(
+      const metrics::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 metrics::ProfilerEvents& past_profiler_events) override;
   void FinishedReceivingProfilerData() override;
 
@@ -185,6 +181,9 @@ class ChromeMetricsServiceClient
   // used.
   base::Callback<void(bool*)> cellular_callback_;
 
+  // Time of this object's creation.
+  const base::TimeTicks start_time_;
+
   base::WeakPtrFactory<ChromeMetricsServiceClient> weak_ptr_factory_;
 
   DISALLOW_COPY_AND_ASSIGN(ChromeMetricsServiceClient);

chrome/browser/metrics/first_web_contents_profiler.cc

@@ -12,6 +12,8 @@
 #include "chrome/browser/ui/browser.h"
 #include "chrome/browser/ui/browser_iterator.h"
 #include "chrome/browser/ui/tabs/tab_strip_model.h"
+#include "components/metrics/profiler/tracking_synchronizer.h"
+#include "components/metrics/proto/profiler_event.pb.h"
 
 scoped_ptr<FirstWebContentsProfiler>
 FirstWebContentsProfiler::CreateProfilerForFirstWebContents(
@@ -51,6 +53,9 @@ void FirstWebContentsProfiler::DidFirstVisuallyNonEmptyPaint() {
                                  elapsed);
   }
 
+  metrics::TrackingSynchronizer::OnProfilingPhaseCompleted(
+      metrics::ProfilerEventProto::EVENT_FIRST_NONEMPTY_PAINT);
+
   if (IsFinishedCollectingMetrics())
     FinishedCollectingMetrics();
 }

chrome/browser/ui/webui/profiler_ui.cc

@@ -163,17 +163,14 @@ void ProfilerUI::GetData() {
 }
 
 void ProfilerUI::ReceivedProfilerData(
+    const metrics::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 metrics::ProfilerEvents& past_events) {
   // Serialize the data to JSON.
   base::DictionaryValue json_data;
   task_profiler::TaskProfilerDataSerializer::ToValue(
-      process_data_phase, process_id, process_type, &json_data);
+      process_data_phase, attributes.process_id, attributes.process_type,
+      &json_data);
 
   // Send the data to the renderer.
   web_ui()->CallJavascriptFunction("g_browserBridge.receivedData", json_data);

chrome/browser/ui/webui/profiler_ui.h

@@ -22,12 +22,8 @@ class ProfilerUI : public content::WebUIController,
  private:
   // TrackingSynchronizerObserver:
   void ReceivedProfilerData(
+      const metrics::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 metrics::ProfilerEvents& past_events) override;
 
   // Used to get |weak_ptr_| to self on the UI thread.

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',
       ],
     },

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",
   ]
 

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();

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.

components/metrics/profiler/tracking_synchronizer_observer.cc

+// 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

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()|

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

content/browser/profiler_controller_impl.cc

@@ -72,7 +72,8 @@ void ProfilerControllerImpl::Unregister(const ProfilerSubscriber* subscriber) {
 }
 
 void ProfilerControllerImpl::GetProfilerDataFromChildProcesses(
-    int sequence_number) {
+    int sequence_number,
+    int current_profiling_phase) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   int pending_processes = 0;
@@ -85,8 +86,10 @@ void ProfilerControllerImpl::GetProfilerDataFromChildProcesses(
       continue;
 
     ++pending_processes;
-    if (!iter.Send(new ChildProcessMsg_GetChildProfilerData(sequence_number)))
+    if (!iter.Send(new ChildProcessMsg_GetChildProfilerData(
+            sequence_number, current_profiling_phase))) {
       --pending_processes;
+    }
   }
 
   BrowserThread::PostTask(
@@ -100,26 +103,66 @@ void ProfilerControllerImpl::GetProfilerDataFromChildProcesses(
           true));
 }
 
-void ProfilerControllerImpl::GetProfilerData(int sequence_number) {
+// static
+void ProfilerControllerImpl::NotifyChildProcessesOfProfilingPhaseCompletion(
+    int profiling_phase) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+
+  for (BrowserChildProcessHostIterator iter; !iter.Done(); ++iter) {
+    // In some cases, there may be no child process of the given type (for
+    // example, the GPU process may not exist and there may instead just be a
+    // GPU thread in the browser process). If that's the case, then the process
+    // handle will be base::kNullProcessHandle and we shouldn't send it a
+    // message.
+    if (iter.GetData().handle == base::kNullProcessHandle)
+      continue;
+
+    iter.Send(new ChildProcessMsg_ProfilingPhaseCompleted(profiling_phase));
+  }
+}
+
+void ProfilerControllerImpl::GetProfilerData(int sequence_number,
+                                             int current_profiling_phase) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 
+  // Iterates through renderers in UI thread, and through other child processes
+  // in IO thread, and send them GetChildProfilerData message. Renderers have to
+  // be contacted from UI thread, and other processes - from IO thread.
   int pending_processes = 0;
   for (RenderProcessHost::iterator it(RenderProcessHost::AllHostsIterator());
        !it.IsAtEnd(); it.Advance()) {
     ++pending_processes;
-    if (!it.GetCurrentValue()->Send(
-            new ChildProcessMsg_GetChildProfilerData(sequence_number))) {
+    if (!it.GetCurrentValue()->Send(new ChildProcessMsg_GetChildProfilerData(
+            sequence_number, current_profiling_phase))) {
       --pending_processes;
     }
   }
   OnPendingProcesses(sequence_number, pending_processes, false);
 
   BrowserThread::PostTask(
-      BrowserThread::IO,
-      FROM_HERE,
+      BrowserThread::IO, FROM_HERE,
       base::Bind(&ProfilerControllerImpl::GetProfilerDataFromChildProcesses,
-                 base::Unretained(this),
-                 sequence_number));
+                 base::Unretained(this), sequence_number,
+                 current_profiling_phase));
+}
+
+void ProfilerControllerImpl::OnProfilingPhaseCompleted(int profiling_phase) {
+  DCHECK_CURRENTLY_ON(BrowserThread::UI);
+
+  // Iterates through renderers in UI thread, and through other child processes
+  // in IO thread, and send them OnProfilingPhase message. Renderers have to be
+  // contacted from UI thread, and other processes - from IO thread.
+  for (RenderProcessHost::iterator it(RenderProcessHost::AllHostsIterator());
+       !it.IsAtEnd(); it.Advance()) {
+    it.GetCurrentValue()->Send(
+        new ChildProcessMsg_ProfilingPhaseCompleted(profiling_phase));
+  }
+
+  BrowserThread::PostTask(
+      BrowserThread::IO, FROM_HERE,
+      base::Bind(&ProfilerControllerImpl::
+                     NotifyChildProcessesOfProfilingPhaseCompletion,
+                 profiling_phase));
 }
 
 }  // namespace content

content/browser/profiler_controller_impl.h

@@ -44,13 +44,20 @@ class ProfilerControllerImpl : public ProfilerController {
   // ProfilerController implementation:
   void Register(ProfilerSubscriber* subscriber) override;
   void Unregister(const ProfilerSubscriber* subscriber) override;
-  void GetProfilerData(int sequence_number) override;
+  void GetProfilerData(int sequence_number,
+                       int current_profiling_phase) override;
+  void OnProfilingPhaseCompleted(int profiling_phase) override;
 
  private:
   friend struct DefaultSingletonTraits<ProfilerControllerImpl>;
 
   // Contact child processes and get their profiler data.
-  void GetProfilerDataFromChildProcesses(int sequence_number);
+  void GetProfilerDataFromChildProcesses(int sequence_number,
+                                         int current_profiling_phase);
+
+  // Contact child processes and notify them of a profiling phase completion.
+  static void NotifyChildProcessesOfProfilingPhaseCompletion(
+      int profiling_phase);
 
   ProfilerSubscriber* subscriber_;
 

content/child/child_thread_impl.cc

@@ -567,6 +567,8 @@ bool ChildThreadImpl::OnMessageReceived(const IPC::Message& msg) {
                         OnSetProfilerStatus)
     IPC_MESSAGE_HANDLER(ChildProcessMsg_GetChildProfilerData,
                         OnGetChildProfilerData)
+    IPC_MESSAGE_HANDLER(ChildProcessMsg_ProfilingPhaseCompleted,
+                        OnProfilingPhaseCompleted)
     IPC_MESSAGE_HANDLER(ChildProcessMsg_DumpHandles, OnDumpHandles)
     IPC_MESSAGE_HANDLER(ChildProcessMsg_SetProcessBackgrounded,
                         OnProcessBackgrounded)
@@ -606,14 +608,19 @@ void ChildThreadImpl::OnSetProfilerStatus(ThreadData::Status status) {
   ThreadData::InitializeAndSetTrackingStatus(status);
 }
 
-void ChildThreadImpl::OnGetChildProfilerData(int sequence_number) {
+void ChildThreadImpl::OnGetChildProfilerData(int sequence_number,
+                                             int current_profiling_phase) {
   tracked_objects::ProcessDataSnapshot process_data;
-  ThreadData::Snapshot(&process_data);
+  ThreadData::Snapshot(current_profiling_phase, &process_data);
 
   Send(
       new ChildProcessHostMsg_ChildProfilerData(sequence_number, process_data));
 }
 
+void ChildThreadImpl::OnProfilingPhaseCompleted(int profiling_phase) {
+  ThreadData::OnProfilingPhaseCompleted(profiling_phase);
+}
+
 void ChildThreadImpl::OnDumpHandles() {
 #if defined(OS_WIN)
   scoped_refptr<HandleEnumerator> handle_enum(

content/child/child_thread_impl.h

@@ -223,7 +223,8 @@ class CONTENT_EXPORT ChildThreadImpl
   // IPC message handlers.
   void OnShutdown();
   void OnSetProfilerStatus(tracked_objects::ThreadData::Status status);
-  void OnGetChildProfilerData(int sequence_number);
+  void OnGetChildProfilerData(int sequence_number, int current_profiling_phase);
+  void OnProfilingPhaseCompleted(int profiling_phase);
   void OnDumpHandles();
   void OnProcessBackgrounded(bool background);
 #ifdef IPC_MESSAGE_LOG_ENABLED

content/common/child_process_messages.h

@@ -58,7 +58,7 @@ IPC_STRUCT_TRAITS_BEGIN(tracked_objects::ProcessDataPhaseSnapshot)
 IPC_STRUCT_TRAITS_END()
 
 IPC_STRUCT_TRAITS_BEGIN(tracked_objects::ProcessDataSnapshot)
-  IPC_STRUCT_TRAITS_MEMBER(phased_process_data_snapshots)
+  IPC_STRUCT_TRAITS_MEMBER(phased_snapshots)
   IPC_STRUCT_TRAITS_MEMBER(process_id)
 IPC_STRUCT_TRAITS_END()
 
@@ -103,8 +103,14 @@ IPC_MESSAGE_CONTROL1(ChildProcessMsg_SetProfilerStatus,
 
 // Send to all the child processes to send back profiler data (ThreadData in
 // tracked_objects).
-IPC_MESSAGE_CONTROL1(ChildProcessMsg_GetChildProfilerData,
-                     int /* sequence_number */)
+IPC_MESSAGE_CONTROL2(ChildProcessMsg_GetChildProfilerData,
+                     int /* sequence_number */,
+                     int /* current_profiling_phase */)
+
+// Send to all the child processes to mark the current profiling phase as
+// finished and start a new phase.
+IPC_MESSAGE_CONTROL1(ChildProcessMsg_ProfilingPhaseCompleted,
+                     int /* profiling_phase */)
 
 // Send to all the child processes to send back histogram data.
 IPC_MESSAGE_CONTROL1(ChildProcessMsg_GetChildHistogramData,

content/public/browser/profiler_controller.h

@@ -42,7 +42,14 @@ class CONTENT_EXPORT ProfilerController {
   virtual void Unregister(const ProfilerSubscriber* subscriber) = 0;
 
   // Contact all processes and get their profiler data.
-  virtual void GetProfilerData(int sequence_number) = 0;
+  // |current_profiling_phase| is the 0-indexed identifier of the current
+  // profiling phase.
+  virtual void GetProfilerData(int sequence_number,
+                               int current_profiling_phase) = 0;
+
+  // Contact child processes and notify them that the |profiling_phase| has
+  // completed.
+  virtual void OnProfilingPhaseCompleted(int profiling_phase) = 0;
 };
 
 }  // namespace content