[threadpool] Add switch to log BEST_EFFORT tasks.

When the --log-best-effort-tasks switch is specified, information about all tasks posted with BEST_EFFORT priority is logged. This is useful to diagnose issues with preventing BEST_EFFORT tasks from running during startup (and eventually during page load). Bug: 887407 Change-Id: I366a78485c1588741519c7254f8e1ab57d1df140 Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1660635 Reviewed-by: Avi Drissman <avi@chromium.org> Reviewed-by: Daniel Cheng <dcheng@chromium.org> Reviewed-by: Gabriel Charette <gab@chromium.org> Commit-Queue: François Doray <fdoray@chromium.org> Cr-Commit-Position: refs/heads/master@{#670886}
Denger-Network · Jun 20, 2019 · 177da2c · 177da2c
1 parent b023728
commit 177da2c
Show file tree

Hide file tree

Showing 16 changed files with 54 additions and 13 deletions.
diff --git a/PRESUBMIT.py b/PRESUBMIT.py
@@ -2198,6 +2198,7 @@ def _CheckSpamLogging(input_api, output_api):
                 input_api.DEFAULT_BLACK_LIST +
                 (r"^base[\\/]logging\.h$",
                  r"^base[\\/]logging\.cc$",
+                 r"^base[\\/]task[\\/]thread_pool[\\/]task_tracker\.cc$",
                  r"^chrome[\\/]app[\\/]chrome_main_delegate\.cc$",
                  r"^chrome[\\/]browser[\\/]chrome_browser_main\.cc$",
                  r"^chrome[\\/]browser[\\/]ui[\\/]startup[\\/]"

diff --git a/base/base_switches.cc b/base/base_switches.cc
@@ -43,6 +43,13 @@ const char kForceFieldTrials[]              = "force-fieldtrials";
 // Generates full memory crash dump.
 const char kFullMemoryCrashReport[] = "full-memory-crash-report";
 
+// Logs information about all tasks posted with TaskPriority::BEST_EFFORT. Use
+// this to diagnose issues that are thought to be caused by
+// TaskPriority::BEST_EFFORT execution fences. Note: Tasks posted to a
+// non-BEST_EFFORT UpdateableSequencedTaskRunner whose priority is later lowered
+// to BEST_EFFORT are not logged.
+const char kLogBestEffortTasks[] = "log-best-effort-tasks";
+
 // Suppresses all error dialogs when present.
 const char kNoErrorDialogs[]                = "noerrdialogs";
 

diff --git a/base/base_switches.h b/base/base_switches.h
@@ -20,6 +20,7 @@ extern const char kEnableFeatures[];
 extern const char kEnableLowEndDeviceMode[];
 extern const char kForceFieldTrials[];
 extern const char kFullMemoryCrashReport[];
+extern const char kLogBestEffortTasks[];
 extern const char kNoErrorDialogs[];
 extern const char kProfilingAtStart[];
 extern const char kProfilingFile[];

diff --git a/base/task/thread_pool/pooled_single_thread_task_runner_manager.cc b/base/task/thread_pool/pooled_single_thread_task_runner_manager.cc
@@ -143,6 +143,7 @@ class WorkerThreadDelegate : public WorkerThread::Delegate {
     auto registered_task_source = task_tracker_->WillQueueTaskSource(sequence);
     if (!registered_task_source)
       return false;
+    task_tracker_->WillPostTaskNow(task, transaction.traits().priority());
     transaction.PushTask(std::move(task));
     bool should_wakeup = EnqueueTaskSource(
         {std::move(registered_task_source), std::move(transaction)});

diff --git a/base/task/thread_pool/pooled_single_thread_task_runner_manager_unittest.cc b/base/task/thread_pool/pooled_single_thread_task_runner_manager_unittest.cc
@@ -69,7 +69,7 @@ class PooledSingleThreadTaskRunnerManagerTest : public testing::Test {
   }
 
   Thread service_thread_;
-  TaskTracker task_tracker_ = {"Test"};
+  TaskTracker task_tracker_{"Test"};
   DelayedTaskManager delayed_task_manager_;
   std::unique_ptr<PooledSingleThreadTaskRunnerManager>
       single_thread_task_runner_manager_;

diff --git a/base/task/thread_pool/task_tracker.cc b/base/task/thread_pool/task_tracker.cc
@@ -8,7 +8,9 @@
 #include <string>
 #include <vector>
 
+#include "base/base_switches.h"
 #include "base/callback.h"
+#include "base/command_line.h"
 #include "base/compiler_specific.h"
 #include "base/debug/alias.h"
 #include "base/json/json_writer.h"
@@ -138,6 +140,14 @@ TaskShutdownBehavior GetEffectiveShutdownBehavior(const TaskTraits& traits,
   return shutdown_behavior;
 }
 
+bool HasLogBestEffortTasksSwitch() {
+  // The CommandLine might not be initialized if ThreadPool is initialized in a
+  // dynamic library which doesn't have access to argc/argv.
+  return CommandLine::InitializedForCurrentProcess() &&
+         CommandLine::ForCurrentProcess()->HasSwitch(
+             switches::kLogBestEffortTasks);
+}
+
 }  // namespace
 
 // Atomic internal state used by TaskTracker to track items that are blocking
@@ -232,7 +242,8 @@ class TaskTracker::State {
 
 // TODO(jessemckenna): Write a helper function to avoid code duplication below.
 TaskTracker::TaskTracker(StringPiece histogram_label)
-    : state_(new State),
+    : has_log_best_effort_tasks_switch_(HasLogBestEffortTasksSwitch()),
+      state_(new State),
       can_run_policy_(CanRunPolicy::kAll),
       flush_cv_(flush_lock_.CreateConditionVariable()),
       shutdown_lock_(&flush_lock_),
@@ -408,6 +419,14 @@ bool TaskTracker::WillPostTask(Task* task,
   return true;
 }
 
+void TaskTracker::WillPostTaskNow(const Task& task, TaskPriority priority) {
+  if (has_log_best_effort_tasks_switch_ &&
+      priority == TaskPriority::BEST_EFFORT) {
+    // A TaskPriority::BEST_EFFORT task is being posted.
+    LOG(INFO) << task.posted_from.ToString();
+  }
+}
+
 RegisteredTaskSource TaskTracker::WillQueueTaskSource(
     scoped_refptr<TaskSource> task_source) {
   DCHECK(task_source);

diff --git a/base/task/thread_pool/task_tracker.h b/base/task/thread_pool/task_tracker.h
@@ -93,11 +93,16 @@ class BASE_EXPORT TaskTracker {
   void SetCanRunPolicy(CanRunPolicy can_run_policy);
 
   // Informs this TaskTracker that |task| with |shutdown_behavior| is about to
-  // be posted to a task source. Returns true if this operation is allowed
-  // (|task| should be pushed into its task source if-and-only-if it is). This
-  // method may also modify metadata on |task| if desired.
+  // be pushed to a task source (if non-delayed) or be added to the
+  // DelayedTaskManager (if delayed). Returns true if this operation is allowed
+  // (the operation should be performed if-and-only-if it is). This method may
+  // also modify metadata on |task| if desired.
   bool WillPostTask(Task* task, TaskShutdownBehavior shutdown_behavior);
 
+  // Informs this TaskTracker that |task| that is about to be pushed to a task
+  // source with |priority|.
+  void WillPostTaskNow(const Task& task, TaskPriority priority);
+
   // Informs this TaskTracker that |task_source| is about to be queued. Returns
   // a RegisteredTaskSource that should be queued if-and-only-if it evaluates to
   // true.
@@ -225,6 +230,10 @@ class BASE_EXPORT TaskTracker {
 
   TaskAnnotator task_annotator_;
 
+  // Indicates whether logging information about TaskPriority::BEST_EFFORT tasks
+  // was enabled with a command line switch.
+  const bool has_log_best_effort_tasks_switch_;
+
   // Number of tasks blocking shutdown and boolean indicating whether shutdown
   // has started.
   const std::unique_ptr<State> state_;

diff --git a/base/task/thread_pool/task_tracker_posix_unittest.cc b/base/task/thread_pool/task_tracker_posix_unittest.cc
@@ -42,7 +42,7 @@ class ThreadPoolTaskTrackerPosixTest : public testing::Test {
 
  protected:
   Thread service_thread_;
-  TaskTrackerPosix tracker_ = {"Test"};
+  TaskTrackerPosix tracker_{"Test"};
 
  private:
   DISALLOW_COPY_AND_ASSIGN(ThreadPoolTaskTrackerPosixTest);

diff --git a/base/task/thread_pool/task_tracker_unittest.cc b/base/task/thread_pool/task_tracker_unittest.cc
@@ -228,7 +228,7 @@ class ThreadPoolTaskTrackerTest
     return num_tasks_executed_;
   }
 
-  TaskTracker tracker_ = {"Test"};
+  TaskTracker tracker_{"Test"};
 
  private:
   void RunTaskCallback() {

diff --git a/base/task/thread_pool/thread_group_impl_unittest.cc b/base/task/thread_pool/thread_group_impl_unittest.cc
@@ -119,7 +119,7 @@ class ThreadGroupImplImplTestBase : public ThreadGroup::Delegate {
   }
 
   Thread service_thread_;
-  TaskTracker task_tracker_ = {"Test"};
+  TaskTracker task_tracker_{"Test"};
   std::unique_ptr<ThreadGroupImpl> thread_group_;
   DelayedTaskManager delayed_task_manager_;
   TrackedRefFactory<ThreadGroup::Delegate> tracked_ref_factory_;

diff --git a/base/task/thread_pool/thread_group_unittest.cc b/base/task/thread_pool/thread_group_unittest.cc
@@ -172,7 +172,7 @@ class ThreadGroupTest : public testing::TestWithParam<PoolExecutionType>,
   }
 
   Thread service_thread_;
-  TaskTracker task_tracker_ = {"Test"};
+  TaskTracker task_tracker_{"Test"};
   DelayedTaskManager delayed_task_manager_;
   test::MockPooledTaskRunnerDelegate mock_pooled_task_runner_delegate_ = {
       task_tracker_.GetTrackedRef(), &delayed_task_manager_};

diff --git a/base/task/thread_pool/thread_pool_impl.cc b/base/task/thread_pool/thread_pool_impl.cc
@@ -52,8 +52,8 @@ constexpr int kMaxBestEffortTasks = 2;
 
 // Indicates whether BEST_EFFORT tasks are disabled by a command line switch.
 bool HasDisableBestEffortTasksSwitch() {
-  // The CommandLine might not be initialized if TaskScheduler is initialized
-  // in a dynamic library which doesn't have access to argc/argv.
+  // The CommandLine might not be initialized if ThreadPool is initialized in a
+  // dynamic library which doesn't have access to argc/argv.
   return CommandLine::InitializedForCurrentProcess() &&
          CommandLine::ForCurrentProcess()->HasSwitch(
              switches::kDisableBestEffortTasks);
@@ -332,6 +332,7 @@ bool ThreadPoolImpl::PostTaskWithSequenceNow(Task task,
     if (!task_source)
       return false;
   }
+  task_tracker_->WillPostTaskNow(task, transaction.traits().priority());
   transaction.PushTask(std::move(task));
   if (task_source) {
     const TaskTraits traits = transaction.traits();

diff --git a/base/task/thread_pool/worker_thread_stack_unittest.cc b/base/task/thread_pool/worker_thread_stack_unittest.cc
@@ -52,7 +52,7 @@ class ThreadPoolWorkerStackTest : public testing::Test {
   }
 
  private:
-  TaskTracker task_tracker_ = {"Test"};
+  TaskTracker task_tracker_{"Test"};
 
  protected:
   scoped_refptr<WorkerThread> worker_a_;

diff --git a/base/task/thread_pool/worker_thread_unittest.cc b/base/task/thread_pool/worker_thread_unittest.cc
@@ -261,7 +261,7 @@ class ThreadPoolWorkerTest : public testing::TestWithParam<int> {
     EXPECT_LE(num_run_tasks_, created_sequences_.size());
   }
 
-  TaskTracker task_tracker_ = {"Test"};
+  TaskTracker task_tracker_{"Test"};
 
   // Synchronizes access to all members below.
   mutable CheckedLock lock_;

diff --git a/content/browser/browser_child_process_host_impl.cc b/content/browser/browser_child_process_host_impl.cc
@@ -321,6 +321,7 @@ void BrowserChildProcessHostImpl::LaunchWithoutExtraCommandLineSwitches(
       switches::kDisablePerfetto,
       switches::kEnableLogging,
       switches::kIPCConnectionTimeout,
+      switches::kLogBestEffortTasks,
       switches::kLogFile,
       switches::kLoggingLevel,
       switches::kTraceToConsole,

diff --git a/content/browser/renderer_host/render_process_host_impl.cc b/content/browser/renderer_host/render_process_host_impl.cc
@@ -3012,6 +3012,7 @@ void RenderProcessHostImpl::PropagateBrowserCommandLineToRenderer(
     switches::kIPCConnectionTimeout,
     switches::kJavaScriptFlags,
     switches::kLitePagesServerSubresourceHost,
+    switches::kLogBestEffortTasks,
     switches::kLogFile,
     switches::kLoggingLevel,
     switches::kMaxActiveWebGLContexts,