scheduler: Add support for tracing scheduler state

content/renderer/scheduler/renderer_scheduler_impl.cc

 // Copyright 2014 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 "content/renderer/scheduler/renderer_scheduler_impl.h"
 
 #include "base/bind.h"
+#include "base/debug/trace_event.h"
+#include "base/debug/trace_event_argument.h"
 #include "base/message_loop/message_loop_proxy.h"
 #include "cc/output/begin_frame_args.h"
 #include "content/renderer/scheduler/renderer_scheduler_selector.h"
 #include "ui/gfx/frame_time.h"
 
 namespace content {
 
 RendererSchedulerImpl::RendererSchedulerImpl()
     : RendererSchedulerImpl(base::MessageLoopProxy::current()) {
 }
@@ skipping 10 matching lines @@
       current_policy_(kNormalPriorityPolicy),
       weak_factory_(this) {
   weak_renderer_scheduler_ptr_ = weak_factory_.GetWeakPtr();
   idle_task_runner_ = make_scoped_refptr(new SingleThreadIdleTaskRunner(
       task_queue_manager_.TaskRunnerForQueue(kIdleTaskQueue),
       weak_factory_.GetWeakPtr()));
   renderer_scheduler_selector_->SetQueuePriority(
       kControlTaskQueue, RendererSchedulerSelector::kControlPriority);
   renderer_scheduler_selector_->DisableQueue(kIdleTaskQueue);
   task_queue_manager_.SetAutoPump(kIdleTaskQueue, false);
+
+  for (size_t i = 0; i < kTaskQueueCount; i++) {
+    renderer_scheduler_selector_->SetQueueName(
+        i, TaskQueueIdToString(static_cast<QueueId>(i)));
+  }
+  TRACE_EVENT_OBJECT_CREATED_WITH_ID(
+      TRACE_DISABLED_BY_DEFAULT("blink.scheduler"), "RendererScheduler", this);
 }

[picksi1, 2014/10/28 11:01:40]

Does it still make sense to use a "blink.scheduler" flag here?

[Sami, 2014/10/28 12:57:47]

You're probably right, let's go for renderer.scheduler. Too bad the name in
TaskQueueManager can't easily be parameterized.

 
 RendererSchedulerImpl::~RendererSchedulerImpl() {
+  TRACE_EVENT_OBJECT_DELETED_WITH_ID(
+      TRACE_DISABLED_BY_DEFAULT("blink.scheduler"), "RendererScheduler", this);
 }
 
 scoped_refptr<base::SingleThreadTaskRunner>
 RendererSchedulerImpl::DefaultTaskRunner() {
   return task_queue_manager_.TaskRunnerForQueue(kDefaultTaskQueue);
 }
 
 scoped_refptr<base::SingleThreadTaskRunner>
 RendererSchedulerImpl::CompositorTaskRunner() {
   return task_queue_manager_.TaskRunnerForQueue(kCompositorTaskQueue);
@@ skipping 17 matching lines @@
   }
 }
 
 void RendererSchedulerImpl::DidReceiveInputEvent() {
   base::AutoLock lock(incoming_signals_lock_);
   if (last_input_time_.is_null()) {
     // Update scheduler policy if should start a new compositor policy mode.
     base::subtle::Release_Store(&policy_may_need_update_, 1);
     PostUpdatePolicyOnControlRunner(base::TimeDelta());
   }
   last_input_time_ = Now();

[alexclarke, 2014/10/27 17:58:11]

I know last_input_time_ is in the json blob, but it would be nice to have some
tracing to mark when this function gets called.

Maybe there was a plan to do that in the trace viewer as a post process?

[Sami, 2014/10/28 12:57:47]

Good idea, I'll just add tracing here.

 }
 
 bool RendererSchedulerImpl::ShouldYieldForHighPriorityWork() {
   main_thread_checker_.CalledOnValidThread();
   return SchedulerPolicy() == kCompositorPriorityPolicy &&
          !task_queue_manager_.IsQueueEmpty(kCompositorTaskQueue);
 }
 
 base::TimeTicks RendererSchedulerImpl::CurrentIdleTaskDeadline() const {
   main_thread_checker_.CalledOnValidThread();
@@ skipping 48 matching lines @@
     case kCompositorPriorityPolicy:
       renderer_scheduler_selector_->SetQueuePriority(
           kCompositorTaskQueue, RendererSchedulerSelector::kHighPriority);
       break;
     case kNormalPriorityPolicy:
       renderer_scheduler_selector_->SetQueuePriority(
           kCompositorTaskQueue, RendererSchedulerSelector::kNormalPriority);
       break;
   }
   current_policy_ = new_policy;
