Add instrumentation to the MessagePumpMac family of classes.

base/message_loop/message_pump_mac.mm

Index: base/message_loop/message_pump_mac.mm
diff --git a/base/message_loop/message_pump_mac.mm b/base/message_loop/message_pump_mac.mm
index f885fbf5f6bbb9d53fc1d24363c0f427699ace6c..fa959479a2581059fbfcf7720a47d0166823a865 100644
--- a/base/message_loop/message_pump_mac.mm
+++ b/base/message_loop/message_pump_mac.mm
@@ -7,10 +7,14 @@
 #import <Foundation/Foundation.h>
 
 #include <limits>
+#include <stack>
 
 #include "base/logging.h"
+#include "base/metrics/histogram.h"
 #include "base/run_loop.h"
+#include "base/strings/stringprintf.h"
 #include "base/time/time.h"
+#include "base/timer/timer.h"
 
 #if !defined(OS_IOS)
 #import <AppKit/AppKit.h>
@@ -51,6 +55,181 @@ 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_.IsRunning())
+      return;
+    timer_.Start(FROM_HERE, sampling_interval_,
+                 base::Bind(&MessagePumpInstrumentation::TimerFired,
+                            weak_ptr_factory_.GetWeakPtr()));
+  }
+
+  // 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:
+    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_count_(0),
+        timer_(true, true) {
+    const char kHistogramName[] = "MessagePumpMac.%s.SampleMs.%lld";
+
+    // Create all the histogram objects that will be used for sampling.
+    for (TimeDelta i; i < sampling_duration_; i += sampling_interval_) {
+      int64 sample = i.InMilliseconds();
+
+      // Generate the time-based histograms.
+      for (HistogramEvent j = LOOP_CYCLE; j < QUEUE_SIZE; ++j) {

[Mark Mentovai, 2013/08/20 22:44:34]

There’s no indication in the enum above that QUEUE_SIZE has been overloaded to
be “first thing in the list that’s not time-based.” Someone could add something
before QUEUE_SIZE and mess this up.

[Robert Sesek, 2013/08/22 17:49:15]

"Solved" with a comment. Fixing this with an in-between marker value makes the
code to account for it harder to follow IMO.

+        std::string name = StringPrintf(kHistogramName, NameForEnum(j), sample);
+        histograms_[j].push_back(
+            Histogram::FactoryTimeGet(name, TimeDelta::FromMilliseconds(1),
+                sampling_interval_, 50,
+                HistogramBase::kUmaTargetedHistogramFlag));
+      }
+
+      // Generate the value-based histograms.
+      for (HistogramEvent j = QUEUE_SIZE; j < HISTOGRAM_EVENT_MAX; ++j) {
+        std::string name = StringPrintf(kHistogramName, NameForEnum(j), sample);
+        histograms_[j].push_back(
+            Histogram::FactoryGet(name, 1, 10000, 50,
+                HistogramBase::kUmaTargetedHistogramFlag));
+      }
+    }

[Mark Mentovai, 2013/08/20 22:44:34]

That was only 75 histograms.

[Robert Sesek, 2013/08/22 17:49:15]

I'll leave it to jar@ to comment on the implications. I could probably reduce
sampling_duration_ if necessary.

[jar (doing other things), 2013/08/22 23:03:39]

I'm not convinced that all these histogtrams are useful (which is I think what
Mark was quietly suggesting by pointing out the total).

I'd be curious to understand better what you are trying to do, as I'm not at all
following the utility.

+  }
+
+  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";
+      case HISTOGRAM_EVENT_MAX:

[Mark Mentovai, 2013/08/20 22:44:34]

This line is not needed. (Some compiler with lots of warnings might get upset if
it sees you’ve handled all of the possible enum values AND provided a default:,
so it might be better to remove this line.)

[Robert Sesek, 2013/08/22 17:49:15]

Done.

