Add instrumentation to the MessagePumpMac family of classes.

This adds UMA-uploaded histograms of sampling intervals for key points of data:
* Total time spent in a CFRunLoop
* Total time waiting in CFRunLoop
* Total time servicing MessagePump::Delegate (the MessageLoop)
* The MessageLoop queue size and queueing delay before servicing

It adds 1 second sampling for 15 seconds at startup, only for the main thread
(NSApplication-based) run loops.

The data will be used to determine if adding scheduling-like behavior to the
MessagePump will result in more efficient processing of the MessageLoop work.

An unforunate side effect of this change is exposing another method on the
MessagePump::Delegate interface, but there does not appear to be a better way
to do this.

BUG=264886
R=jar@chromium.org, mark@chromium.org

Review URL: https://codereview.chromium.org/22911026

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@221427 0039d316-1c4b-4281-b951-d872f2087c98

base/message_loop/message_loop.cc

@@ -660,6 +660,20 @@ bool MessageLoop::DoIdleWork() {
   return false;
 }
 
+void MessageLoop::GetQueueingInformation(size_t* queue_size,
+                                         TimeDelta* queueing_delay) {
+  *queue_size = work_queue_.size();
+  if (*queue_size == 0) {
+    *queueing_delay = TimeDelta();
+    return;
+  }
+
+  const PendingTask& next_to_run = work_queue_.front();
+  tracked_objects::Duration duration =
+      tracked_objects::TrackedTime::Now() - next_to_run.EffectiveTimePosted();
+  *queueing_delay = TimeDelta::FromMilliseconds(duration.InMilliseconds());
+}
+
 void MessageLoop::DeleteSoonInternal(const tracked_objects::Location& from_here,
                                      void(*deleter)(const void*),
                                      const void* object) {

base/message_loop/message_loop.h

@@ -478,6 +478,8 @@ class BASE_EXPORT MessageLoop : public MessagePump::Delegate {
   virtual bool DoWork() OVERRIDE;
   virtual bool DoDelayedWork(TimeTicks* next_delayed_work_time) OVERRIDE;
   virtual bool DoIdleWork() OVERRIDE;
+  virtual void GetQueueingInformation(size_t* queue_size,
+                                      TimeDelta* queueing_delay) OVERRIDE;
 
   Type type_;
 

base/message_loop/message_pump.h

@@ -6,10 +6,12 @@
 #define BASE_MESSAGE_LOOP_MESSAGE_PUMP_H_
 
 #include "base/base_export.h"
+#include "base/basictypes.h"
 #include "base/threading/non_thread_safe.h"
 
 namespace base {
 
+class TimeDelta;
 class TimeTicks;
 
 class BASE_EXPORT MessagePump : public NonThreadSafe {
@@ -39,6 +41,19 @@ class BASE_EXPORT MessagePump : public NonThreadSafe {
     // Called from within Run just before the message pump goes to sleep.
     // Returns true to indicate that idle work was done.
     virtual bool DoIdleWork() = 0;
+
+    // Via the two required out pointers, returns the length of the Delegate's
+    // work queue and the length of time that the first item in the queue has
+    // been waiting to run. If the work queue is empty, the count and delay
+    // will both be zero.
+    // Note that this only counts the tasks in the ready-to-run queue and not
+    // the incoming queue that is used by other threads to post tasks. The
+    // latter queue requires holding a lock, which is deemed too expensive for
+    // instrumentation code. Under normal conditions, the incoming queue should
+    // be small or zero, but under heavy loads it may be much larger and
+    // |queue_count| may be up to 1/4 the size of the incoming queue.
+    virtual void GetQueueingInformation(size_t* queue_count,
+                                        TimeDelta* queueing_delay) {}
   };
 
   MessagePump();

base/message_loop/message_pump_mac.h

@@ -36,6 +36,8 @@
 
 #include <CoreFoundation/CoreFoundation.h>
 
+#include "base/memory/weak_ptr.h"
+
 #if !defined(__OBJC__)
 class NSAutoreleasePool;
 #else  // !defined(__OBJC__)
@@ -57,6 +59,7 @@ class NSAutoreleasePool;
 
 namespace base {
 
+class MessagePumpInstrumentation;
 class RunLoop;
 class TimeTicks;
 
@@ -93,6 +96,11 @@ class MessagePumpCFRunLoopBase : public MessagePump {
   // objects autoreleased by work to fall into the current autorelease pool.
   virtual NSAutoreleasePool* CreateAutoreleasePool();
 
+  // Enables instrumentation of the MessagePump. See MessagePumpInstrumentation
+  // in the implementation for details.
+  void EnableInstrumentation();
+  WeakPtr<MessagePumpInstrumentation> instrumentation_;
+
  private:
   // Timer callback scheduled by ScheduleDelayedWork.  This does not do any
   // work, but it signals work_source_ so that delayed work can be performed
@@ -106,11 +114,11 @@ class MessagePumpCFRunLoopBase : public MessagePump {
   static void RunWorkSource(void* info);
   bool RunWork();
 
-  // Perform idle-priority work.  This is normally called by PreWaitObserver,
-  // but is also associated with idle_work_source_.  When this function
-  // actually does perform idle work, it will resignal that source.  The
-  // static method calls the instance method; the instance method returns
-  // true if idle work was done.
+  // Perform idle-priority work.  This is normally called by
+  // StartOrEndWaitObserver, but is also associated with idle_work_source_. When
+  // this function actually does perform idle work, it will resignal that
+  // source.  The static method calls the instance method; the instance method
+  // returns true if idle work was done.
   static void RunIdleWorkSource(void* info);
   bool RunIdleWork();
 
@@ -132,8 +140,8 @@ class MessagePumpCFRunLoopBase : public MessagePump {
 
   // Observer callback responsible for performing idle-priority work, before
   // the run loop goes to sleep.  Associated with idle_work_observer_.
-  static void PreWaitObserver(CFRunLoopObserverRef observer,
-                              CFRunLoopActivity activity, void* info);
+  static void StartOrEndWaitObserver(CFRunLoopObserverRef observer,
+                                     CFRunLoopActivity activity, void* info);
 
   // Observer callback called before the run loop processes any sources.
   // Associated with pre_source_observer_.

base/message_loop/message_pump_mac.mm

@@ -7,9 +7,14 @@
 #import <Foundation/Foundation.h>
 
 #include <limits>
+#include <stack>
 
+#include "base/format_macros.h"
 #include "base/logging.h"
+#include "base/mac/scoped_cftyperef.h"
+#include "base/metrics/histogram.h"
 #include "base/run_loop.h"
+#include "base/strings/stringprintf.h"
 #include "base/time/time.h"
 
 #if !defined(OS_IOS)
@@ -51,6 +56,228 @@ class MessagePumpScopedAutoreleasePool {
   DISALLOW_COPY_AND_ASSIGN(MessagePumpScopedAutoreleasePool);
 };
 
+// This class is used to instrument the MessagePump to gather various timing
+// data about when the underlying run loop is entered, when it is waiting, and
+// when it is servicing its delegate.
+//
+// The metrics are gathered as UMA-tracked histograms. To gather the data over
+// time, sampling is used, such that a new histogram is created for each metric
+// every |sampling_interval| for |sampling_duration|. After sampling is
+// complete, this class deletes itself.
+class MessagePumpInstrumentation {
+ public:
+  // Creates an instrument for the MessagePump on the current thread. Every
+  // |sampling_interval|, a new histogram will be created to track the metrics
+  // over time. After |sampling_duration|, this will delete itself, causing the
+  // WeakPtr to go NULL.
+  static WeakPtr<MessagePumpInstrumentation> Create(
+      const TimeDelta& sampling_interval,
+      const TimeDelta& sampling_duration) {
+    MessagePumpInstrumentation* instrument =
+        new MessagePumpInstrumentation(sampling_interval, sampling_duration);
+    return instrument->weak_ptr_factory_.GetWeakPtr();
+  }
+
+  // Starts the timer that runs the sampling instrumentation. Can be called
+  // multiple times as a noop.
+  void StartIfNeeded() {
+    if (timer_)
+      return;
+
+    sampling_start_time_ = generation_start_time_ = TimeTicks::Now();
+
+    CFRunLoopTimerContext timer_context = { .info = this };
+    timer_.reset(CFRunLoopTimerCreate(
+        NULL,  // allocator
+        (Time::Now() + sampling_interval_).ToCFAbsoluteTime(),
+        sampling_interval_.InSecondsF(),
+        0,  // flags
+        0,  // order
+        &MessagePumpInstrumentation::TimerFired,
+        &timer_context));
+    CFRunLoopAddTimer(CFRunLoopGetCurrent(),
+                      timer_,
+                      kCFRunLoopCommonModes);
+  }
+
+  // Used to track kCFRunLoopEntry.
+  void LoopEntered() {
+    loop_run_times_.push(TimeTicks::Now());
+  }
+
+  // Used to track kCFRunLoopExit.
+  void LoopExited() {
+    TimeDelta duration = TimeTicks::Now() - loop_run_times_.top();
+    loop_run_times_.pop();
+    GetHistogram(LOOP_CYCLE)->AddTime(duration);
+  }
+
+  // Used to track kCFRunLoopBeforeWaiting.
+  void WaitingStarted() {
+    loop_wait_times_.push(TimeTicks::Now());
+  }
+
+  // Used to track kCFRunLoopAfterWaiting.
+  void WaitingFinished() {
+    TimeDelta duration = TimeTicks::Now() - loop_wait_times_.top();
+    loop_wait_times_.pop();
+    GetHistogram(LOOP_WAIT)->AddTime(duration);
+  }
+
+  // Used to track when the MessagePump will invoke its |delegate|.
+  void WorkSourceEntered(MessagePump::Delegate* delegate) {
+    work_source_times_.push(TimeTicks::Now());
+    if (delegate) {
+      size_t queue_size;
+      TimeDelta queuing_delay;
+      delegate->GetQueueingInformation(&queue_size, &queuing_delay);
+      GetHistogram(QUEUE_SIZE)->Add(queue_size);
+      GetHistogram(QUEUE_DELAY)->AddTime(queuing_delay);
+    }
+  }
+
+  // Used to track the completion of servicing the MessagePump::Delegate.
+  void WorkSourceExited() {
+    TimeDelta duration = TimeTicks::Now() - work_source_times_.top();
+    work_source_times_.pop();
+    GetHistogram(WORK_SOURCE)->AddTime(duration);
+  }
+
+ private:
+  enum HistogramEvent {
+    // Time-based histograms:
+    LOOP_CYCLE,  // LoopEntered/LoopExited
+    LOOP_WAIT,  // WaitingStarted/WaitingEnded
+    WORK_SOURCE,  // WorkSourceExited
+    QUEUE_DELAY,  // WorkSourceEntered
+
+    // Value-based histograms:
+    // NOTE: Do not add value-based histograms before this event, only after.
+    QUEUE_SIZE,  // WorkSourceEntered
+
+    HISTOGRAM_EVENT_MAX,
+  };
+
+  MessagePumpInstrumentation(const TimeDelta& sampling_interval,
+                             const TimeDelta& sampling_duration)
+      : weak_ptr_factory_(this),
+        sampling_interval_(sampling_interval),
+        sampling_duration_(sampling_duration),
+        sample_generation_(0) {
+    // Create all the histogram objects that will be used for sampling.
+    const char kHistogramName[] = "MessagePumpMac.%s.SampleMs.%" PRId64;
+    for (TimeDelta i; i < sampling_duration_; i += sampling_interval_) {
+      int64 sample = i.InMilliseconds();
+
+      // Generate the time-based histograms.
+      for (int j = LOOP_CYCLE; j < QUEUE_SIZE; ++j) {
+        std::string name = StringPrintf(kHistogramName,
+            NameForEnum(static_cast<HistogramEvent>(j)), sample);
+        histograms_[j].push_back(
+            Histogram::FactoryTimeGet(name, TimeDelta::FromMilliseconds(1),
+                sampling_interval_, 50,
+                HistogramBase::kUmaTargetedHistogramFlag));
+      }
+
+      // Generate the value-based histograms.
+      for (int j = QUEUE_SIZE; j < HISTOGRAM_EVENT_MAX; ++j) {
+        std::string name = StringPrintf(kHistogramName,
+            NameForEnum(static_cast<HistogramEvent>(j)), sample);
+        histograms_[j].push_back(
+            Histogram::FactoryGet(name, 1, 10000, 50,
+                HistogramBase::kUmaTargetedHistogramFlag));
+      }
+    }
+  }
+
+  ~MessagePumpInstrumentation() {
+    if (timer_)
+      CFRunLoopTimerInvalidate(timer_);
+  }
+
+  const char* NameForEnum(HistogramEvent event) {
+    switch (event) {
+      case LOOP_CYCLE: return "LoopCycle";
+      case LOOP_WAIT: return "Waiting";
+      case WORK_SOURCE: return "WorkSource";
+      case QUEUE_DELAY: return "QueueingDelay";
+      case QUEUE_SIZE: return "QueueSize";
+      default:
+        NOTREACHED();
+        return NULL;
+    }
+  }
+
+  static void TimerFired(CFRunLoopTimerRef timer, void* context) {
+    static_cast<MessagePumpInstrumentation*>(context)->TimerFired();
+  }
+
+  // Called by the run loop when the sampling_interval_ has elapsed. Advances
+  // the sample_generation_, which controls into which histogram data is
+  // recorded, while recording and accounting for timer skew. Will delete this
+  // object after |sampling_duration_| has elapsed.
+  void TimerFired() {
+    TimeTicks now = TimeTicks::Now();
+    TimeDelta delta = now - generation_start_time_;
+
+    // The timer fired, so advance the generation by at least one.
+    ++sample_generation_;
+
+    // To account for large timer skew/drift, advance the generation by any
+    // more completed intervals.
+    for (TimeDelta skew_advance = delta - sampling_interval_;
+         skew_advance >= sampling_interval_;
+         skew_advance -= sampling_interval_) {
+      ++sample_generation_;
+    }
+
+    generation_start_time_ = now;
+    if (now >= sampling_start_time_ + sampling_duration_)
+      delete this;
+  }
+
+  HistogramBase* GetHistogram(HistogramEvent event) {
+    DCHECK_LT(sample_generation_, histograms_[event].size());
+    return histograms_[event][sample_generation_];
+  }
+
+  // Vends the pointer to the Create()or.
+  WeakPtrFactory<MessagePumpInstrumentation> weak_ptr_factory_;
+
+  // The interval and duration of the sampling.
+  TimeDelta sampling_interval_;
+  TimeDelta sampling_duration_;
+
+  // The time at which sampling started.
+  TimeTicks sampling_start_time_;
+
+  // The timer that advances the sample_generation_ and sets the
+  // generation_start_time_ for the current sample interval.
+  base::ScopedCFTypeRef<CFRunLoopTimerRef> timer_;
+
+  // The two-dimensional array of histograms. The first dimension is the
+  // HistogramEvent type. The second is for the sampling intervals.
+  std::vector<HistogramBase*> histograms_[HISTOGRAM_EVENT_MAX];
+
+  // The index in the second dimension of histograms_, which controls in which
+  // sampled histogram events are recorded.
+  size_t sample_generation_;
+
+  // The last time at which the timer fired. This is used to track timer skew
+  // (i.e. it did not fire on time) and properly account for it when advancing
+  // samle_generation_.
+  TimeTicks generation_start_time_;
+
+  // MessagePump activations can be nested. Use a stack for each of the
+  // possibly reentrant HistogramEvent types to properly balance and calculate
+  // the timing information.
+  std::stack<TimeTicks> loop_run_times_;
+  std::stack<TimeTicks> loop_wait_times_;
+  std::stack<TimeTicks> work_source_times_;
+
+  DISALLOW_COPY_AND_ASSIGN(MessagePumpInstrumentation);
+};
+
 // Must be called on the run loop thread.
 MessagePumpCFRunLoopBase::MessagePumpCFRunLoopBase()
     : delegate_(NULL),
@@ -101,10 +328,11 @@ MessagePumpCFRunLoopBase::MessagePumpCFRunLoopBase()
   CFRunLoopObserverContext observer_context = CFRunLoopObserverContext();
   observer_context.info = this;
   pre_wait_observer_ = CFRunLoopObserverCreate(NULL,  // allocator
-                                               kCFRunLoopBeforeWaiting,
+                                               kCFRunLoopBeforeWaiting |
+                                                  kCFRunLoopAfterWaiting,
                                                true,  // repeat
                                                0,     // priority
-                                               PreWaitObserver,
+                                               StartOrEndWaitObserver,
                                                &observer_context);
   CFRunLoopAddObserver(run_loop_, pre_wait_observer_, kCFRunLoopCommonModes);
 
@@ -193,6 +421,11 @@ void MessagePumpCFRunLoopBase::SetDelegate(Delegate* delegate) {
   }
 }
 
+void MessagePumpCFRunLoopBase::EnableInstrumentation() {
+  instrumentation_ = MessagePumpInstrumentation::Create(
+      TimeDelta::FromSeconds(1), TimeDelta::FromSeconds(15));
+}
+
 // May be called on any thread.
 void MessagePumpCFRunLoopBase::ScheduleWork() {
   CFRunLoopSourceSignal(work_source_);
@@ -240,6 +473,9 @@ bool MessagePumpCFRunLoopBase::RunWork() {
     return false;
   }
 
+  if (instrumentation_)
+    instrumentation_->WorkSourceEntered(delegate_);
+
   // The NSApplication-based run loop only drains the autorelease pool at each
   // UI event (NSEvent).  The autorelease pool is not drained for each
   // CFRunLoopSource target that's run.  Use a local pool for any autoreleased
@@ -279,6 +515,9 @@ bool MessagePumpCFRunLoopBase::RunWork() {
     CFRunLoopSourceSignal(work_source_);
   }
 
+  if (instrumentation_)
+    instrumentation_->WorkSourceExited();
+
   return resignal_work_source;
 }
 
@@ -363,11 +602,18 @@ void MessagePumpCFRunLoopBase::MaybeScheduleNestingDeferredWork() {
 
 // Called from the run loop.
 // static
-void MessagePumpCFRunLoopBase::PreWaitObserver(CFRunLoopObserverRef observer,
-                                               CFRunLoopActivity activity,
-                                               void* info) {
+void MessagePumpCFRunLoopBase::StartOrEndWaitObserver(
+    CFRunLoopObserverRef observer,
+    CFRunLoopActivity activity,
+    void* info) {
   MessagePumpCFRunLoopBase* self = static_cast<MessagePumpCFRunLoopBase*>(info);
 
+  if (activity == kCFRunLoopAfterWaiting) {
+    if (self->instrumentation_)
+      self->instrumentation_->WaitingFinished();
+    return;
+  }
+
   // Attempt to do some idle work before going to sleep.
   self->RunIdleWork();
 
@@ -376,6 +622,9 @@ void MessagePumpCFRunLoopBase::PreWaitObserver(CFRunLoopObserverRef observer,
   // nesting-deferred work may have accumulated.  Schedule it for processing
   // if appropriate.
   self->MaybeScheduleNestingDeferredWork();
+
+  if (self->instrumentation_)
+    self->instrumentation_->WaitingStarted();
 }
 
 // Called from the run loop.
@@ -402,6 +651,9 @@ void MessagePumpCFRunLoopBase::EnterExitObserver(CFRunLoopObserverRef observer,
 
   switch (activity) {
     case kCFRunLoopEntry:
+      if (self->instrumentation_)
+        self->instrumentation_->LoopEntered();
+
       ++self->nesting_level_;
       if (self->nesting_level_ > self->deepest_nesting_level_) {
         self->deepest_nesting_level_ = self->nesting_level_;
@@ -415,9 +667,9 @@ void MessagePumpCFRunLoopBase::EnterExitObserver(CFRunLoopObserverRef observer,
       // handling sources to exiting without any sleep.  This most commonly
       // occurs when CFRunLoopRunInMode is passed a timeout of 0, causing it
       // to make a single pass through the loop and exit without sleep.  Some
-      // native loops use CFRunLoop in this way.  Because PreWaitObserver will
-      // not be called in these case, MaybeScheduleNestingDeferredWork needs
-      // to be called here, as the run loop exits.
+      // native loops use CFRunLoop in this way.  Because StartOrEndWaitObserver
+      // will not be called in these case, MaybeScheduleNestingDeferredWork
+      // needs to be called here, as the run loop exits.
       //
       // MaybeScheduleNestingDeferredWork consults self->nesting_level_
       // to determine whether to schedule nesting-deferred work.  It expects
@@ -427,6 +679,9 @@ void MessagePumpCFRunLoopBase::EnterExitObserver(CFRunLoopObserverRef observer,
       // loop.
       self->MaybeScheduleNestingDeferredWork();
       --self->nesting_level_;
+
+      if (self->instrumentation_)
+        self->instrumentation_->LoopExited();
       break;
 
     default:
@@ -556,11 +811,15 @@ void MessagePumpUIApplication::Attach(Delegate* delegate) {
 MessagePumpNSApplication::MessagePumpNSApplication()
     : keep_running_(true),
       running_own_loop_(false) {
+  EnableInstrumentation();
 }
 
 MessagePumpNSApplication::~MessagePumpNSApplication() {}
 
 void MessagePumpNSApplication::DoRun(Delegate* delegate) {
+  if (instrumentation_)
+    instrumentation_->StartIfNeeded();
+
   bool last_running_own_loop_ = running_own_loop_;
 
   // NSApp must be initialized by calling: