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/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)
 #import <AppKit/AppKit.h>
 #endif  // !defined(OS_IOS)
 
 namespace {
 
 void NoOp(void* info) {
 }
@@ skipping 21 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_)
+      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 (HistogramEvent j = LOOP_CYCLE; j < QUEUE_SIZE; ++j) {
+        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));
+      }
+    }
+  }
+
+  ~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),
       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 29 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

[jar (doing other things), 2013/08/29 22:15:08]

I'm surprised we do this.  Adding an observer on a per-message basis has a large
impact on performance (as I recall), even if you try to only do work
infrequently.

[Robert Sesek, 2013/08/30 16:25:07]

This observer is added once at the creation of the MessagePump, though it's
called every pass through the system run loop as appropriate. The cost is small.

[jar (doing other things), 2013/09/04 01:20:17]

I see... this is a Mac thing... not the generic task observer list that I've
seen placed in the message loop.  Sorry for my confusion.

-                                               kCFRunLoopBeforeWaiting,
+                                               kCFRunLoopBeforeWaiting |
+                                                  kCFRunLoopAfterWaiting,
                                                true,  // repeat
                                                0,     // priority
-                                               PreWaitObserver,
+                                               StartOrEndWaitObserver,
                                                &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 64 matching lines @@
   // nesting-deferred work in case any work was deferred because nested work
   // was disallowed.
   if (deepest_nesting_level_ > nesting_level_) {
     deepest_nesting_level_ = nesting_level_;
     CFRunLoopSourceSignal(nesting_deferred_work_source_);
   }
 }
 
 // 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();
 
   // 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.
+      // 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
       // 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