+      default:
+        NOTREACHED();
+        return NULL;
+    }
+  }
+
+  // Called when |sampling_interval| has elapsed.
+  void TimerFired() {
+    ++sample_count_;
+
+    if (sampling_interval_ * sample_count_ >= sampling_duration_) {
+      timer_.Stop();
+      delete this;
+    }
+  }
+
+  HistogramBase* GetHistogram(HistogramEvent event) {
+    return histograms_[event][sample_count_];
+  }
+
+  // Vends the pointer to the Create()er.
+  WeakPtrFactory<MessagePumpInstrumentation> weak_ptr_factory_;
+
+  // The interval and duration of the sampling, as well as the number of
+  // times the timer has fired.
+  TimeDelta sampling_interval_;
+  TimeDelta sampling_duration_;
+  size_t sample_count_;
+
+  // The timer that invokes TimerFired() to advance the |sample_count_|.
+  Timer timer_;

[Mark Mentovai, 2013/08/20 22:44:34]

…this is running on a Timer. And the timers are dispatched by the message loop.

1. Would a CFTimer be better? Still dispatched by the message loop, still not
guaranteed to run in any time, but maybe you’d get better priority given the
current loop structure?

2. Maybe you should do something to track the actual time it took for your timer
to fire. You’d then have a massive data-processing pain to deal with the data
that produced, though.

3. Maybe it’s fine as-is, but tracking sample_count_ as a simple
monotonically-increasing thing per timer “generation” is bad. Maybe what you
need to do is set the timer on each iteration so that its fire time is as close
to the time you want as possible, and maybe you need to adjust things so that if
you expected a timer to fire at 2 seconds past the epoch to record things that
happened in the [1.0, 2.0) interval, but it actually fired at 4 seconds, you
record them as having happened in the [1.0, 4.0) interval, since that’s the best
information you’d really have at that point. But I don’t know if that would work
well for analysis with your current schema either.

[Robert Sesek, 2013/08/22 17:49:15]

Sigh, I know.
Yes, I've switched to a CFRunLoopTimer and it performs pretty well. I
experimented with using the events the Instrumentation is recording as chances
for advancing the generation. That had problems when the run loop went to sleep
and there was nothing to interrupt it to advance the generation.
Done. I'm not sure it can be used to correct any of the data (and I'm not sure
it matters _too_ much). I'm more concerned with how data changes over time,
local and absolute minima and maxima, and the effect of a dependent variable
(the scheduling behavior) on it. If data doesn't line exactly up into buckets,
that's probably fine for my purposes.
Now that I'm recording timer skew, I'm also advancing sample_count_ (now
sample_generation_) by any skew that is greater than or equal to
sampling_interval_.

+
+  // 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];
+
+  // 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,7 +280,8 @@ MessagePumpCFRunLoopBase::MessagePumpCFRunLoopBase()
   CFRunLoopObserverContext observer_context = CFRunLoopObserverContext();
   observer_context.info = this;
   pre_wait_observer_ = CFRunLoopObserverCreate(NULL,  // allocator
-                                               kCFRunLoopBeforeWaiting,
+                                               kCFRunLoopBeforeWaiting |
+                                                  kCFRunLoopAfterWaiting,
                                                true,  // repeat
                                                0,     // priority
                                                PreWaitObserver,

[Mark Mentovai, 2013/08/20 22:44:34]

Either your new code is temporary (and you should add a comment explaining why
you call something called PreWaitObserver for post-wait also) or it’s not (and
you should rename PreWaitObserver).

[Robert Sesek, 2013/08/22 17:49:15]

Done.

@@ -193,6 +373,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 +425,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 +467,9 @@ bool MessagePumpCFRunLoopBase::RunWork() {
     CFRunLoopSourceSignal(work_source_);
   }
 
+  if (instrumentation_)
+    instrumentation_->WorkSourceExited();
+
   return resignal_work_source;
 }
 
@@ -368,6 +559,12 @@ void MessagePumpCFRunLoopBase::PreWaitObserver(CFRunLoopObserverRef observer,
                                                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 +573,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 +602,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_;
@@ -427,6 +630,9 @@ void MessagePumpCFRunLoopBase::EnterExitObserver(CFRunLoopObserverRef observer,
       // loop.
       self->MaybeScheduleNestingDeferredWork();
       --self->nesting_level_;
+
+      if (self->instrumentation_)
+        self->instrumentation_->LoopExited();
       break;
 
     default:
@@ -556,11 +762,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: