cc: Heuristic for Renderer latency recovery

cc/scheduler/scheduler.cc

 // Copyright 2011 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 "cc/scheduler/scheduler.h"
 
 #include <algorithm>
 
 #include "base/auto_reset.h"
 #include "base/logging.h"
@@ skipping 111 matching lines @@
 
 base::TimeTicks Scheduler::Now() const {
   base::TimeTicks now = gfx::FrameTime::Now();
   TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler.now"),
                "Scheduler::Now",
                "now",
                now);
   return now;
 }
 
+void Scheduler::SetAuthoritativeVSyncInterval(const base::TimeDelta& interval) {

[mithro-old, 2015/05/27 04:40:14]

Moving this SetAuthoritativeVSyncInterval seems unrelated to the rest of this
change? 

Should it be split out into a separate CL?

+  authoritative_vsync_interval_ = interval;

[mithro-old, 2015/05/27 04:40:14]

Would it be useful to do a TRACE_EVENT here too?

+  if (vsync_observer_)
+    vsync_observer_->OnUpdateVSyncParameters(last_vsync_timebase_, interval);
+}
+
 void Scheduler::CommitVSyncParameters(base::TimeTicks timebase,
                                       base::TimeDelta interval) {
+  TRACE_EVENT2("cc", "Scheduler::CommitVSyncParameters", "timebase",
+               (timebase - base::TimeTicks()).InSecondsF(), "interval",

[mithro-old, 2015/05/27 04:40:14]

TRACE_EVENT should have native support for base::TimeTicks (see lines 1327-1341
of base/trace_event/trace_event.h), you shouldn't need to do the conversion
here.

This log should probably be in the separate CL referenced above.

+               interval.InSecondsF());
+
   if (authoritative_vsync_interval_ != base::TimeDelta()) {
     interval = authoritative_vsync_interval_;
   } else if (interval == base::TimeDelta()) {
     // TODO(brianderson): We should not be receiving 0 intervals.
     interval = BeginFrameArgs::DefaultInterval();
   }
 
   last_vsync_timebase_ = timebase;
 
   if (vsync_observer_)
@@ skipping 236 matching lines @@
     BeginImplFrameWithDeadline(adjusted_args);
   }
   return true;
 }
 
 void Scheduler::SetChildrenNeedBeginFrames(bool children_need_begin_frames) {
   state_machine_.SetChildrenNeedBeginFrames(children_need_begin_frames);
   ProcessScheduledActions();
 }
 
-void Scheduler::SetAuthoritativeVSyncInterval(const base::TimeDelta& interval) {
-  authoritative_vsync_interval_ = interval;
-  if (vsync_observer_)
-    vsync_observer_->OnUpdateVSyncParameters(last_vsync_timebase_, interval);
-}
-
 void Scheduler::SetVideoNeedsBeginFrames(bool video_needs_begin_frames) {
   state_machine_.SetVideoNeedsBeginFrames(video_needs_begin_frames);
   ProcessScheduledActions();
 }
 
 void Scheduler::OnDrawForOutputSurface() {
   DCHECK(settings_.using_synchronous_renderer_compositor);
   DCHECK_EQ(state_machine_.begin_impl_frame_state(),
             SchedulerStateMachine::BEGIN_IMPL_FRAME_STATE_IDLE);
   DCHECK(!BeginImplFrameDeadlinePending());
@@ skipping 85 matching lines @@
                args.AsValue(), "main_thread_is_high_latency",
                main_thread_is_in_high_latency_mode);
   TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler"),
                  "MainThreadLatency", main_thread_is_in_high_latency_mode);
 
   advance_commit_state_task_.Cancel();
 
   begin_impl_frame_args_ = args;
   begin_impl_frame_args_.deadline -= client_->DrawDurationEstimate();
 
