Instead of emitting a JSON dictionary for the CC scheduler State emit…

… a strongly typed protozero event. This is the first full protozero typed event (!!). As part of this we need to add some dependencies on tracing to access the macros as well as protozero writing. This improves the output trace size when enabled because we no longer need to write out the JSON dictionary including field names. And decreasing tracing CPU overhead when this category is enabled by 8% (6%-10% at 95% CI) [1] This should also improve memory usage while tracing since we will not be emitting large dynamically allocated JSON dictionaries. [1] https://docs.google.com/spreadsheets/d/1dxtQ72hl_aRA4lWp45u0SsGysZ1YR155oE83pUd5Iso/edit?usp=sharing TBR=nuskos@google.com Change-Id: I0ac53b850cbce78d893ff26a204280bc8d627c4d Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1944357 Commit-Queue: Stephen Nusko <nuskos@chromium.org> Reviewed-by: Stephen Nusko <nuskos@chromium.org> Reviewed-by: Eric Seckler <eseckler@chromium.org> Reviewed-by: enne <enne@chromium.org> Auto-Submit: Stephen Nusko <nuskos@chromium.org> Cr-Commit-Position: refs/heads/master@{#721203}
qweri0p · Dec 3, 2019 · 4283a7b · 4283a7b
1 parent a680ace
commit 4283a7b
Show file tree

Hide file tree

