WorkerThread CPU Load UMA

third_party/WebKit/Source/platform/scheduler/child/worker_scheduler_impl.cc

Index: third_party/WebKit/Source/platform/scheduler/child/worker_scheduler_impl.cc
diff --git a/third_party/WebKit/Source/platform/scheduler/child/worker_scheduler_impl.cc b/third_party/WebKit/Source/platform/scheduler/child/worker_scheduler_impl.cc
index 192502a38fbdd6b6a66a93484d365672c8370ad6..f9a555a58284efdb57c33a295dba7ac2b80ee8d8 100644
--- a/third_party/WebKit/Source/platform/scheduler/child/worker_scheduler_impl.cc
+++ b/third_party/WebKit/Source/platform/scheduler/child/worker_scheduler_impl.cc
@@ -5,14 +5,34 @@
 #include "platform/scheduler/child/worker_scheduler_impl.h"
 
 #include "base/bind.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/trace_event/trace_event.h"
 #include "base/trace_event/trace_event_argument.h"
-#include "public/platform/scheduler/base/task_queue.h"
+#include "platform/scheduler/base/time_converter.h"
 #include "platform/scheduler/child/scheduler_tqm_delegate.h"
+#include "public/platform/scheduler/base/task_queue.h"
 
 namespace blink {
 namespace scheduler {
 
+namespace {
+// Workers could be short-lived, set a shorter interval than
+// the renderer thread.
+constexpr base::TimeDelta kThreadLoadTrackerReportingInterval =
+    base::TimeDelta::FromSeconds(30);
+constexpr base::TimeDelta kThreadLoadTrackerWaitingPeriodBeforeReporting =
+    base::TimeDelta::FromSeconds(30);

[altimin, 2017/03/22 22:25:24]

I wonder if we should use lower windows for these intervals. 1 minute was fine
for main thread because we could rely on new tasks coming to the main thread. I
wonder if we should use something like 1 second here?

I also wonder if we need WaitingPeriodBeforeReporting here? (probably not).

[kinuko, 2017/03/23 05:42:32]

Matt, Hiroki- any thoughts here?  Shorter time makes sense to me in general.
I wondered the same-- Yeah maybe not.

[falken, 2017/03/23 06:48:05]

At first I was worried that a 1 second reporting interval would mean the worker
thread gets woken up every to record something every 1 second, but from code
inspection it looks like that is not the case; instead, the sample count just
increases when recording and the actual work done is not increased.

Do we reasonably expect the recording to happen on worker shutdown? For example,
if there is a dedicated worker that is running some heavy task indefinitely,
until the user closes the tab: would that be reflected in the histograms as 100%
load, or would we never get a chance to record something?

[kinuko, 2017/03/23 07:00:20]

Looking into the code it looks we can correctly log when the worker shuts down
(regardless of whether the shutdown was graceful or not), but if the worker
thread's life time tends to be shorter than the interval we'll lose a lot of
stats.

[kinuko, 2017/04/03 13:01:20]

Ok, from the UMA looks like about 85% of workers live ~1 sec (About 6~7% live
about 1 min and I assume they're SW cases), so setting this like 1 sec seems
like a reasonable decision.  I also set BeforeReporting interval to 0.

+
+void ReportWorkerTaskLoad(base::TimeTicks time, double load) {
+  int load_percentage = static_cast<int>(load * 100);
+  DCHECK_LE(load_percentage, 100);
+  // TODO(kinuko): Maybe we also want to separately log when the associated
+  // tab is in foreground and when not.
+  UMA_HISTOGRAM_PERCENTAGE("WorkerScheduler.WorkerThreadLoad", load_percentage);
+}
+
+}  // namespace
+
 WorkerSchedulerImpl::WorkerSchedulerImpl(
     scoped_refptr<SchedulerTqmDelegate> main_task_runner)
     : helper_(main_task_runner,
@@ -27,8 +47,14 @@ WorkerSchedulerImpl::WorkerSchedulerImpl(
                    base::TimeDelta::FromMilliseconds(300)),
       idle_canceled_delayed_task_sweeper_("worker.scheduler",
                                           &helper_,
-                                          idle_helper_.IdleTaskRunner()) {
+                                          idle_helper_.IdleTaskRunner()),
+      load_tracker_(helper_.scheduler_tqm_delegate()->NowTicks(),
+                    base::Bind(&ReportWorkerTaskLoad),
+                    kThreadLoadTrackerReportingInterval,
+                    kThreadLoadTrackerWaitingPeriodBeforeReporting) {
   initialized_ = false;
+  load_tracker_.Resume(helper_.scheduler_tqm_delegate()->NowTicks());
+  helper_.AddTaskTimeObserver(this);
   TRACE_EVENT_OBJECT_CREATED_WITH_ID(
       TRACE_DISABLED_BY_DEFAULT("worker.scheduler"), "WorkerScheduler", this);
 }
@@ -36,6 +62,7 @@ WorkerSchedulerImpl::WorkerSchedulerImpl(
 WorkerSchedulerImpl::~WorkerSchedulerImpl() {
   TRACE_EVENT_OBJECT_DELETED_WITH_ID(
       TRACE_DISABLED_BY_DEFAULT("worker.scheduler"), "WorkerScheduler", this);
+  helper_.RemoveTaskTimeObserver(this);
 }
 
 void WorkerSchedulerImpl::Init() {
@@ -77,6 +104,7 @@ void WorkerSchedulerImpl::RemoveTaskObserver(
 }
 
 void WorkerSchedulerImpl::Shutdown() {
+  load_tracker_.RecordIdle(helper_.scheduler_tqm_delegate()->NowTicks());
   DCHECK(initialized_);
   helper_.Shutdown();
 }
@@ -94,5 +122,18 @@ base::TimeTicks WorkerSchedulerImpl::CurrentIdleTaskDeadlineForTesting() const {
   return idle_helper_.CurrentIdleTaskDeadline();
 }
 
+void WorkerSchedulerImpl::willProcessTask(TaskQueue* task_queue,
+                                          double start_time) {}
+
+void WorkerSchedulerImpl::didProcessTask(TaskQueue* task_queue,
+                                         double start_time,
+                                         double end_time) {
+  base::TimeTicks start_time_ticks =
+      MonotonicTimeInSecondsToTimeTicks(start_time);
+  base::TimeTicks end_time_ticks = MonotonicTimeInSecondsToTimeTicks(end_time);

[kinuko, 2017/03/22 09:41:10]

I tried to make the code consistent here (i.e. using TaskTimeObserver and
MonotinicTimeInSecondsToTimeTicks conversion to get these) but let me know if
that's not the recommended way.

+
+  load_tracker_.RecordTaskTime(start_time_ticks, end_time_ticks);
+}
+
 }  // namespace scheduler
 }  // namespace blink