From 10353eba91551855a3c011869d6973de37a76da7 Mon Sep 17 00:00:00 2001 From: Randell Jesup Date: Thu, 7 Nov 2019 12:53:28 +0000 Subject: [PATCH] Bug 1572337: Monitor running event delays and start times r=froydnj This lets us determine the time that an event has been running, and the time that the event spent queued - which can be used to figure out 'jank' at the time the event was queued. For PrioritizedEventQueues, only if such queuing would delay an input event then the queuing delay is reported. Differential Revision: https://phabricator.services.mozilla.com/D41279 --HG-- extra : moz-landing-system : lando --- xpcom/threads/AbstractEventQueue.h | 18 +++- xpcom/threads/EventQueue.cpp | 42 +++++++- xpcom/threads/EventQueue.h | 12 ++- xpcom/threads/LazyIdleThread.cpp | 10 ++ xpcom/threads/PrioritizedEventQueue.cpp | 132 ++++++++++++++---------- xpcom/threads/PrioritizedEventQueue.h | 12 ++- xpcom/threads/SynchronizedEventQueue.h | 3 +- xpcom/threads/ThreadEventQueue.cpp | 14 ++- xpcom/threads/ThreadEventQueue.h | 5 +- xpcom/threads/nsIThread.idl | 19 ++++ xpcom/threads/nsThread.cpp | 29 ++++-- xpcom/threads/nsThread.h | 9 ++ 12 files changed, 221 insertions(+), 84 deletions(-) diff --git a/xpcom/threads/AbstractEventQueue.h b/xpcom/threads/AbstractEventQueue.h index 38b696ec4c69..b449219fbd15 100644 --- a/xpcom/threads/AbstractEventQueue.h +++ b/xpcom/threads/AbstractEventQueue.h @@ -9,6 +9,7 @@ #include "mozilla/AlreadyAddRefed.h" #include "mozilla/MemoryReporting.h" +#include "mozilla/TimeStamp.h" #include "mozilla/Mutex.h" class nsIRunnable; @@ -44,19 +45,26 @@ enum class EventQueuePriority { class AbstractEventQueue { public: // Add an event to the end of the queue. Implementors are free to use - // aPriority however they wish. If the runnable supports nsIRunnablePriority - // and the implementing class supports prioritization, aPriority represents - // the result of calling nsIRunnablePriority::GetPriority(). + // aPriority however they wish. If the runnable supports + // nsIRunnablePriority and the implementing class supports + // prioritization, aPriority represents the result of calling + // nsIRunnablePriority::GetPriority(). *aDelay is time the event has + // already been delayed (used when moving an event from one queue to + // another) virtual void PutEvent(already_AddRefed&& aEvent, EventQueuePriority aPriority, - const MutexAutoLock& aProofOfLock) = 0; + const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aDelay = nullptr) = 0; // Get an event from the front of the queue. aPriority is an out param. If the // implementation supports priorities, then this should be the same priority // that the event was pushed with. aPriority may be null. This should return // null if the queue is non-empty but the event in front is not ready to run. + // *aLastEventDelay is the time the event spent in queues before being + // retrieved. virtual already_AddRefed GetEvent( - EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock) = 0; + EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aLastEventDelay = nullptr) = 0; // Returns true if the queue is empty. Implies !HasReadyEvent(). virtual bool IsEmpty(const MutexAutoLock& aProofOfLock) = 0; diff --git a/xpcom/threads/EventQueue.cpp b/xpcom/threads/EventQueue.cpp index c50d8e8612a8..8b79a2cc48e9 100644 --- a/xpcom/threads/EventQueue.cpp +++ b/xpcom/threads/EventQueue.cpp @@ -13,14 +13,34 @@ EventQueue::EventQueue(EventQueuePriority aPriority) {} void EventQueue::PutEvent(already_AddRefed&& aEvent, EventQueuePriority aPriority, - const MutexAutoLock& aProofOfLock) { + const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aDelay) { +#ifdef MOZ_GECKO_PROFILER + // Sigh, this doesn't check if this thread is being profiled + if (profiler_is_active()) { + // check to see if the profiler has been enabled since the last PutEvent + while (mDispatchTimes.Count() < mQueue.Count()) { + mDispatchTimes.Push(TimeStamp()); + } + mDispatchTimes.Push(aDelay ? TimeStamp::Now() - *aDelay : TimeStamp::Now()); + } else { + // XXX clear queues when profiler is turned off without adding (much) + // overhead instead of doing this + mDispatchTimes.Push(TimeStamp()); + } +#endif + nsCOMPtr event(aEvent); mQueue.Push(std::move(event)); } already_AddRefed EventQueue::GetEvent( - EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock) { + EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aLastEventDelay) { if (mQueue.IsEmpty()) { + if (aLastEventDelay) { + *aLastEventDelay = TimeDuration(); + } return nullptr; } @@ -28,6 +48,24 @@ already_AddRefed EventQueue::GetEvent( *aPriority = EventQueuePriority::Normal; } +#ifdef MOZ_GECKO_PROFILER + if (profiler_is_active()) { + // check to see if the profiler has been enabled since the last PutEvent + while (mDispatchTimes.Count() < mQueue.Count()) { + mDispatchTimes.Push(TimeStamp()); + } + TimeStamp dispatch_time = mDispatchTimes.Pop(); + if (!dispatch_time.IsNull()) { + if (aLastEventDelay) { + *aLastEventDelay = TimeStamp::Now() - dispatch_time; + } + } + } else { + (void)mDispatchTimes.Pop(); + } + // XXX clear queues when profiler is turned off without adding (much) overhead +#endif + nsCOMPtr result = mQueue.Pop(); return result.forget(); } diff --git a/xpcom/threads/EventQueue.h b/xpcom/threads/EventQueue.h index 81652e585a28..0b6542285692 100644 --- a/xpcom/threads/EventQueue.h +++ b/xpcom/threads/EventQueue.h @@ -23,10 +23,11 @@ class EventQueue final : public AbstractEventQueue { explicit EventQueue(EventQueuePriority aPriority); void PutEvent(already_AddRefed&& aEvent, - EventQueuePriority aPriority, - const MutexAutoLock& aProofOfLock) final; + EventQueuePriority aPriority, const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aDelay = nullptr) final; already_AddRefed GetEvent( - EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock) final; + EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aLastEventDelay = nullptr) final; void DidRunEvent(const MutexAutoLock& aProofOfLock) {} bool IsEmpty(const MutexAutoLock& aProofOfLock) final; @@ -54,6 +55,11 @@ class EventQueue final : public AbstractEventQueue { private: mozilla::Queue> mQueue; +#ifdef MOZ_GECKO_PROFILER + // This queue is only populated when the profiler is turned on. + mozilla::Queue mDispatchTimes; + TimeDuration mLastEventDelay; +#endif }; } // namespace mozilla diff --git a/xpcom/threads/LazyIdleThread.cpp b/xpcom/threads/LazyIdleThread.cpp index d2aebf892157..362ab5b807f2 100644 --- a/xpcom/threads/LazyIdleThread.cpp +++ b/xpcom/threads/LazyIdleThread.cpp @@ -395,6 +395,16 @@ LazyIdleThread::DelayedDispatch(already_AddRefed, uint32_t) { return NS_ERROR_NOT_IMPLEMENTED; } +NS_IMETHODIMP +LazyIdleThread::GetRunningEventDelay(TimeDuration* aDelay, TimeStamp* aStart) { + if (mThread) { + return mThread->GetRunningEventDelay(aDelay, aStart); + } + *aDelay = TimeDuration(); + *aStart = TimeStamp(); + return NS_OK; +} + NS_IMETHODIMP LazyIdleThread::IsOnCurrentThread(bool* aIsOnCurrentThread) { if (mThread) { diff --git a/xpcom/threads/PrioritizedEventQueue.cpp b/xpcom/threads/PrioritizedEventQueue.cpp index 031a9ea21eba..ee657a432d9c 100644 --- a/xpcom/threads/PrioritizedEventQueue.cpp +++ b/xpcom/threads/PrioritizedEventQueue.cpp @@ -30,7 +30,8 @@ PrioritizedEventQueue::~PrioritizedEventQueue() = default; void PrioritizedEventQueue::PutEvent(already_AddRefed&& aEvent, EventQueuePriority aPriority, - const MutexAutoLock& aProofOfLock) { + const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aDelay) { // Double check the priority with a QI. RefPtr event(aEvent); EventQueuePriority priority = aPriority; @@ -45,22 +46,24 @@ void PrioritizedEventQueue::PutEvent(already_AddRefed&& aEvent, switch (priority) { case EventQueuePriority::High: - mHighQueue->PutEvent(event.forget(), priority, aProofOfLock); + mHighQueue->PutEvent(event.forget(), priority, aProofOfLock, aDelay); break; case EventQueuePriority::Input: - mInputQueue->PutEvent(event.forget(), priority, aProofOfLock); + mInputQueue->PutEvent(event.forget(), priority, aProofOfLock, aDelay); break; case EventQueuePriority::MediumHigh: - mMediumHighQueue->PutEvent(event.forget(), priority, aProofOfLock); + mMediumHighQueue->PutEvent(event.forget(), priority, aProofOfLock, + aDelay); break; case EventQueuePriority::Normal: - mNormalQueue->PutEvent(event.forget(), priority, aProofOfLock); + mNormalQueue->PutEvent(event.forget(), priority, aProofOfLock, aDelay); break; case EventQueuePriority::DeferredTimers: - mDeferredTimersQueue->PutEvent(event.forget(), priority, aProofOfLock); + mDeferredTimersQueue->PutEvent(event.forget(), priority, aProofOfLock, + aDelay); break; case EventQueuePriority::Idle: - mIdleQueue->PutEvent(event.forget(), priority, aProofOfLock); + mIdleQueue->PutEvent(event.forget(), priority, aProofOfLock, aDelay); break; case EventQueuePriority::Count: MOZ_CRASH("EventQueuePriority::Count isn't a valid priority"); @@ -145,7 +148,8 @@ EventQueuePriority PrioritizedEventQueue::SelectQueue( } already_AddRefed PrioritizedEventQueue::GetEvent( - EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock) { + EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aLastEventDelay) { #ifndef RELEASE_OR_BETA // Clear mNextIdleDeadline so that it is possible to determine that // we're running an idle runnable in ProcessNextEvent. @@ -165,64 +169,80 @@ already_AddRefed PrioritizedEventQueue::GetEvent( *aPriority = queue; } - if (queue == EventQueuePriority::High) { - nsCOMPtr event = mHighQueue->GetEvent(aPriority, aProofOfLock); - MOZ_ASSERT(event); - mInputHandlingStartTime = TimeStamp(); - mProcessHighPriorityQueue = false; - return event.forget(); - } + // Since Input events will only be delayed behind Input or High events, + // the amount of time a lower-priority event spent in the queue is + // irrelevant in knowing how long an input event would be delayed. + // Alternatively, we could export the delay and let the higher-level code + // key off the returned priority level (though then it'd need to know + // if the thread's queue was a PrioritizedEventQueue or normal/other + // EventQueue). + nsCOMPtr event; + switch (queue) { + default: + MOZ_CRASH(); + break; - if (queue == EventQueuePriority::Input) { - nsCOMPtr event = - mInputQueue->GetEvent(aPriority, aProofOfLock); - MOZ_ASSERT(event); - return event.forget(); - } + case EventQueuePriority::High: + event = mHighQueue->GetEvent(aPriority, aProofOfLock, aLastEventDelay); + MOZ_ASSERT(event); + mInputHandlingStartTime = TimeStamp(); + mProcessHighPriorityQueue = false; + break; - if (queue == EventQueuePriority::MediumHigh) { - nsCOMPtr event = - mMediumHighQueue->GetEvent(aPriority, aProofOfLock); - return event.forget(); - } + case EventQueuePriority::Input: + event = mInputQueue->GetEvent(aPriority, aProofOfLock, aLastEventDelay); + MOZ_ASSERT(event); + break; - if (queue == EventQueuePriority::Normal) { - nsCOMPtr event = - mNormalQueue->GetEvent(aPriority, aProofOfLock); - return event.forget(); - } + // All queue priorities below Input don't add their queuing time to the + // time an input event will be delayed, so report 0 for time-in-queue + // if we're below Input; input events will only be delayed by the time + // an event actually runs (if the event is below Input event's priority) + case EventQueuePriority::MediumHigh: + event = mMediumHighQueue->GetEvent(aPriority, aProofOfLock); + *aLastEventDelay = TimeDuration(); + break; - // If we get here, then all queues except deferredtimers and idle are empty. - MOZ_ASSERT(queue == EventQueuePriority::Idle || - queue == EventQueuePriority::DeferredTimers); + case EventQueuePriority::Normal: + event = mNormalQueue->GetEvent(aPriority, aProofOfLock); + *aLastEventDelay = TimeDuration(); + break; - if (mIdleQueue->IsEmpty(aProofOfLock) && - mDeferredTimersQueue->IsEmpty(aProofOfLock)) { - mIdlePeriodState.RanOutOfTasks(*mMutex); - return nullptr; - } + case EventQueuePriority::Idle: + case EventQueuePriority::DeferredTimers: + *aLastEventDelay = TimeDuration(); + // If we get here, then all queues except deferredtimers and idle are + // empty. - TimeStamp idleDeadline = mIdlePeriodState.GetDeadlineForIdleTask(*mMutex); - if (!idleDeadline) { - return nullptr; - } + if (mIdleQueue->IsEmpty(aProofOfLock) && + mDeferredTimersQueue->IsEmpty(aProofOfLock)) { + mIdlePeriodState.RanOutOfTasks(*mMutex); + return nullptr; + } - nsCOMPtr event = - mDeferredTimersQueue->GetEvent(aPriority, aProofOfLock); - if (!event) { - event = mIdleQueue->GetEvent(aPriority, aProofOfLock); - } - if (event) { - nsCOMPtr idleEvent = do_QueryInterface(event); - if (idleEvent) { - idleEvent->SetDeadline(idleDeadline); - } + TimeStamp idleDeadline = mIdlePeriodState.GetDeadlineForIdleTask(*mMutex); + if (!idleDeadline) { + return nullptr; + } + + nsCOMPtr event = + mDeferredTimersQueue->GetEvent(aPriority, aProofOfLock); + if (!event) { + event = mIdleQueue->GetEvent(aPriority, aProofOfLock); + } + if (event) { + nsCOMPtr idleEvent = do_QueryInterface(event); + if (idleEvent) { + idleEvent->SetDeadline(idleDeadline); + } #ifndef RELEASE_OR_BETA - // Store the next idle deadline to be able to determine budget use - // in ProcessNextEvent. - *mNextIdleDeadline = idleDeadline; + // Store the next idle deadline to be able to determine budget use + // in ProcessNextEvent. + *mNextIdleDeadline = idleDeadline; #endif + } + break; } return event.forget(); diff --git a/xpcom/threads/PrioritizedEventQueue.h b/xpcom/threads/PrioritizedEventQueue.h index 3903ee365507..362cd633f67c 100644 --- a/xpcom/threads/PrioritizedEventQueue.h +++ b/xpcom/threads/PrioritizedEventQueue.h @@ -49,10 +49,13 @@ class PrioritizedEventQueue final : public AbstractEventQueue { virtual ~PrioritizedEventQueue(); void PutEvent(already_AddRefed&& aEvent, - EventQueuePriority aPriority, - const MutexAutoLock& aProofOfLock) final; + EventQueuePriority aPriority, const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aDelay = nullptr) final; + // See PrioritizedEventQueue.cpp for explanation of + // aHypotheticalInputEventDelay already_AddRefed GetEvent( - EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock) final; + EventQueuePriority* aPriority, const MutexAutoLock& aProofOfLock, + mozilla::TimeDuration* aHypotheticalInputEventDelay = nullptr) final; void DidRunEvent(const MutexAutoLock& aProofOfLock); bool IsEmpty(const MutexAutoLock& aProofOfLock) final; @@ -111,6 +114,9 @@ class PrioritizedEventQueue final : public AbstractEventQueue { // a pointer to it here. Mutex* mMutex = nullptr; + TimeDuration mLastEventDelay; + TimeStamp mLastEventStart; + #ifndef RELEASE_OR_BETA // Pointer to a place where the most recently computed idle deadline is // stored. diff --git a/xpcom/threads/SynchronizedEventQueue.h b/xpcom/threads/SynchronizedEventQueue.h index c9ecf83a369a..fc9047887080 100644 --- a/xpcom/threads/SynchronizedEventQueue.h +++ b/xpcom/threads/SynchronizedEventQueue.h @@ -57,7 +57,8 @@ class ThreadTargetSink { class SynchronizedEventQueue : public ThreadTargetSink { public: virtual already_AddRefed GetEvent( - bool aMayWait, EventQueuePriority* aPriority) = 0; + bool aMayWait, EventQueuePriority* aPriority, + mozilla::TimeDuration* aLastEventDelay = nullptr) = 0; virtual void DidRunEvent() = 0; virtual bool HasPendingEvent() = 0; diff --git a/xpcom/threads/ThreadEventQueue.cpp b/xpcom/threads/ThreadEventQueue.cpp index 7e46ccc0237d..07afc0949274 100644 --- a/xpcom/threads/ThreadEventQueue.cpp +++ b/xpcom/threads/ThreadEventQueue.cpp @@ -131,17 +131,19 @@ bool ThreadEventQueue::PutEventInternal( template already_AddRefed ThreadEventQueue::GetEvent( - bool aMayWait, EventQueuePriority* aPriority) { + bool aMayWait, EventQueuePriority* aPriority, + mozilla::TimeDuration* aLastEventDelay) { MutexAutoLock lock(mLock); nsCOMPtr event; for (;;) { if (mNestedQueues.IsEmpty()) { - event = mBaseQueue->GetEvent(aPriority, lock); + event = mBaseQueue->GetEvent(aPriority, lock, aLastEventDelay); } else { // We always get events from the topmost queue when there are nested // queues. - event = mNestedQueues.LastElement().mQueue->GetEvent(aPriority, lock); + event = mNestedQueues.LastElement().mQueue->GetEvent(aPriority, lock, + aLastEventDelay); } if (event || !aMayWait) { @@ -261,8 +263,10 @@ void ThreadEventQueue::PopEventQueue(nsIEventTarget* aTarget) { // Move events from the old queue to the new one. nsCOMPtr event; EventQueuePriority prio; - while ((event = item.mQueue->GetEvent(&prio, lock))) { - prevQueue->PutEvent(event.forget(), prio, lock); + TimeDuration delay; + while ((event = item.mQueue->GetEvent(&prio, lock, &delay))) { + // preserve the event delay so far + prevQueue->PutEvent(event.forget(), prio, lock, &delay); } mNestedQueues.RemoveLastElement(); diff --git a/xpcom/threads/ThreadEventQueue.h b/xpcom/threads/ThreadEventQueue.h index 5ed7c3990ed0..a67e4a9c239b 100644 --- a/xpcom/threads/ThreadEventQueue.h +++ b/xpcom/threads/ThreadEventQueue.h @@ -36,8 +36,9 @@ class ThreadEventQueue final : public SynchronizedEventQueue { bool PutEvent(already_AddRefed&& aEvent, EventQueuePriority aPriority) final; - already_AddRefed GetEvent(bool aMayWait, - EventQueuePriority* aPriority) final; + already_AddRefed GetEvent( + bool aMayWait, EventQueuePriority* aPriority, + mozilla::TimeDuration* aLastEventDelay = nullptr) final; void DidRunEvent() final; bool HasPendingEvent() final; bool HasPendingHighPriorityEvents() final; diff --git a/xpcom/threads/nsIThread.idl b/xpcom/threads/nsIThread.idl index 28368e1e7792..9042463ff65c 100644 --- a/xpcom/threads/nsIThread.idl +++ b/xpcom/threads/nsIThread.idl @@ -10,6 +10,9 @@ #include "mozilla/AlreadyAddRefed.h" namespace mozilla { class TimeStamp; +class TimeDurationValueCalculator; +template class BaseTimeDuration; +typedef BaseTimeDuration TimeDuration; enum class EventQueuePriority; } %} @@ -20,6 +23,7 @@ native EventQueuePriority(mozilla::EventQueuePriority); native nsIEventTargetPtr(nsIEventTarget*); native nsISerialEventTargetPtr(nsISerialEventTarget*); native TimeStamp(mozilla::TimeStamp); +native TimeDuration(mozilla::TimeDuration); /** * This interface provides a high-level abstraction for an operating system @@ -177,5 +181,20 @@ interface nsIThread : nsISerialEventTarget [noscript] readonly attribute TimeStamp lastLongTaskEnd; [noscript] readonly attribute TimeStamp lastLongNonIdleTaskEnd; + /** + * Get information on the timing of the currently-running event. + * + * @param delay + * The amount of time the current running event in the specified queue waited + * to run. Will return TimeDuration() if the queue is empty or has not run any + * new events since event delay monitoring started. NOTE: delay will be + * TimeDuration() if this thread uses a PrioritizedEventQueue (i.e. MainThread) + * and the event priority is below Input. + * @param start + * The time the currently running event began to run, or TimeStamp() if no + * event is running. + */ + [noscript] void getRunningEventDelay(out TimeDuration delay, out TimeStamp start); + [noscript] void setNameForWakeupTelemetry(in ACString name); }; diff --git a/xpcom/threads/nsThread.cpp b/xpcom/threads/nsThread.cpp index 0301037a93e5..78233218d537 100644 --- a/xpcom/threads/nsThread.cpp +++ b/xpcom/threads/nsThread.cpp @@ -731,6 +731,13 @@ nsThread::DelayedDispatch(already_AddRefed aEvent, return mEventTarget->DelayedDispatch(std::move(aEvent), aDelayMs); } +NS_IMETHODIMP +nsThread::GetRunningEventDelay(TimeDuration* aDelay, TimeStamp* aStart) { + *aDelay = mLastEventDelay; + *aStart = mLastEventStart; + return NS_OK; +} + NS_IMETHODIMP nsThread::IsOnCurrentThread(bool* aResult) { if (mEventTarget) { @@ -1131,7 +1138,8 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult) { // mNestedEventLoopDepth has been incremented, since that destructor can // also do work. EventQueuePriority priority; - nsCOMPtr event = mEvents->GetEvent(reallyWait, &priority); + nsCOMPtr event = + mEvents->GetEvent(reallyWait, &priority, &mLastEventDelay); *aResult = (event.get() != nullptr); @@ -1166,6 +1174,8 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult) { // to run. DelayForChaosMode(ChaosFeature::TaskRunning, 1000); + mozilla::TimeStamp now = mozilla::TimeStamp::Now(); + if (mIsMainThread) { BackgroundHangMonitor().NotifyActivity(); } @@ -1174,7 +1184,7 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult) { mCurrentPerformanceCounter) { // This is a recursive call, we're saving the time // spent in the parent event if the runnable is linked to a DocGroup. - mozilla::TimeDuration duration = TimeStamp::Now() - mCurrentEventStart; + mozilla::TimeDuration duration = now - mCurrentEventStart; mCurrentPerformanceCounter->IncrementExecutionDuration( duration.ToMicroseconds()); } @@ -1214,10 +1224,10 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult) { bool recursiveEvent = mNestedEventLoopDepth > mCurrentEventLoopDepth; mCurrentEventLoopDepth = mNestedEventLoopDepth; if (mIsMainThread && !recursiveEvent) { - mCurrentEventStart = mozilla::TimeStamp::Now(); + mCurrentEventStart = now; } RefPtr currentPerformanceCounter; - mCurrentEventStart = mozilla::TimeStamp::Now(); + mLastEventStart = now; mCurrentEvent = event; mCurrentPerformanceCounter = GetPerformanceCounter(event); currentPerformanceCounter = mCurrentPerformanceCounter; @@ -1265,9 +1275,14 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult) { mCurrentEventLoopDepth = MaxValue::value; mCurrentPerformanceCounter = nullptr; } - } else if (aMayWait) { - MOZ_ASSERT(ShuttingDown(), "This should only happen when shutting down"); - rv = NS_ERROR_UNEXPECTED; + } else { + mLastEventDelay = TimeDuration(); + mLastEventStart = TimeStamp(); + if (aMayWait) { + MOZ_ASSERT(ShuttingDown(), + "This should only happen when shutting down"); + rv = NS_ERROR_UNEXPECTED; + } } } diff --git a/xpcom/threads/nsThread.h b/xpcom/threads/nsThread.h index 5c6783a73ed7..eee3d157e1a6 100644 --- a/xpcom/threads/nsThread.h +++ b/xpcom/threads/nsThread.h @@ -237,9 +237,18 @@ class nsThread : public nsIThreadInternal, // Used to track which event is being executed by ProcessNextEvent nsCOMPtr mCurrentEvent; + // When the current event started. Note: recursive events use the time + // the outmost event started, so the entire recursion chain is considered + // one event. mozilla::TimeStamp mCurrentEventStart; mozilla::TimeStamp mNextIdleDeadline; + // The time the currently running event spent in event queues, and + // when it started running. If no event is running, they are + // TimeDuration() & TimeStamp(). + mozilla::TimeDuration mLastEventDelay; + mozilla::TimeStamp mLastEventStart; + #ifdef EARLY_BETA_OR_EARLIER nsCString mNameForWakeupTelemetry; mozilla::TimeStamp mLastWakeupCheckTime;