1482244 - monitor per-thread event queue responsiveness for Profiling directly

Status: NEW

(Core :: XPCOM, enhancement, P5)

Description

[Randell Jesup [:jesup] (needinfo me)]

The profiler measures event responsiveness by injecting events every 16ms for every nsThread; this causes extra overhead and can affect profiles.

A better solution would be to directly monitor event processing delay when the profiler is configured and active in the thread code, since it knows when events are queued.

Comment 1

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP patch to monitor event delays

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP patch to monitor event delays

closer to building....

Comment 3

[Markus Stange [:mstange]]

Does this implement the approach suggested in bug 1340714 or some other approach? I haven't looked at the patch in detail yet.

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

How does this deal with idle queue?
It is totally ok for an runnable to stay in idle queue for quite some time.

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Markus Stange [:mstange] from comment #3)
> Does this implement the approach suggested in bug 1340714 or some other
> approach? I haven't looked at the patch in detail yet.

this does implement that, it turns out.  It records the time events enter the queue, then monitors when the come out and start execution.

(In reply to Olli Pettay [:smaug] from comment #4)
> How does this deal with idle queue?
> It is totally ok for an runnable to stay in idle queue for quite some time.

I'll verify it's only picking up the normal queue, and modify to ensure that (probably needed).

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

We have also other queues.  I guess need to just not care about idle queue.

Comment 7

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP patch to monitor event delays

comes *this* close to building

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP patch to monitor event delays

down to 2 errors...

Comment 9

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP patch to monitor event delays

builds and runs

Comment 10

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP patch to monitor event delays

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

Attachment: p2 - Monitor event dispatch->runtime by recording dispatch times

implements just the DispatchTime part of responsiveness

Comment 12

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Move nsIRunnable uses to Runnable or UnnamedRunnable

just the move from nsIRunnable to Runnable (and the new UnnamedRunnable; we could simply name them all instead)

Comment 13

[Nathan Froyd [:froydnj]]

Comment on attachment 9042517 [details] [diff] [review]
Move nsIRunnable uses to Runnable or UnnamedRunnable

Review of attachment 9042517 [details] [diff] [review]:
-----------------------------------------------------------------

I skimmed through this and it looks mostly fine.  The NS_IMPL_ISUPPORTS invocations may need some extra checks for these to make sure we are getting them right, or deleting them if we are able.

::: dom/base/CustomElementRegistry.h
@@ +389,5 @@
>    /**
>     * Looking up a custom element definition.
>     * https://html.spec.whatwg.org/#look-up-a-custom-element-definition
>     */
> +  CustomElementDefinition* LookupCustomElementDefinition(nsAtom* aeNameAtom,

Is this just C-x e gone bad, or something else?

::: dom/base/TimeoutExecutor.cpp
@@ +15,5 @@
>  
>  namespace mozilla {
>  namespace dom {
>  
> +NS_IMPL_ISUPPORTS(TimeoutExecutor, nsITimerCallback)

Surely this needs to dispatch to some superclass?

::: dom/workers/ScriptLoader.cpp
@@ -616,5 @@
>    }
>  
> -  NS_IMETHOD
> -  GetName(nsACString& aName) override {
> -    aName.AssignLiteral("ScriptLoaderRunnable");

Why are we deleting this?

@@ +1386,5 @@
>      }
>    }
>  };
>  
> +NS_IMPL_ISUPPORTS(ScriptLoaderRunnable, nsIRunnable)

This should just dispatch to the superclass so we don't lose the nsINamed support?

::: dom/workers/WorkerPrivate.cpp
@@ -557,5 @@
>    NS_IMETHOD
>    Notify(nsITimer* aTimer) override { return Run(); }
> -
> -  NS_IMETHOD
> -  GetName(nsACString& aName) override {

Losing this seems not good.

::: netwerk/base/nsAsyncRedirectVerifyHelper.cpp
@@ +62,3 @@
>  nsresult nsAsyncRedirectVerifyHelper::Init(
> +    nsIChannel *oldChan, nsIChannel *newChan, uint32_t flags,
> +    nsIEventTarget *mainThreadEventTarget, bool synchronize) {

This looks like a spurious change.

@@ +139,5 @@
>    return NS_OK;
>  }
>  
>  nsresult nsAsyncRedirectVerifyHelper::DelegateOnChannelRedirect(
> +    nsIChannelEventSink *sink, nsIChannel *oldChannel, nsIChannel *newChannel,

This too.

::: xpcom/threads/nsThreadUtils.h
@@ +485,5 @@
>  };
>  
>  // This class is designed to be subclassed.
> +//
> +class UnnamedRunnable : public Runnable {

This class would need some documentation telling people that they really shouldn't derive from this.

Comment 14

[Randell Jesup [:jesup] (needinfo me)]

Attachment: Move nsIRunnable uses to Runnable or UnnamedRunnable

inheritance issues generally dealt with.  There are a few runnables that I punted on for now (mostly those involved in cycle collection, which can cause some problems per discussion with smaug).  There were a couple where I wasn't sure what to do with the MAP macros or the like; those are marked with XXX.  Builds and works.  I may hand off finishing this, while I work on revising the separate responsiveness work

Comment 15

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP - Monitor event dispatch->run time by recording dispatch times in a queue

WIP for alternate implementation that uses mirrored queues in EventQueue to track dispatch times, instead of modifying Runnable.  Still needs more work on when to maintain the mirror'd queues and freeing them when the profiler is disabled (if we care)

Comment 16

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP - Monitor event dispatch->run time by recording dispatch times in a queue

WIP, but compiles and (mostly) runs; while grabbing a profile I hit an apparent deadlock in the profiler.  Looking for feedback on the approach, especially the *EventQueue* code.  I cut a few corners on some of the more esoteric EventTarget implementations.  given how many things mess with eventtarget, it may make more sense to try to expose it via nsIThread instead.

Comment 17

[Nathan Froyd [:froydnj]]

Comment on attachment 9043193 [details] [diff] [review]
WIP - Monitor event dispatch->run time by recording dispatch times in a queue

Review of attachment 9043193 [details] [diff] [review]:
-----------------------------------------------------------------

This looks reasonable.  I wish there was some way to not push and pop null timestamps all the time, but a couple minutes' thought suggests that trying to avoid that makes the code significantly more complicated

::: xpcom/threads/EventQueue.cpp
@@ +17,5 @@
> +#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()) {

Is this condition ever going to be true given that if `!profiler_is_active()`, we're pushing/popping null TimeStamps?

@@ +44,5 @@
>  
> +#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()) {

Likewise for this.

@@ +73,5 @@
> +                                           const MutexAutoLock& aProofOfLock) const {
> +  if (mDispatchTimes.IsEmpty()) {
> +    return TimeDuration(0);
> +  }
> +  TimeStamp dispatch_time = mDispatchTimes.FirstElement();

Nit: this should be `const TimeStamp& dispatch_time`.

Comment 18

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP - Monitor event dispatch->run time by recording dispatch times in a queue

nsIThread version is much cleaner... modulo a bug in AutoProfilerInit (null mThread for MainThread)

Comment 19

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP - Monitor event dispatch->run time by recording dispatch times in a queue

fixes the pre-existing bug with mThread on the first RegisteredThread being null

Comment 20

[Randell Jesup [:jesup] (needinfo me)]

Attachment: WIP - Monitor event dispatch->run time by recording dispatch times in a queue

a couple files were missing before.  Also, found that now that capturing mainthread responsiveness works, it was deadlocking since a ThreadEventQueue needs to lock to decide if it should use mBaseQueue of the top mNestedQueue, and we need to query this while the thread is paused - boom.  Solution is to (when the profiler is on!) record the delay times on each GetEvent on the ThreadEventQueue.  This is slightly imprecise for CurrentEventDelay, but overall should be very close to correct.  Working on validating the returned values, since I see some unexpected jumps after sequences of 0 CurrentEventDelay

Comment 21

[Randell Jesup [:jesup] (needinfo me)]

Mostly moot due to the implementation of bug 1572337