Report expected task queueing time via UMA

base/message_loop/message_loop.cc

Index: base/message_loop/message_loop.cc
diff --git a/base/message_loop/message_loop.cc b/base/message_loop/message_loop.cc
index 7038178079fc1619eec2366fc521c335f4fcadab..e3e8bf88f05bdf06099b7f2fc94b2b524aa1a287 100644
--- a/base/message_loop/message_loop.cc
+++ b/base/message_loop/message_loop.cc
@@ -123,6 +123,8 @@ MessageLoop::DestructionObserver::~DestructionObserver() {
 
 MessageLoop::NestingObserver::~NestingObserver() {}
 
+MessageLoop::RecentTimeObserver::~RecentTimeObserver() {}
+
 //------------------------------------------------------------------------------
 
 MessageLoop::MessageLoop(Type type)
@@ -275,6 +277,16 @@ void MessageLoop::RemoveNestingObserver(NestingObserver* observer) {
   nesting_observers_.RemoveObserver(observer);
 }
 
+void MessageLoop::AddRecentTimeObserver(RecentTimeObserver* observer) {
+  DCHECK_EQ(this, current());
+  recent_time_observers_.AddObserver(observer);
+}
+
+void MessageLoop::RemoveRecentTimeObserver(RecentTimeObserver* observer) {
+  DCHECK_EQ(this, current());
+  recent_time_observers_.RemoveObserver(observer);
+}
+
 void MessageLoop::PostTask(
     const tracked_objects::Location& from_here,
     const Closure& task) {
@@ -609,8 +621,13 @@ bool MessageLoop::DoWork() {
 }
 
 bool MessageLoop::DoDelayedWork(TimeTicks* next_delayed_work_time) {
+  recent_time_ = TimeTicks::Now();

[tdresser, 2016/05/30 19:07:46]

This is probably the scariest part of this patch.

We could make sure this only ran if there was a recent time observer.

This is only going to run once per pump of the message loop, which seems pretty
reasonable.

[panicker, 2016/06/07 19:58:02]

Looks like this is undoing the optimization added in cr/4247003 for overload
case (no concrete perf improvement numbers linked there though), and in addition
also calling Now() even when the work queue is empty.
However it seems like one could quantify the performance hit with running some
benchmarks?

[tdresser, 2016/06/07 20:23:16]

I'm not very worried about calling now even when the work queue is empty
(especially if we switch to only doing it when there's an observer). The
alternative is adding a timer that's running most of the time, which would incur
the same cost.

You're right that this undoes that optimization though (and leaves a bit of
essentially dead code).

Another option would be to have the MessagePump itself compute the current time
once per pump, and expose that widely.

+
+  FOR_EACH_OBSERVER(RecentTimeObserver, recent_time_observers_,
+                    OnUpdateRecentTime(recent_time_));

[panicker, 2016/06/07 19:58:02]

To me it seems iffy to call an override-able method here, future developers
could add arbitrarily complex / expensive code here.
Have you considered making this non-overridable?

(In that sense it is scarier than calling Now() - which is known fixed cost)

[tdresser, 2016/06/07 20:23:15]

It isn't completely clear to me how you'd make this non-overrideable. What would
the API look like? Another option would be to expose a global'ish getter, which
I thought looked a bit uglier.

[panicker, 2016/06/07 21:04:39]

Yeah a global-ish getter could work, although not pretty.
As a strawman: RecentTimeObserver could be stateful (atomic or locking needed)
and contain recent_time member with setter (called from here) and getter. Then
derived classes would observe latest recent_time from base class member.

+
   if (!nestable_tasks_allowed_ || delayed_work_queue_.empty()) {
-    recent_time_ = *next_delayed_work_time = TimeTicks();
+    *next_delayed_work_time = TimeTicks();
     return false;
   }
 
@@ -623,7 +640,6 @@ bool MessageLoop::DoDelayedWork(TimeTicks* next_delayed_work_time) {
 
   TimeTicks next_run_time = delayed_work_queue_.top().delayed_run_time;
   if (next_run_time > recent_time_) {
-    recent_time_ = TimeTicks::Now();  // Get a better view of Now();
     if (next_run_time > recent_time_) {
       *next_delayed_work_time = next_run_time;
       return false;