-  if (!state_machine_.impl_latency_takes_priority() &&
-      main_thread_is_in_high_latency_mode &&
-      CanCommitAndActivateBeforeDeadline()) {
+  if (ShouldRecoverMainLatency()) {
+    TRACE_EVENT_INSTANT0("cc", "SkipBeginMainFrameToReduceLatency",
+                         TRACE_EVENT_SCOPE_THREAD);
     state_machine_.SetSkipNextBeginMainFrameToReduceLatency();
+  } else if (ShouldRecoverImplLatency()) {
+    TRACE_EVENT_INSTANT0("cc", "SkipBeginImplFrameToReduceLatency",

[mithro-old, 2015/05/27 04:40:14]

Should this be Scheduler::SkipBeginImplFrameToReduceLatency ?

+                         TRACE_EVENT_SCOPE_THREAD);
+    frame_source_->DidFinishFrame(begin_retro_frame_args_.size());
+    return;
   }
 
   BeginImplFrame();
 
   // The deadline will be scheduled in ProcessScheduledActions.
   state_machine_.OnBeginImplFrameDeadlinePending();
   ProcessScheduledActions();
 }
 
 void Scheduler::BeginImplFrameSynchronous(const BeginFrameArgs& args) {
   TRACE_EVENT1("cc,benchmark", "Scheduler::BeginImplFrame", "args",
                args.AsValue());
   begin_impl_frame_args_ = args;
   BeginImplFrame();
+

[mithro-old, 2015/05/27 04:40:14]

nit: Extra newline?

   FinishImplFrame();
 }
 
 void Scheduler::FinishImplFrame() {
   state_machine_.OnBeginImplFrameIdle();
   ProcessScheduledActions();
 
   client_->DidFinishImplFrame();
   frame_source_->DidFinishFrame(begin_retro_frame_args_.size());
 }
@@ skipping 16 matching lines @@
 }
 
 void Scheduler::ScheduleBeginImplFrameDeadline() {
   // The synchronous compositor does not post a deadline task.
   DCHECK(!settings_.using_synchronous_renderer_compositor);
 
   begin_impl_frame_deadline_task_.Cancel();
   begin_impl_frame_deadline_task_.Reset(begin_impl_frame_deadline_closure_);
 
   begin_impl_frame_deadline_mode_ =
       state_machine_.CurrentBeginImplFrameDeadlineMode();

[mithro-old, 2015/05/27 04:40:14]

nit: Random new line removal?

-
   base::TimeTicks deadline;
   switch (begin_impl_frame_deadline_mode_) {
     case SchedulerStateMachine::BEGIN_IMPL_FRAME_DEADLINE_MODE_NONE:
       // No deadline.
       return;
     case SchedulerStateMachine::BEGIN_IMPL_FRAME_DEADLINE_MODE_IMMEDIATE:
       // We are ready to draw a new active tree immediately.
       // We don't use Now() here because it's somewhat expensive to call.
       deadline = base::TimeTicks();
       break;
@@ skipping 197 matching lines @@
   state->SetInteger("begin_retro_frame_args_", begin_retro_frame_args_.size());
   state->SetBoolean("begin_retro_frame_task_",
                     !begin_retro_frame_task_.IsCancelled());
   state->SetBoolean("begin_impl_frame_deadline_task_",
                     !begin_impl_frame_deadline_task_.IsCancelled());
   state->SetBoolean("advance_commit_state_task_",
                     !advance_commit_state_task_.IsCancelled());
   state->BeginDictionary("begin_impl_frame_args");
   begin_impl_frame_args_.AsValueInto(state);
   state->EndDictionary();
+  state->SetString("begin_impl_frame_deadline_mode_",
+                   SchedulerStateMachine::BeginImplFrameDeadlineModeToString(
+                       begin_impl_frame_deadline_mode_));
 
   base::TimeTicks now = Now();
   base::TimeTicks frame_time = begin_impl_frame_args_.frame_time;
   base::TimeTicks deadline = begin_impl_frame_args_.deadline;
   base::TimeDelta interval = begin_impl_frame_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",
@@ skipping 12 matching lines @@
                    client_->DrawDurationEstimate().InMillisecondsF());
   state->SetDouble(
       "begin_main_frame_to_commit_duration_estimate_ms",
       client_->BeginMainFrameToCommitDurationEstimate().InMillisecondsF());
   state->SetDouble(
       "commit_to_activate_duration_estimate_ms",
       client_->CommitToActivateDurationEstimate().InMillisecondsF());
   state->EndDictionary();
 }
 
