diff options
author | rsesek@chromium.org <rsesek@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2014-07-02 02:03:57 +0000 |
---|---|---|
committer | rsesek@chromium.org <rsesek@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2014-07-02 02:03:57 +0000 |
commit | 9c7cbf42cdaa6d53d4a1b6fe8322bbfcbab36af9 (patch) | |
tree | 3facfac7d6a16141fce8d4132348d902fb156809 /base | |
parent | 1283330e588bf1d5e73e7c2533af4c85e7cdc5a2 (diff) | |
download | chromium_src-9c7cbf42cdaa6d53d4a1b6fe8322bbfcbab36af9.zip chromium_src-9c7cbf42cdaa6d53d4a1b6fe8322bbfcbab36af9.tar.gz chromium_src-9c7cbf42cdaa6d53d4a1b6fe8322bbfcbab36af9.tar.bz2 |
Revert 221427 "Add instrumentation to the MessagePumpMac family ..."
This code is no longer needed, since the experiment is not viable.
> 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
TBR=rsesek@chromium.org
Review URL: https://codereview.chromium.org/360373004
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@280939 0039d316-1c4b-4281-b951-d872f2087c98
Diffstat (limited to 'base')
-rw-r--r-- | base/message_loop/message_loop.cc | 14 | ||||
-rw-r--r-- | base/message_loop/message_loop.h | 2 | ||||
-rw-r--r-- | base/message_loop/message_pump.h | 14 | ||||
-rw-r--r-- | base/message_loop/message_pump_mac.h | 20 | ||||
-rw-r--r-- | base/message_loop/message_pump_mac.mm | 272 |
5 files changed, 15 insertions, 307 deletions
diff --git a/base/message_loop/message_loop.cc b/base/message_loop/message_loop.cc index ccece4d..8e817dab 100644 --- a/base/message_loop/message_loop.cc +++ b/base/message_loop/message_loop.cc @@ -632,20 +632,6 @@ 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) { diff --git a/base/message_loop/message_loop.h b/base/message_loop/message_loop.h index 22d4f73..a65fbf5 100644 --- a/base/message_loop/message_loop.h +++ b/base/message_loop/message_loop.h @@ -446,8 +446,6 @@ 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; const Type type_; diff --git a/base/message_loop/message_pump.h b/base/message_loop/message_pump.h index a795f31..4dc501b6 100644 --- a/base/message_loop/message_pump.h +++ b/base/message_loop/message_pump.h @@ -12,7 +12,6 @@ namespace base { -class TimeDelta; class TimeTicks; class BASE_EXPORT MessagePump : public NonThreadSafe { @@ -42,19 +41,6 @@ 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(); diff --git a/base/message_loop/message_pump_mac.h b/base/message_loop/message_pump_mac.h index 6e63d2b..f52bd76 100644 --- a/base/message_loop/message_pump_mac.h +++ b/base/message_loop/message_pump_mac.h @@ -58,7 +58,6 @@ namespace base { -class MessagePumpInstrumentation; class RunLoop; class TimeTicks; @@ -112,11 +111,6 @@ class MessagePumpCFRunLoopBase : public MessagePump { // objects autoreleased by work to fall into the current autorelease pool. virtual AutoreleasePoolType* 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 @@ -130,11 +124,11 @@ class MessagePumpCFRunLoopBase : public MessagePump { static void RunWorkSource(void* info); bool RunWork(); - // 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. + // 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. static void RunIdleWorkSource(void* info); bool RunIdleWork(); @@ -156,8 +150,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 StartOrEndWaitObserver(CFRunLoopObserverRef observer, - CFRunLoopActivity activity, void* info); + static void PreWaitObserver(CFRunLoopObserverRef observer, + CFRunLoopActivity activity, void* info); // Observer callback called before the run loop processes any sources. // Associated with pre_source_observer_. diff --git a/base/message_loop/message_pump_mac.mm b/base/message_loop/message_pump_mac.mm index 0ab9ab7..914977b 100644 --- a/base/message_loop/message_pump_mac.mm +++ b/base/message_loop/message_pump_mac.mm @@ -8,15 +8,11 @@ #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/message_loop/timer_slack.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) @@ -123,226 +119,6 @@ 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)); - CFRunLoopAddTimerToAllModes(CFRunLoopGetCurrent(), timer_); - } - - // 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), @@ -393,11 +169,10 @@ MessagePumpCFRunLoopBase::MessagePumpCFRunLoopBase() CFRunLoopObserverContext observer_context = CFRunLoopObserverContext(); observer_context.info = this; pre_wait_observer_ = CFRunLoopObserverCreate(NULL, // allocator - kCFRunLoopBeforeWaiting | - kCFRunLoopAfterWaiting, + kCFRunLoopBeforeWaiting, true, // repeat 0, // priority - StartOrEndWaitObserver, + PreWaitObserver, &observer_context); CFRunLoopAddObserverToAllModes(run_loop_, pre_wait_observer_); @@ -482,11 +257,6 @@ 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_); @@ -543,9 +313,6 @@ 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 @@ -585,9 +352,6 @@ bool MessagePumpCFRunLoopBase::RunWork() { CFRunLoopSourceSignal(work_source_); } - if (instrumentation_) - instrumentation_->WorkSourceExited(); - return resignal_work_source; } @@ -672,18 +436,11 @@ void MessagePumpCFRunLoopBase::MaybeScheduleNestingDeferredWork() { // Called from the run loop. // static -void MessagePumpCFRunLoopBase::StartOrEndWaitObserver( - CFRunLoopObserverRef observer, - CFRunLoopActivity activity, - void* info) { +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(); @@ -692,9 +449,6 @@ void MessagePumpCFRunLoopBase::StartOrEndWaitObserver( // 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. @@ -721,9 +475,6 @@ 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_; @@ -737,9 +488,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 StartOrEndWaitObserver - // 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 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 @@ -749,9 +500,6 @@ void MessagePumpCFRunLoopBase::EnterExitObserver(CFRunLoopObserverRef observer, // loop. self->MaybeScheduleNestingDeferredWork(); --self->nesting_level_; - - if (self->instrumentation_) - self->instrumentation_->LoopExited(); break; default: @@ -881,15 +629,11 @@ 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: |