Report expected task queueing time via UMA

base/message_loop/message_loop.cc

 // Copyright 2013 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 "base/message_loop/message_loop.h"
 
 #include <algorithm>
 #include <memory>
 #include <utility>
 
@@ skipping 105 matching lines @@
 }
 
 MessageLoop::TaskObserver::~TaskObserver() {
 }
 
 MessageLoop::DestructionObserver::~DestructionObserver() {
 }
 
 MessageLoop::NestingObserver::~NestingObserver() {}
 
+MessageLoop::RecentTimeObserver::~RecentTimeObserver() {}
+
 //------------------------------------------------------------------------------
 
 MessageLoop::MessageLoop(Type type)
     : MessageLoop(type, MessagePumpFactoryCallback()) {
   BindToCurrentThread();
 }
 
 MessageLoop::MessageLoop(std::unique_ptr<MessagePump> pump)
     : MessageLoop(TYPE_CUSTOM, Bind(&ReturnPump, Passed(&pump))) {
   BindToCurrentThread();
@@ skipping 132 matching lines @@
 void MessageLoop::AddNestingObserver(NestingObserver* observer) {
   DCHECK_EQ(this, current());
   nesting_observers_.AddObserver(observer);
 }
 
 void MessageLoop::RemoveNestingObserver(NestingObserver* observer) {
   DCHECK_EQ(this, current());
   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) {
   task_runner_->PostTask(from_here, task);
 }
 
 void MessageLoop::PostDelayedTask(
     const tracked_objects::Location& from_here,
     const Closure& task,
     TimeDelta delay) {
@@ skipping 314 matching lines @@
           return true;
       }
     } while (!work_queue_.empty());
   }
 
   // Nothing happened.
   return false;
 }
 
 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;
   }
 
   // When we "fall behind", there will be a lot of tasks in the delayed work
   // queue that are ready to run.  To increase efficiency when we fall behind,
   // we will only call Time::Now() intermittently, and then process all tasks
   // that are ready to run before calling it again.  As a result, the more we
   // fall behind (and have a lot of ready-to-run delayed tasks), the more
   // efficient we'll be at handling the tasks.
 
   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;
     }
   }
 
   PendingTask pending_task = delayed_work_queue_.top();
   delayed_work_queue_.pop();
 
   if (!delayed_work_queue_.empty())
@@ skipping 103 matching lines @@
       persistent,
       mode,
       controller,
       delegate);
 }
 #endif
 
 #endif  // !defined(OS_NACL_SFI)
 
 }  // namespace base