Showing 21 changed files with 496 additions and 311 deletions.
diff --git a/cc/BUILD.gn b/cc/BUILD.gn
@@ -375,6 +375,7 @@ cc_component("cc") {
     "//cc/base",
     "//cc/paint",
     "//components/viz/common",
+    "//services/tracing/public/cpp:cpp",
     "//skia",
   ]
   deps = [

diff --git a/cc/DEPS b/cc/DEPS
@@ -29,11 +29,13 @@ include_rules = [
   "+mojo/public/cpp/system/platform_handle.h",
   "+skia/ext",
   "+services/metrics/public/cpp",
+  "+services/tracing/public/cpp",
   "+third_party/khronos/GLES2/gl2.h",
   "+third_party/khronos/GLES2/gl2ext.h",
   "+third_party/libyuv",
   "+third_party/skia/include",
   "+third_party/skia/src/core/SkRemoteGlyphCache.h",
+  "+third_party/perfetto/protos/perfetto/trace/track_event",
   "+ui/events/types",
   "+ui/latency",
   "+ui/gfx",

diff --git a/cc/metrics/compositor_timing_history.cc b/cc/metrics/compositor_timing_history.cc
@@ -13,6 +13,7 @@
 #include "base/trace_event/trace_event.h"
 #include "cc/debug/rendering_stats_instrumentation.h"
 #include "cc/metrics/compositor_frame_reporting_controller.h"
+#include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_compositor_scheduler_state.pbzero.h"
 
 namespace cc {
 
@@ -593,25 +594,21 @@ CompositorTimingHistory::CreateUMAReporter(UMACategory category) {
   return base::WrapUnique<CompositorTimingHistory::UMAReporter>(nullptr);
 }
 
-void CompositorTimingHistory::AsValueInto(
-    base::trace_event::TracedValue* state) const {
-  state->SetDouble(
-      "begin_main_frame_queue_critical_estimate_ms",
-      BeginMainFrameQueueDurationCriticalEstimate().InMillisecondsF());
-  state->SetDouble(
-      "begin_main_frame_queue_not_critical_estimate_ms",
-      BeginMainFrameQueueDurationNotCriticalEstimate().InMillisecondsF());
-  state->SetDouble(
-      "begin_main_frame_start_to_ready_to_commit_estimate_ms",
-      BeginMainFrameStartToReadyToCommitDurationEstimate().InMillisecondsF());
-  state->SetDouble("commit_to_ready_to_activate_estimate_ms",
-                   CommitToReadyToActivateDurationEstimate().InMillisecondsF());
-  state->SetDouble("prepare_tiles_estimate_ms",
-                   PrepareTilesDurationEstimate().InMillisecondsF());
-  state->SetDouble("activate_estimate_ms",
-                   ActivateDurationEstimate().InMillisecondsF());
-  state->SetDouble("draw_estimate_ms",
-                   DrawDurationEstimate().InMillisecondsF());
+void CompositorTimingHistory::AsProtozeroInto(
+    perfetto::protos::pbzero::CompositorTimingHistory* state) const {
+  state->set_begin_main_frame_queue_critical_estimate_delta_us(
+      BeginMainFrameQueueDurationCriticalEstimate().InMicroseconds());
+  state->set_begin_main_frame_queue_not_critical_estimate_delta_us(
+      BeginMainFrameQueueDurationNotCriticalEstimate().InMicroseconds());
+  state->set_begin_main_frame_start_to_ready_to_commit_estimate_delta_us(
+      BeginMainFrameStartToReadyToCommitDurationEstimate().InMicroseconds());
+  state->set_commit_to_ready_to_activate_estimate_delta_us(
+      CommitToReadyToActivateDurationEstimate().InMicroseconds());
+  state->set_prepare_tiles_estimate_delta_us(
+      PrepareTilesDurationEstimate().InMicroseconds());
+  state->set_activate_estimate_delta_us(
+      ActivateDurationEstimate().InMicroseconds());
+  state->set_draw_estimate_delta_us(DrawDurationEstimate().InMicroseconds());
 }
 
 base::TimeTicks CompositorTimingHistory::Now() const {

diff --git a/cc/metrics/compositor_timing_history.h b/cc/metrics/compositor_timing_history.h
@@ -12,11 +12,13 @@
 #include "cc/tiles/tile_priority.h"
 #include "components/viz/common/frame_sinks/begin_frame_args.h"
 
-namespace base {
-namespace trace_event {
-class TracedValue;
-}  // namespace trace_event
-}  // namespace base
+namespace perfetto {
+namespace protos {
+namespace pbzero {
+class CompositorTimingHistory;
+}
+}  // namespace protos
+}  // namespace perfetto
 
 namespace viz {
 struct FrameTimingDetails;
@@ -47,7 +49,8 @@ class CC_EXPORT CompositorTimingHistory {
 
   CompositorTimingHistory& operator=(const CompositorTimingHistory&) = delete;
 
-  void AsValueInto(base::trace_event::TracedValue* state) const;
+  void AsProtozeroInto(
+      perfetto::protos::pbzero::CompositorTimingHistory* state) const;
 
   // The main thread responsiveness depends heavily on whether or not the
   // on_critical_path flag is set, so we record response times separately.

diff --git a/cc/scheduler/begin_frame_tracker.cc b/cc/scheduler/begin_frame_tracker.cc
@@ -4,6 +4,8 @@
 
 #include "cc/scheduler/begin_frame_tracker.h"
 
+#include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_compositor_scheduler_state.pbzero.h"
+
 namespace cc {
 
 BeginFrameTracker::BeginFrameTracker(const base::Location& location)
@@ -77,36 +79,35 @@ base::TimeDelta BeginFrameTracker::Interval() const {
   return interval;
 }
 
-void BeginFrameTracker::AsValueInto(
+void BeginFrameTracker::AsProtozeroInto(
     base::TimeTicks now,
-    base::trace_event::TracedValue* state) const {
-  state->SetDouble("updated_at_ms",
-                   current_updated_at_.since_origin().InMillisecondsF());
-  state->SetDouble("finished_at_ms",
-                   current_finished_at_.since_origin().InMillisecondsF());
+    perfetto::protos::pbzero::BeginImplFrameArgs* state) const {
+  state->set_updated_at_us(current_updated_at_.since_origin().InMicroseconds());
+  state->set_finished_at_us(
+      current_finished_at_.since_origin().InMicroseconds());
   if (HasFinished()) {
-    state->SetString("state", "FINISHED");
-    state->BeginDictionary("current_args_");
+    state->set_state(
+        perfetto::protos::pbzero::BeginImplFrameArgs::BEGIN_FRAME_FINISHED);
+    current_args_.AsProtozeroInto(state->set_current_args());
   } else {
-    state->SetString("state", "USING");
-    state->BeginDictionary("last_args_");
+    state->set_state(
+        perfetto::protos::pbzero::BeginImplFrameArgs::BEGIN_FRAME_USING);
+    current_args_.AsProtozeroInto(state->set_last_args());
   }
-  current_args_.AsValueInto(state);
-  state->EndDictionary();
 
   base::TimeTicks frame_time = current_args_.frame_time;
   base::TimeTicks deadline = current_args_.deadline;
   base::TimeDelta interval = current_args_.interval;
-  state->BeginDictionary("major_timestamps_in_ms");
-  state->SetDouble("0_interval", interval.InMillisecondsF());
-  state->SetDouble("1_now_to_deadline", (deadline - now).InMillisecondsF());
-  state->SetDouble("2_frame_time_to_now", (now - frame_time).InMillisecondsF());
-  state->SetDouble("3_frame_time_to_deadline",
-                   (deadline - frame_time).InMillisecondsF());
-  state->SetDouble("4_now", now.since_origin().InMillisecondsF());
-  state->SetDouble("5_frame_time", frame_time.since_origin().InMillisecondsF());
-  state->SetDouble("6_deadline", deadline.since_origin().InMillisecondsF());
-  state->EndDictionary();
+
+  auto* timestamps = state->set_timestamps_in_us();
+  timestamps->set_interval_delta(interval.InMicroseconds());
+  timestamps->set_now_to_deadline_delta((deadline - now).InMicroseconds());
+  timestamps->set_frame_time_to_now_delta((now - frame_time).InMicroseconds());
+  timestamps->set_frame_time_to_deadline_delta(
+      (deadline - frame_time).InMicroseconds());
+  timestamps->set_now(now.since_origin().InMicroseconds());
+  timestamps->set_frame_time(frame_time.since_origin().InMicroseconds());
+  timestamps->set_deadline(deadline.since_origin().InMicroseconds());
 }
 
 const viz::BeginFrameArgs& BeginFrameTracker::DangerousMethodCurrentOrLast()

diff --git a/cc/scheduler/begin_frame_tracker.h b/cc/scheduler/begin_frame_tracker.h
@@ -16,6 +16,13 @@
 
 #define BEGINFRAMETRACKER_FROM_HERE FROM_HERE_WITH_EXPLICIT_FUNCTION("")
 
+namespace perfetto {
+namespace protos {
+namespace pbzero {
+class BeginImplFrameArgs;
+}
+}  // namespace protos
+}  // namespace perfetto
 namespace cc {
 
 // Microclass to trace and check properties for correct BeginFrameArgs (BFA)
@@ -68,8 +75,9 @@ class CC_EXPORT BeginFrameTracker {
   // any time.
   base::TimeDelta Interval() const;
 
-  void AsValueInto(base::TimeTicks now,
-                   base::trace_event::TracedValue* dict) const;
+  void AsProtozeroInto(
+      base::TimeTicks now,
+      perfetto::protos::pbzero::BeginImplFrameArgs* dict) const;
 
   // The following methods violate principles of how viz::BeginFrameArgs should
   // be used. These methods should only be used when there is no other choice.

diff --git a/cc/scheduler/scheduler.cc b/cc/scheduler/scheduler.cc
@@ -16,6 +16,8 @@
 #include "cc/metrics/begin_main_frame_metrics.h"
 #include "cc/metrics/compositor_timing_history.h"
 #include "components/viz/common/frame_sinks/delay_based_time_source.h"
+#include "services/tracing/public/cpp/perfetto/macros.h"
+#include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_compositor_scheduler_state.pbzero.h"
 
 namespace cc {
 
@@ -154,7 +156,7 @@ void Scheduler::DidSubmitCompositorFrame(uint32_t frame_token) {
 }
 
 void Scheduler::DidReceiveCompositorFrameAck() {
-  DCHECK_GT(state_machine_.pending_submit_frames(), 0) << AsValue()->ToString();
+  DCHECK_GT(state_machine_.pending_submit_frames(), 0);
   compositor_timing_history_->DidReceiveCompositorFrameAck();
   state_machine_.DidReceiveCompositorFrameAck();
   ProcessScheduledActions();
@@ -784,8 +786,10 @@ void Scheduler::ProcessScheduledActions() {
   SchedulerStateMachine::Action action;
   do {
     action = state_machine_.NextAction();
-    TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler"),
-                 "SchedulerStateMachine", "state", AsValue());
+    TRACE_EVENT(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler"),
+                "SchedulerStateMachine", [this](perfetto::EventContext ctx) {
+                  this->AsProtozeroInto(ctx.event()->set_cc_scheduler_state());
+                });
     base::AutoReset<SchedulerStateMachine::Action> mark_inside_action(
         &inside_action_, action);
     switch (action) {
@@ -866,62 +870,47 @@ void Scheduler::ProcessScheduledActions() {
   StartOrStopBeginFrames();
 }
 
-std::unique_ptr<base::trace_event::ConvertableToTraceFormat>
-Scheduler::AsValue() const {
-  auto state = std::make_unique<base::trace_event::TracedValue>();
-  AsValueInto(state.get());
-  return std::move(state);
-}
-
-void Scheduler::AsValueInto(base::trace_event::TracedValue* state) const {
+void Scheduler::AsProtozeroInto(
+    perfetto::protos::pbzero::ChromeCompositorSchedulerState* state) const {
   base::TimeTicks now = Now();
 
-  state->BeginDictionary("state_machine");
-  state_machine_.AsValueInto(state);
-  state->EndDictionary();
-
-  state->SetBoolean("observing_begin_frame_source",
-                    observing_begin_frame_source_);
-  state->SetBoolean("begin_impl_frame_deadline_task",
-                    !begin_impl_frame_deadline_task_.IsCancelled());
-  state->SetBoolean("pending_begin_frame_task",
-                    !pending_begin_frame_task_.IsCancelled());
-  state->SetBoolean("skipped_last_frame_missed_exceeded_deadline",
-                    skipped_last_frame_missed_exceeded_deadline_);
-  state->SetBoolean("skipped_last_frame_to_reduce_latency",
-                    skipped_last_frame_to_reduce_latency_);
-  state->SetString("inside_action",
-                   SchedulerStateMachine::ActionToString(inside_action_));
-  state->SetString("deadline_mode",
-                   SchedulerStateMachine::BeginImplFrameDeadlineModeToString(
-                       deadline_mode_));
-
-  state->SetDouble("deadline_ms", deadline_.since_origin().InMillisecondsF());
-  state->SetDouble("deadline_scheduled_at_ms",
-                   deadline_scheduled_at_.since_origin().InMillisecondsF());
-
-  state->SetDouble("now_ms", Now().since_origin().InMillisecondsF());
-  state->SetDouble("now_to_deadline_ms", (deadline_ - Now()).InMillisecondsF());
-  state->SetDouble("now_to_deadline_scheduled_at_ms",
-                   (deadline_scheduled_at_ - Now()).InMillisecondsF());
-
-  state->BeginDictionary("begin_impl_frame_args");
-  begin_impl_frame_tracker_.AsValueInto(now, state);
-  state->EndDictionary();
-
-  state->BeginDictionary("begin_frame_observer_state");
-  BeginFrameObserverBase::AsValueInto(state);
-  state->EndDictionary();
+  state_machine_.AsProtozeroInto(state->set_state_machine());
+
+  state->set_observing_begin_frame_source(observing_begin_frame_source_);
+  state->set_begin_impl_frame_deadline_task(
+      !begin_impl_frame_deadline_task_.IsCancelled());
+  state->set_pending_begin_frame_task(!pending_begin_frame_task_.IsCancelled());
+  state->set_skipped_last_frame_missed_exceeded_deadline(
+      skipped_last_frame_missed_exceeded_deadline_);
+  state->set_skipped_last_frame_to_reduce_latency(
+      skipped_last_frame_to_reduce_latency_);
+  state->set_inside_action(
+      SchedulerStateMachine::ActionToProtozeroEnum(inside_action_));
+  state->set_deadline_mode(
+      SchedulerStateMachine::BeginImplFrameDeadlineModeToProtozeroEnum(
+          deadline_mode_));
+
+  state->set_deadline_us(deadline_.since_origin().InMicroseconds());
+  state->set_deadline_scheduled_at_us(
+      deadline_scheduled_at_.since_origin().InMicroseconds());
+
+  state->set_now_us(Now().since_origin().InMicroseconds());
+  state->set_now_to_deadline_delta_us((deadline_ - Now()).InMicroseconds());
+  state->set_now_to_deadline_scheduled_at_delta_us(
+      (deadline_scheduled_at_ - Now()).InMicroseconds());
+
+  begin_impl_frame_tracker_.AsProtozeroInto(now,
+                                            state->set_begin_impl_frame_args());
+
+  BeginFrameObserverBase::AsProtozeroInto(
+      state->set_begin_frame_observer_state());
 
   if (begin_frame_source_) {
-    state->BeginDictionary("begin_frame_source_state");
-    begin_frame_source_->AsValueInto(state);
-    state->EndDictionary();
+    begin_frame_source_->AsProtozeroInto(state->set_begin_frame_source_state());
   }
 
-  state->BeginDictionary("compositor_timing_history");
-  compositor_timing_history_->AsValueInto(state);
-  state->EndDictionary();
+  compositor_timing_history_->AsProtozeroInto(
+      state->set_compositor_timing_history());
 }
 
 void Scheduler::UpdateCompositorTimingHistoryRecordingEnabled() {

diff --git a/cc/scheduler/scheduler.h b/cc/scheduler/scheduler.h
@@ -20,10 +20,14 @@
 #include "components/viz/common/frame_sinks/begin_frame_source.h"
 #include "components/viz/common/frame_sinks/delay_based_time_source.h"
 
-namespace base {
-namespace trace_event {
-class ConvertableToTraceFormat;
+namespace perfetto {
+namespace protos {
+namespace pbzero {
+class ChromeCompositorSchedulerState;
 }
+}  // namespace protos
+}  // namespace perfetto
+namespace base {
 class SingleThreadTaskRunner;
 }
 
@@ -224,9 +228,8 @@ class CC_EXPORT Scheduler : public viz::BeginFrameObserverBase {
   // the main thread by the cc scheduler.
   void SetMainThreadWantsBeginMainFrameNotExpected(bool new_state);
 
-  std::unique_ptr<base::trace_event::ConvertableToTraceFormat> AsValue() const;
-
-  void AsValueInto(base::trace_event::TracedValue* state) const;
+  void AsProtozeroInto(
+      perfetto::protos::pbzero::ChromeCompositorSchedulerState* state) const;
 
   void SetVideoNeedsBeginFrames(bool video_needs_begin_frames);