Report expected task queueing time via UMA

components/scheduler/renderer/queueing_time_estimator.cc

Index: components/scheduler/renderer/queueing_time_estimator.cc
diff --git a/components/scheduler/renderer/queueing_time_estimator.cc b/components/scheduler/renderer/queueing_time_estimator.cc
new file mode 100644
index 0000000000000000000000000000000000000000..0483614b3afb7078bee291ea74c95e88ac2ff5af
--- /dev/null
+++ b/components/scheduler/renderer/queueing_time_estimator.cc
@@ -0,0 +1,90 @@
+// Copyright 2016 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 "components/scheduler/renderer/queueing_time_estimator.h"
+
+#include "base/time/default_tick_clock.h"
+
+namespace scheduler {
+
+QueueingTimeEstimator::QueueingTimeEstimator(
+    QueueingTimeEstimator::QueueingTimeEstimatorClient* client,
+    base::TickClock* time_source,
+    base::TimeDelta window_duration)
+    : client_(client),
+      time_source_(time_source),
+      outstanding_task_count_(0),
+      window_duration_(window_duration),
+      window_start_time_(time_source->NowTicks()) {}
+
+QueueingTimeEstimator::~QueueingTimeEstimator() {}
+
+void QueueingTimeEstimator::WillProcessTask(
+    const base::PendingTask& pending_task) {
+  // Avoid measuring the duration in nested run loops.
+  if (++outstanding_task_count_ != 1)
+    return;
+
+  task_start_time_ = time_source_->NowTicks();
+}
+
+base::TimeDelta ExpectedQueueingTimeFromTask(base::TimeTicks task_start,

[Sami, 2016/04/20 09:51:27]

Could you move this into an unnamed namespace?

[tdresser, 2016/04/20 15:13:32]

Done.

+                                             base::TimeTicks task_end,
+                                             base::TimeTicks window_start,
+                                             base::TimeTicks window_end) {
+  DCHECK(task_start <= task_end);
+  DCHECK(window_start < window_end);

[Sami, 2016/04/20 09:51:27]

DCHECK(task_start <= window_end);
DCHECK(task_end >= window_start);

?

[tdresser, 2016/04/20 15:13:32]

Done.

+  base::TimeTicks task_in_window_start_time =
+      std::max(task_start, window_start);
+  base::TimeTicks task_in_window_end_time =
+      std::min(task_end, window_end);

[Sami, 2016/04/20 09:51:27]

DCHECK(start <= end)?

[tdresser, 2016/04/20 15:13:32]

Done.

+
+  double probability_of_this_task =

[Sami, 2016/04/20 09:51:27]

You could use, e.g., InMillisecondsF() to avoid the static_cast.

[tdresser, 2016/04/20 15:13:32]

Won't that cause loss of precision? Dividing both sides by
kMicrosecondsPerMillisecond seems unnecessary.

Let me know if you think the loss of precision isn't that important.

[Sami, 2016/04/21 10:04:01]

Good point, let's keep the code you have.

+      static_cast<double>((task_in_window_end_time - task_in_window_start_time)
+                              .InMicroseconds()) /
+      (window_end - window_start).InMicroseconds();
+
+  base::TimeDelta expected_queueing_duration_within_task =

[Sami, 2016/04/20 09:51:26]

I'm not sure I understand this equation. Shouldn't this just be the total length
of the task (minus any part that is before the start of the window) divided by
two?

[tdresser, 2016/04/20 15:13:32]

Here's an example where that doesn't work.
With a 5 second window, consider a 20 second task starting at the beginning of
the window.
Total length of task = 20 seconds.
Divided by 2 = 10 seconds.

But the expected queueing time is more than 10 seconds.

The queueing time at the start of the window is 20 seconds, and at the end of
the window is 15 seconds. Thus the expected queueing time is (20 + 15)/2 = 17.5
seconds.

[Sami, 2016/04/21 10:04:01]

Thanks for the explanation, that made it clear.

+      ((task_end - task_in_window_start_time) +
+       (task_end - task_in_window_end_time)) /
+      2;
+
+  return base::TimeDelta::FromMicroseconds(

[Sami, 2016/04/20 09:51:27]

FromMillisecondsD to avoid some truncation?

[tdresser, 2016/04/20 15:13:32]

Done.

+      probability_of_this_task *
+      expected_queueing_duration_within_task.InMicroseconds());

[Sami, 2016/04/20 09:51:27]

InMillisecondsF if you decide to make the above change.

[tdresser, 2016/04/20 15:13:32]

Done.

+}
+
+void QueueingTimeEstimator::DidProcessTask(
+    const base::PendingTask& pending_task) {
+  if (--outstanding_task_count_ != 0)
+    return;
+
+  bool start_past_window =
+      task_start_time_ > window_start_time_ + window_duration_;
+  bool end_past_window =
+      time_source_->NowTicks() > window_start_time_ + window_duration_;

[Sami, 2016/04/20 09:51:27]

We like to minimize the number of calls to Now() since it can be pretty
expensive. I suggest caching the snapshotted time at the start of this function
since this should be more or less instantaneous.

[tdresser, 2016/04/20 15:13:32]

Fixed. This is better from a readability perspective too.

+
+  while (end_past_window) {
+    if (!start_past_window) {
+      // Include the current task in this window.
+      current_expected_queueing_time_ += ExpectedQueueingTimeFromTask(
+          task_start_time_, time_source_->NowTicks(), window_start_time_,
+          window_start_time_ + window_duration_);
+    }
+    client_->OnQueueingTimeForWindowEstimated(current_expected_queueing_time_);
+    window_start_time_ += window_duration_;

[Sami, 2016/04/20 09:51:27]

We only really care about the window we are currently in, right? Could we make
this just compute that instead of working through the intermediate windows?
Usually this shouldn't be a problem but there are cases where we could be in a
very long running task which spans lots of windows (e.g., stopped on a JS
breakpoint, which IIRC spins a nested run loop).

[tdresser, 2016/04/20 15:13:32]

The intermediate windows definitely matter.

We need to sample regularly if we want to actually know what the expected time
is across multiple windows.

Given that the time window is 5 seconds, I doubt this should be an issue.

Based on your question about the formula, I suspect there's some confusion over
exactly what we're measuring. Does this make sense now?

[Sami, 2016/04/21 10:04:01]

Ah, I didn't realize the client was expected to sample multiple measurements.
Reporting intermediate windows makes sense then.

+    current_expected_queueing_time_ = base::TimeDelta();
+
+    start_past_window =
+        task_start_time_ > window_start_time_ + window_duration_;
+    end_past_window =
+        time_source_->NowTicks() > window_start_time_ + window_duration_;
+  }
+
+  current_expected_queueing_time_ += ExpectedQueueingTimeFromTask(
+      task_start_time_, time_source_->NowTicks(), window_start_time_,
+      window_start_time_ + window_duration_);
+}
+
+}  // namespace scheduler