+
+  TRACE_EVENT_OBJECT_SNAPSHOT_WITH_ID(
+      TRACE_DISABLED_BY_DEFAULT("blink.scheduler"),
+      "RendererScheduler",
+      this,
+      AsValueLocked());
+  TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("blink.scheduler"),
+                 "RendererScheduler.policy",
+                 current_policy_);
 }
 
 void RendererSchedulerImpl::StartIdlePeriod() {
+  TRACE_EVENT_ASYNC_BEGIN0(TRACE_DISABLED_BY_DEFAULT("blink.scheduler"),
+                           "RendererSchedulerIdlePeriod",
+                           this);
   renderer_scheduler_selector_->EnableQueue(
       kIdleTaskQueue, RendererSchedulerSelector::kBestEffortPriority);
   task_queue_manager_.PumpQueue(kIdleTaskQueue);
 }
 
 void RendererSchedulerImpl::EndIdlePeriod() {
+  TRACE_EVENT_ASYNC_END0(TRACE_DISABLED_BY_DEFAULT("blink.scheduler"),
+                         "RendererSchedulerIdlePeriod",
+                         this);
   renderer_scheduler_selector_->DisableQueue(kIdleTaskQueue);
 }
 
 base::TimeTicks RendererSchedulerImpl::Now() const {
   return gfx::FrameTime::Now();
 }
 
+// static
+const char* RendererSchedulerImpl::TaskQueueIdToString(QueueId queue_id) {
+  switch (queue_id) {
+    case kDefaultTaskQueue:
+      return "default_tq";
+    case kCompositorTaskQueue:
+      return "compositor_tq";
+    case kIdleTaskQueue:
+      return "idle_tq";
+    case kControlTaskQueue:
+      return "control_tq";
+    default:
+      NOTREACHED();
+      return nullptr;
+  }
+}
+
+// static
+const char* RendererSchedulerImpl::PolicyToString(Policy policy) {
+  switch (policy) {
+    case kNormalPriorityPolicy:
+      return "normal";
+    case kCompositorPriorityPolicy:
+      return "compositor";
+    default:
+      NOTREACHED();
+      return nullptr;
+  }
+}
+
+scoped_refptr<base::debug::ConvertableToTraceFormat>
+RendererSchedulerImpl::AsValueLocked() const {
+  main_thread_checker_.CalledOnValidThread();
+  incoming_signals_lock_.AssertAcquired();
+  scoped_refptr<base::debug::TracedValue> state =
+      new base::debug::TracedValue();
+
+  state->SetString("current_policy", PolicyToString(current_policy_));
+  state->BeginDictionary("task_queue_manager");
+  task_queue_manager_.AsValueInto(state.get());
+  state->EndDictionary();
+  state->BeginDictionary("renderer_scheduler_selector");
+  renderer_scheduler_selector_->AsValueInto(state.get());
+  state->EndDictionary();
+  state->SetDouble("now",
+                   (Now() - base::TimeTicks()).InMicroseconds() / 1000.0L);

[rmcilroy, 2014/10/27 17:51:28]

Maybe pass in the value of "Now()" from it's use in updatePolicy so it is not
out-of-sync with respect to the values we used to make the policy update
decision?

[Sami, 2014/10/28 12:57:47]

Done, although it's a little messy since I want to avoid reading the clock
unnecessarily.

+  state->SetDouble(
+      "last_input_time",
+      (last_input_time_ - base::TimeTicks()).InMicroseconds() / 1000.0L);

[picksi1, 2014/10/28 11:01:40]

Would InMillisecondsF() do the same here?

[Sami, 2014/10/28 12:57:47]

Yes, that's much cleaner. I wonder why cc -- where I lifted this from -- didn't
use that.

+  state->SetDouble(
+      "estimated_next_frame_begin",
+      (estimated_next_frame_begin_ - base::TimeTicks()).InMicroseconds() /
+          1000.0L);
+
+  return state;
+}
+
 }  // namespace content