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

@@ -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<nsIRunnable>&& 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<nsIRunnable> 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;

xpcom/threads/EventQueue.cpp

@@ -13,14 +13,34 @@ EventQueue::EventQueue(EventQueuePriority aPriority) {}
 
 void EventQueue::PutEvent(already_AddRefed<nsIRunnable>&& 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<nsIRunnable> event(aEvent);
   mQueue.Push(std::move(event));
 }
 
 already_AddRefed<nsIRunnable> 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<nsIRunnable> 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<nsIRunnable> result = mQueue.Pop();
   return result.forget();
 }

xpcom/threads/EventQueue.h

@@ -23,10 +23,11 @@ class EventQueue final : public AbstractEventQueue {
   explicit EventQueue(EventQueuePriority aPriority);
 
   void PutEvent(already_AddRefed<nsIRunnable>&& aEvent,
-                EventQueuePriority aPriority,
-                const MutexAutoLock& aProofOfLock) final;
+                EventQueuePriority aPriority, const MutexAutoLock& aProofOfLock,
+                mozilla::TimeDuration* aDelay = nullptr) final;
   already_AddRefed<nsIRunnable> 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<nsCOMPtr<nsIRunnable>> mQueue;
+#ifdef MOZ_GECKO_PROFILER
+  // This queue is only populated when the profiler is turned on.
+  mozilla::Queue<mozilla::TimeStamp> mDispatchTimes;
+  TimeDuration mLastEventDelay;
+#endif
 };
 
 }  // namespace mozilla

xpcom/threads/LazyIdleThread.cpp

@@ -395,6 +395,16 @@ LazyIdleThread::DelayedDispatch(already_AddRefed<nsIRunnable>, 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) {

xpcom/threads/PrioritizedEventQueue.cpp

@@ -30,7 +30,8 @@ PrioritizedEventQueue::~PrioritizedEventQueue() = default;
 
 void PrioritizedEventQueue::PutEvent(already_AddRefed<nsIRunnable>&& aEvent,
                                      EventQueuePriority aPriority,
-                                     const MutexAutoLock& aProofOfLock) {
+                                     const MutexAutoLock& aProofOfLock,
+                                     mozilla::TimeDuration* aDelay) {
   // Double check the priority with a QI.
   RefPtr<nsIRunnable> event(aEvent);
   EventQueuePriority priority = aPriority;
@@ -45,22 +46,24 @@ void PrioritizedEventQueue::PutEvent(already_AddRefed<nsIRunnable>&& 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<nsIRunnable> 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<nsIRunnable> PrioritizedEventQueue::GetEvent(
     *aPriority = queue;
   }
 
-  if (queue == EventQueuePriority::High) {
-    nsCOMPtr<nsIRunnable> 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<nsIRunnable> event;
+  switch (queue) {
+    default:
+      MOZ_CRASH();
+      break;
 
-  if (queue == EventQueuePriority::Input) {
-    nsCOMPtr<nsIRunnable> 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<nsIRunnable> 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<nsIRunnable> 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<nsIRunnable> event =
-      mDeferredTimersQueue->GetEvent(aPriority, aProofOfLock);
-  if (!event) {
-    event = mIdleQueue->GetEvent(aPriority, aProofOfLock);
-  }
-  if (event) {
-    nsCOMPtr<nsIIdleRunnable> idleEvent = do_QueryInterface(event);
-    if (idleEvent) {
-      idleEvent->SetDeadline(idleDeadline);
-    }
+      TimeStamp idleDeadline = mIdlePeriodState.GetDeadlineForIdleTask(*mMutex);
+      if (!idleDeadline) {
+        return nullptr;
+      }
+
+      nsCOMPtr<nsIRunnable> event =
+          mDeferredTimersQueue->GetEvent(aPriority, aProofOfLock);
+      if (!event) {
+        event = mIdleQueue->GetEvent(aPriority, aProofOfLock);
+      }
+      if (event) {
+        nsCOMPtr<nsIIdleRunnable> 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();

xpcom/threads/PrioritizedEventQueue.h

@@ -49,10 +49,13 @@ class PrioritizedEventQueue final : public AbstractEventQueue {
   virtual ~PrioritizedEventQueue();
 
   void PutEvent(already_AddRefed<nsIRunnable>&& 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<nsIRunnable> 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.

xpcom/threads/SynchronizedEventQueue.h

@@ -57,7 +57,8 @@ class ThreadTargetSink {
 class SynchronizedEventQueue : public ThreadTargetSink {
  public:
   virtual already_AddRefed<nsIRunnable> GetEvent(
-      bool aMayWait, EventQueuePriority* aPriority) = 0;
+      bool aMayWait, EventQueuePriority* aPriority,
+      mozilla::TimeDuration* aLastEventDelay = nullptr) = 0;
   virtual void DidRunEvent() = 0;
   virtual bool HasPendingEvent() = 0;
 

xpcom/threads/ThreadEventQueue.cpp

@@ -131,17 +131,19 @@ bool ThreadEventQueue<InnerQueueT>::PutEventInternal(
 
 template <class InnerQueueT>
 already_AddRefed<nsIRunnable> ThreadEventQueue<InnerQueueT>::GetEvent(
-    bool aMayWait, EventQueuePriority* aPriority) {
+    bool aMayWait, EventQueuePriority* aPriority,
+    mozilla::TimeDuration* aLastEventDelay) {
   MutexAutoLock lock(mLock);
 
   nsCOMPtr<nsIRunnable> 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<InnerQueueT>::PopEventQueue(nsIEventTarget* aTarget) {
   // Move events from the old queue to the new one.
   nsCOMPtr<nsIRunnable> 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();

xpcom/threads/ThreadEventQueue.h

@@ -36,8 +36,9 @@ class ThreadEventQueue final : public SynchronizedEventQueue {
   bool PutEvent(already_AddRefed<nsIRunnable>&& aEvent,
                 EventQueuePriority aPriority) final;
 
-  already_AddRefed<nsIRunnable> GetEvent(bool aMayWait,
-                                         EventQueuePriority* aPriority) final;
+  already_AddRefed<nsIRunnable> GetEvent(
+      bool aMayWait, EventQueuePriority* aPriority,
+      mozilla::TimeDuration* aLastEventDelay = nullptr) final;
   void DidRunEvent() final;
   bool HasPendingEvent() final;
   bool HasPendingHighPriorityEvents() final;

xpcom/threads/nsIThread.idl

@@ -10,6 +10,9 @@
 #include "mozilla/AlreadyAddRefed.h"
 namespace mozilla {
 class TimeStamp;
+class TimeDurationValueCalculator;
+template <typename T> class BaseTimeDuration;
+typedef BaseTimeDuration<TimeDurationValueCalculator> 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);
 };

xpcom/threads/nsThread.cpp

@@ -731,6 +731,13 @@ nsThread::DelayedDispatch(already_AddRefed<nsIRunnable> 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<nsIRunnable> event = mEvents->GetEvent(reallyWait, &priority);
+    nsCOMPtr<nsIRunnable> 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<mozilla::PerformanceCounter> 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<uint32_t>::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;
+      }
     }
   }
 

xpcom/threads/nsThread.h

@@ -237,9 +237,18 @@ class nsThread : public nsIThreadInternal,
   // Used to track which event is being executed by ProcessNextEvent
   nsCOMPtr<nsIRunnable> 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;