Add SequenceManager debug option to show task reordering

This is helpful whern diagnosing test failures resulting from scheduler
policy changes.

Bug: 971191
Change-Id: I835db83e62895e45ef7400d231db8b6e30f14ab3
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1806464Reviewed-by: Alexander Timin <altimin@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#697201}

base/task/sequence_manager/sequence_manager.h

@@ -102,6 +102,11 @@ class BASE_EXPORT SequenceManager {
       kNone,
       kEnabled,
       kEnabledWithBacktrace,
+
+      // Logs high priority tasks and the lower priority tasks they skipped
+      // past.  Useful for debugging test failures caused by scheduler policy
+      // changes.
+      kReorderedOnly,
     };
     TaskLogging task_execution_logging = TaskLogging::kNone;
 

base/task/sequence_manager/sequence_manager_impl.cc

@@ -503,52 +503,60 @@ Optional<Task> SequenceManagerImpl::TakeTask() {
                      "task_type", executing_task.task_type);
   TRACE_EVENT_BEGIN0("sequence_manager", executing_task.task_queue_name);
 
-#if DCHECK_IS_ON() && !defined(OS_NACL)
-  LogTaskDebugInfo(executing_task);
-#endif
-
   return task;
 }
 
 #if DCHECK_IS_ON() && !defined(OS_NACL)
 void SequenceManagerImpl::LogTaskDebugInfo(
-    const ExecutingTask& executing_task) {
+    const WorkQueue* selected_work_queue) const {
+  const Task* task = selected_work_queue->GetFrontTask();
   switch (settings_.task_execution_logging) {
     case Settings::TaskLogging::kNone:
       break;
 
     case Settings::TaskLogging::kEnabled:
-      LOG(INFO) << "#"
-                << static_cast<uint64_t>(
-                       executing_task.pending_task.enqueue_order())
-                << " " << executing_task.task_queue_name
-                << (executing_task.pending_task.cross_thread_
-                        ? " Run crossthread "
-                        : " Run ")
-                << executing_task.pending_task.posted_from.ToString();
+      LOG(INFO) << "#" << static_cast<uint64_t>(task->enqueue_order()) << " "
+                << selected_work_queue->task_queue()->GetName()
+                << (task->cross_thread_ ? " Run crossthread " : " Run ")
+                << task->posted_from.ToString();
       break;
 
     case Settings::TaskLogging::kEnabledWithBacktrace: {
       std::array<const void*, PendingTask::kTaskBacktraceLength + 1> task_trace;
-      task_trace[0] = executing_task.pending_task.posted_from.program_counter();
-      std::copy(executing_task.pending_task.task_backtrace.begin(),
-                executing_task.pending_task.task_backtrace.end(),
+      task_trace[0] = task->posted_from.program_counter();
+      std::copy(task->task_backtrace.begin(), task->task_backtrace.end(),
                 task_trace.begin() + 1);
       size_t length = 0;
       while (length < task_trace.size() && task_trace[length])
         ++length;
       if (length == 0)
         break;
-      LOG(INFO) << "#"
-                << static_cast<uint64_t>(
-                       executing_task.pending_task.enqueue_order())
-                << " " << executing_task.task_queue_name
-                << (executing_task.pending_task.cross_thread_
-                        ? " Run crossthread "
-                        : " Run ")
+      LOG(INFO) << "#" << static_cast<uint64_t>(task->enqueue_order()) << " "
+                << selected_work_queue->task_queue()->GetName()
+                << (task->cross_thread_ ? " Run crossthread " : " Run ")
                 << debug::StackTrace(task_trace.data(), length);
       break;
     }
+
+    case Settings::TaskLogging::kReorderedOnly: {
+      std::vector<const Task*> skipped_tasks;
+      main_thread_only().selector.CollectSkippedOverLowerPriorityTasks(
+          selected_work_queue, &skipped_tasks);
+
+      if (skipped_tasks.empty())
+        break;
+
+      LOG(INFO) << "#" << static_cast<uint64_t>(task->enqueue_order()) << " "
+                << selected_work_queue->task_queue()->GetName()
+                << (task->cross_thread_ ? " Run crossthread " : " Run ")
+                << task->posted_from.ToString();
+
+      for (const Task* skipped_task : skipped_tasks) {
+        LOG(INFO) << "# (skipped over) "
+                  << static_cast<uint64_t>(skipped_task->enqueue_order()) << " "
+                  << skipped_task->posted_from.ToString();
+      }
+    }
   }
 }
 #endif  // DCHECK_IS_ON() && !defined(OS_NACL)
@@ -607,6 +615,10 @@ Optional<Task> SequenceManagerImpl::TakeTaskImpl() {
       return nullopt;
     }
 
+#if DCHECK_IS_ON() && !defined(OS_NACL)
+    LogTaskDebugInfo(work_queue);
+#endif  // DCHECK_IS_ON() && !defined(OS_NACL)
+
     main_thread_only().task_execution_stack.emplace_back(
         work_queue->TakeTaskFromWorkQueue(), work_queue->task_queue(),
         InitializeTaskTiming(work_queue->task_queue()));

base/task/sequence_manager/sequence_manager_impl.h

@@ -388,7 +388,7 @@ class BASE_EXPORT SequenceManagerImpl
   TimeDelta GetDelayTillNextDelayedTask(LazyNow* lazy_now) const;
 
 #if DCHECK_IS_ON()
-  void LogTaskDebugInfo(const ExecutingTask& executing_task);
+  void LogTaskDebugInfo(const internal::WorkQueue* work_queue) const;
 #endif
 
   // Determines if wall time or thread time should be recorded for the next

base/task/sequence_manager/task_queue_selector.cc

@@ -159,6 +159,15 @@ void TaskQueueSelector::WorkQueueSetBecameNonEmpty(size_t set_index) {
   }
 }
 