+bool Scheduler::ShouldRecoverMainLatency() const {
+  if (!state_machine_.MainThreadIsInHighLatencyMode())
+    return false;
+
+  if (state_machine_.impl_latency_takes_priority())
+    return false;
+
+  return CanCommitAndActivateBeforeDeadline();
+}
+
+bool Scheduler::ShouldRecoverImplLatency() const {
+  if (!state_machine_.SwapThrottled())
+    return false;
+
+  bool frame_time_is_before_deadline =
+      begin_impl_frame_args_.frame_time < begin_impl_frame_args_.deadline;

[mithro-old, 2015/05/27 04:40:14]

When is this ever not true? Is it because begin_impl_frame_args_ has been
adjusted?

[brianderson, 2015/05/27 23:22:31]

Yes, if the estimated draw time is 20ms, for example. I will add a comment.

+
+  SchedulerStateMachine::BeginImplFrameDeadlineMode
+      next_begin_impl_frame_deadline_mode =
+          state_machine_.CurrentBeginImplFrameDeadlineMode();
+  switch (next_begin_impl_frame_deadline_mode) {
+    case SchedulerStateMachine::BEGIN_IMPL_FRAME_DEADLINE_MODE_NONE:
+      return false;
+    case SchedulerStateMachine::BEGIN_IMPL_FRAME_DEADLINE_MODE_IMMEDIATE:
+      return frame_time_is_before_deadline;

[mithro-old, 2015/05/27 04:40:14]

I can't remember, are we allow to use fall through in Chrome?

[brianderson, 2015/05/27 23:22:32]

Looks like it is allowed.

+    case SchedulerStateMachine::BEGIN_IMPL_FRAME_DEADLINE_MODE_REGULAR:
+      return frame_time_is_before_deadline;
+    case SchedulerStateMachine::BEGIN_IMPL_FRAME_DEADLINE_MODE_LATE:
+      return CanCommitAndActivateBeforeDeadline();
+    case SchedulerStateMachine::
+        BEGIN_IMPL_FRAME_DEADLINE_MODE_BLOCKED_ON_READY_TO_DRAW:
+      return false;
+  }
+  NOTREACHED();
+  return false;
+}
+
 bool Scheduler::CanCommitAndActivateBeforeDeadline() const {
   // Check if the main thread computation and commit can be finished before the
   // impl thread's deadline.
   base::TimeTicks estimated_draw_time =
       begin_impl_frame_args_.frame_time +
       client_->BeginMainFrameToCommitDurationEstimate() +
       client_->CommitToActivateDurationEstimate();
 

[mithro-old, 2015/05/27 04:40:14]

nit: Unrelated removal?

[brianderson, 2015/06/30 22:03:53]

I added a trace event on line 506 above and removed this one.

-  TRACE_EVENT2(
-      TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler"),
-      "CanCommitAndActivateBeforeDeadline",
-      "time_left_after_drawing_ms",
-      (begin_impl_frame_args_.deadline - estimated_draw_time).InMillisecondsF(),
-      "state",
-      AsValue());
-
   return estimated_draw_time < begin_impl_frame_args_.deadline;
 }
 
 bool Scheduler::IsBeginMainFrameSentOrStarted() const {
   return (state_machine_.commit_state() ==
               SchedulerStateMachine::COMMIT_STATE_BEGIN_MAIN_FRAME_SENT ||
           state_machine_.commit_state() ==
               SchedulerStateMachine::COMMIT_STATE_BEGIN_MAIN_FRAME_STARTED);
 }
 
 }  // namespace cc