Add instrumentation to the MessagePumpMac family of classes.

base/message_loop/message_pump_mac.mm

 // Copyright (c) 2012 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.
 
 #import "base/message_loop/message_pump_mac.h"
 
 #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>
 #endif  // !defined(OS_IOS)
 
 namespace {
 
 void NoOp(void* info) {
 }
 
@@ skipping 20 matching lines @@
   }
    ~MessagePumpScopedAutoreleasePool() {
     [pool_ drain];
   }
 
  private:
   NSAutoreleasePool* pool_;
   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),
       delayed_work_fire_time_(kCFTimeIntervalMax),
       nesting_level_(0),
       run_nesting_level_(0),
       deepest_nesting_level_(0),
       delegateless_work_(false),
       delegateless_idle_work_(false) {
   run_loop_ = CFRunLoopGetCurrent();
@@ skipping 30 matching lines @@
   source_context.perform = RunNestingDeferredWorkSource;
   nesting_deferred_work_source_ = CFRunLoopSourceCreate(NULL,  // allocator
                                                         0,     // priority
                                                         &source_context);
   CFRunLoopAddSource(run_loop_, nesting_deferred_work_source_,
                      kCFRunLoopCommonModes);
 
   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.

                                                &observer_context);
   CFRunLoopAddObserver(run_loop_, pre_wait_observer_, kCFRunLoopCommonModes);
 
   pre_source_observer_ = CFRunLoopObserverCreate(NULL,  // allocator
                                                  kCFRunLoopBeforeSources,
                                                  true,  // repeat
                                                  0,     // priority
                                                  PreSourceObserver,
                                                  &observer_context);
   CFRunLoopAddObserver(run_loop_, pre_source_observer_, kCFRunLoopCommonModes);
@@ skipping 68 matching lines @@
       CFRunLoopSourceSignal(work_source_);
       delegateless_work_ = false;
     }
     if (delegateless_idle_work_) {
       CFRunLoopSourceSignal(idle_work_source_);
       delegateless_idle_work_ = false;
     }
   }
 }
 
+void MessagePumpCFRunLoopBase::EnableInstrumentation() {
+  instrumentation_ = MessagePumpInstrumentation::Create(
+      TimeDelta::FromSeconds(1), TimeDelta::FromSeconds(15));
+}
+
 // May be called on any thread.
 void MessagePumpCFRunLoopBase::ScheduleWork() {
   CFRunLoopSourceSignal(work_source_);
   CFRunLoopWakeUp(run_loop_);
 }
 
 // Must be called on the run loop thread.
 void MessagePumpCFRunLoopBase::ScheduleDelayedWork(
     const TimeTicks& delayed_work_time) {
   TimeDelta delta = delayed_work_time - TimeTicks::Now();
@@ skipping 27 matching lines @@
 // Called by MessagePumpCFRunLoopBase::RunWorkSource.
 bool MessagePumpCFRunLoopBase::RunWork() {
   if (!delegate_) {
     // This point can be reached with a NULL delegate_ if Run is not on the
     // stack but foreign code is spinning the CFRunLoop.  Arrange to come back
     // here when a delegate is available.
     delegateless_work_ = true;
     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
   // objects if the app is not currently handling a UI event to ensure they're
   // released promptly even in the absence of UI events.
   MessagePumpScopedAutoreleasePool autorelease_pool(this);
 
   // Call DoWork and DoDelayedWork once, and if something was done, arrange to
   // come back here again as long as the loop is still running.
   bool did_work = delegate_->DoWork();
@@ skipping 19 matching lines @@
         // running.
         resignal_work_source = true;
       }
     }
   }
 
   if (resignal_work_source) {
     CFRunLoopSourceSignal(work_source_);
   }
 
+  if (instrumentation_)
+    instrumentation_->WorkSourceExited();
+
   return resignal_work_source;
 }
 
 // Called from the run loop.
 // static
 void MessagePumpCFRunLoopBase::RunIdleWorkSource(void* info) {
   MessagePumpCFRunLoopBase* self = static_cast<MessagePumpCFRunLoopBase*>(info);
   self->RunIdleWork();
 }
 
@@ skipping 69 matching lines @@
   }
 }
 
 // Called from the run loop.
 // static
 void MessagePumpCFRunLoopBase::PreWaitObserver(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();
 
   // The run loop is about to go to sleep.  If any of the work done since it
   // started or woke up resulted in a nested run loop running,
   // 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.
 // static
 void MessagePumpCFRunLoopBase::PreSourceObserver(CFRunLoopObserverRef observer,
                                                  CFRunLoopActivity activity,
                                                  void* info) {
   MessagePumpCFRunLoopBase* self = static_cast<MessagePumpCFRunLoopBase*>(info);
 
   // The run loop has reached the top of the loop and is about to begin
   // processing sources.  If the last iteration of the loop at this nesting
   // level did not sleep or exit, nesting-deferred work may have accumulated
   // if a nested loop ran.  Schedule nesting-deferred work for processing if
   // appropriate.
   self->MaybeScheduleNestingDeferredWork();
 }
 
 // Called from the run loop.
 // static
 void MessagePumpCFRunLoopBase::EnterExitObserver(CFRunLoopObserverRef observer,
                                                  CFRunLoopActivity activity,
                                                  void* info) {
   MessagePumpCFRunLoopBase* self = static_cast<MessagePumpCFRunLoopBase*>(info);
 
   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_;
       }
       break;
 
     case kCFRunLoopExit:
       // Not all run loops go to sleep.  If a run loop is stopped before it
       // goes to sleep due to a CFRunLoopStop call, or if the timeout passed
       // to CFRunLoopRunInMode expires, the run loop may proceed directly from
       // 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.
       //
       // MaybeScheduleNestingDeferredWork consults self->nesting_level_
       // to determine whether to schedule nesting-deferred work.  It expects
       // the nesting level to be set to the depth of the loop that is going
       // to sleep or exiting.  It must be called before decrementing the
       // value so that the value still corresponds to the level of the exiting
       // loop.
       self->MaybeScheduleNestingDeferredWork();
       --self->nesting_level_;
+
+      if (self->instrumentation_)
+        self->instrumentation_->LoopExited();
       break;
 
     default:
       break;
   }
 
   self->EnterExitRunLoop(activity);
 }
 
 // Called by MessagePumpCFRunLoopBase::EnterExitRunLoop.  The default
@@ skipping 109 matching lines @@
   run_loop_ = new RunLoop();
   CHECK(run_loop_->BeforeRun());
   SetDelegate(delegate);
 }
 
 #else
 
 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:
   // [{some class which implements CrAppProtocol} sharedApplication]
   // Most likely candidates are CrApplication or BrowserCrApplication.
   // These can be initialized from C++ code by calling
   // RegisterCrApp() or RegisterBrowserCrApp().
   CHECK(NSApp);
 
   if (![NSApp isRunning]) {
@@ skipping 121 matching lines @@
     [NSApplication sharedApplication];
     g_not_using_cr_app = true;
     return new MessagePumpNSApplication;
 #endif
   }
 
   return new MessagePumpNSRunLoop;
 }
 
 }  // namespace base