+void TaskQueueSelector::CollectSkippedOverLowerPriorityTasks(
+    const internal::WorkQueue* selected_work_queue,
+    std::vector<const Task*>* result) const {
+  delayed_work_queue_sets_.CollectSkippedOverLowerPriorityTasks(
+      selected_work_queue, result);
+  immediate_work_queue_sets_.CollectSkippedOverLowerPriorityTasks(
+      selected_work_queue, result);
+}
+
 #if DCHECK_IS_ON() || !defined(NDEBUG)
 bool TaskQueueSelector::CheckContainsQueueForTest(
     const internal::TaskQueueImpl* queue) const {

base/task/sequence_manager/task_queue_selector.h

@@ -76,6 +76,12 @@ class BASE_EXPORT TaskQueueSelector : public WorkQueueSets::Observer {
   void WorkQueueSetBecameEmpty(size_t set_index) override;
   void WorkQueueSetBecameNonEmpty(size_t set_index) override;
 
+  // Populates |result| with tasks with lower priority than the first task from
+  // |selected_work_queue| which could otherwise run now.
+  void CollectSkippedOverLowerPriorityTasks(
+      const internal::WorkQueue* selected_work_queue,
+      std::vector<const Task*>* result) const;
+
  protected:
   WorkQueueSets* delayed_work_queue_sets() { return &delayed_work_queue_sets_; }
 

base/task/sequence_manager/task_queue_selector_unittest.cc

@@ -762,6 +762,21 @@ TEST_F(TaskQueueSelectorTest, TestObserverWithTwoBlockedQueues) {
   task_queue2->UnregisterTaskQueue();
 }
 
+TEST_F(TaskQueueSelectorTest, CollectSkippedOverLowerPriorityTasks) {
+  size_t queue_order[] = {0, 1, 2, 3, 2, 1, 0};
+  PushTasks(queue_order, 7);
+  selector_.SetQueuePriority(task_queues_[3].get(), TaskQueue::kHighPriority);
+
+  std::vector<const Task*> result;
+  selector_.CollectSkippedOverLowerPriorityTasks(
+      task_queues_[3]->immediate_work_queue(), &result);
+
+  ASSERT_EQ(3u, result.size());
+  EXPECT_EQ(2u, result[0]->enqueue_order());  // The order here isn't important.
+  EXPECT_EQ(3u, result[1]->enqueue_order());
+  EXPECT_EQ(4u, result[2]->enqueue_order());
+}
+
 class DisabledAntiStarvationLogicTaskQueueSelectorTest
     : public TaskQueueSelectorTestBase,
       public testing::WithParamInterface<TaskQueue::QueuePriority> {

base/task/sequence_manager/work_queue.cc

@@ -305,6 +305,16 @@ void WorkQueue::PopTaskForTesting() {
   tasks_.pop_front();
 }
 
+void WorkQueue::CollectTasksOlderThan(EnqueueOrder reference,
+                                      std::vector<const Task*>* result) const {
+  for (const Task& task : tasks_) {
+    if (task.enqueue_order() >= reference)
+      break;
+
+    result->push_back(&task);
+  }
+}
+
 }  // namespace internal
 }  // namespace sequence_manager
 }  // namespace base

base/task/sequence_manager/work_queue.h

@@ -161,6 +161,11 @@ class BASE_EXPORT WorkQueue {
   // Test support function. This should not be used in production code.
   void PopTaskForTesting();
 
+  // Iterates through |tasks_| adding any that are older than |reference| to
+  // |result|.
+  void CollectTasksOlderThan(EnqueueOrder reference,
+                             std::vector<const Task*>* result) const;
+
  private:
   bool InsertFenceImpl(EnqueueOrder fence);
 

base/task/sequence_manager/work_queue_sets.cc

@@ -237,6 +237,19 @@ bool WorkQueueSets::ContainsWorkQueueForTest(
 }
 #endif
 
+void WorkQueueSets::CollectSkippedOverLowerPriorityTasks(
+    const internal::WorkQueue* selected_work_queue,
+    std::vector<const Task*>* result) const {
+  EnqueueOrder selected_enqueue_order;
+  CHECK(selected_work_queue->GetFrontTaskEnqueueOrder(&selected_enqueue_order));
+  for (size_t priority = selected_work_queue->work_queue_set_index() + 1;
+       priority < TaskQueue::kQueuePriorityCount; priority++) {
+    for (const OldestTaskEnqueueOrder& pair : work_queue_heaps_[priority]) {
+      pair.value->CollectTasksOlderThan(selected_enqueue_order, result);
+    }
+  }
+}
+
 }  // namespace internal
 }  // namespace sequence_manager
 }  // namespace base

base/task/sequence_manager/work_queue_sets.h

@@ -95,6 +95,12 @@ class BASE_EXPORT WorkQueueSets {
 
   const char* GetName() const { return name_; }
 
+  // Collects ready tasks which where skipped over when |selected_work_queue|
+  // was selected. Note this is somewhat expensive.
+  void CollectSkippedOverLowerPriorityTasks(
+      const internal::WorkQueue* selected_work_queue,
+      std::vector<const Task*>* result) const;
+
  private:
   struct OldestTaskEnqueueOrder {
     EnqueueOrder key;

base/task/sequence_manager/work_queue_sets_unittest.cc

@@ -331,6 +331,32 @@ TEST_F(WorkQueueSetsTest, PushNonNestableTaskToFront) {
   EXPECT_EQ(queue1, work_queue_sets_->GetOldestQueueInSet(set));
 }
 
+TEST_F(WorkQueueSetsTest, CollectSkippedOverLowerPriorityTasks) {
+  WorkQueue* queue1 = NewTaskQueue("queue1");
+  WorkQueue* queue2 = NewTaskQueue("queue2");
+  WorkQueue* queue3 = NewTaskQueue("queue3");
+
+  work_queue_sets_->ChangeSetIndex(queue1, 3);
+  work_queue_sets_->ChangeSetIndex(queue2, 2);
+  work_queue_sets_->ChangeSetIndex(queue3, 1);
+
+  queue1->Push(FakeTaskWithEnqueueOrder(1));
+  queue1->Push(FakeTaskWithEnqueueOrder(2));
+  queue2->Push(FakeTaskWithEnqueueOrder(3));
+  queue3->Push(FakeTaskWithEnqueueOrder(4));
+  queue3->Push(FakeTaskWithEnqueueOrder(5));
+  queue2->Push(FakeTaskWithEnqueueOrder(6));
+  queue1->Push(FakeTaskWithEnqueueOrder(7));
+
+  std::vector<const Task*> result;
+  work_queue_sets_->CollectSkippedOverLowerPriorityTasks(queue3, &result);
+
+  ASSERT_EQ(3u, result.size());
+  EXPECT_EQ(3u, result[0]->enqueue_order());  // The order here isn't important.
+  EXPECT_EQ(1u, result[1]->enqueue_order());
+  EXPECT_EQ(2u, result[2]->enqueue_order());
+}
+
 }  // namespace internal
 }  // namespace sequence_manager
 }  // namespace base

base/task/sequence_manager/work_queue_unittest.cc

@@ -555,6 +555,20 @@ TEST_F(WorkQueueTest, RemoveAllCanceledTasksFromFrontQueueBlockedByFence) {
   EXPECT_FALSE(work_queue_->GetFrontTaskEnqueueOrder(&enqueue_order));
 }
 
+TEST_F(WorkQueueTest, CollectTasksOlderThan) {
+  work_queue_->Push(FakeTaskWithEnqueueOrder(2));
+  work_queue_->Push(FakeTaskWithEnqueueOrder(3));
+  work_queue_->Push(FakeTaskWithEnqueueOrder(4));
+
+  std::vector<const Task*> result;
+  work_queue_->CollectTasksOlderThan(EnqueueOrder::FromIntForTesting(4),
+                                     &result);
+
+  ASSERT_EQ(2u, result.size());
+  EXPECT_EQ(2u, result[0]->enqueue_order());
+  EXPECT_EQ(3u, result[1]->enqueue_order());
+}
+
 }  // namespace internal
 }  // namespace sequence_manager
 }  // namespace base