Open Bug 1482244 Opened 4 years ago Updated 7 months ago

monitor per-thread event queue responsiveness for Profiling directly

Categories

(Core :: XPCOM, enhancement, P5)

58 Branch
enhancement

Tracking

()

People

(Reporter: jesup, Unassigned)

Details

Attachments

(5 files, 9 obsolete files)

170.47 KB, patch
Details | Diff | Splinter Review
9.28 KB, patch
Details | Diff | Splinter Review
190.59 KB, patch
Details | Diff | Splinter Review
42.03 KB, patch
froydnj
: feedback+
Details | Diff | Splinter Review
30.25 KB, patch
Details | Diff | Splinter Review
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.
Assignee: nobody → rjesup
Status: NEW → ASSIGNED
closer to building....
Attachment #8998989 - Attachment is obsolete: true
Does this implement the approach suggested in bug 1340714 or some other approach? I haven't looked at the patch in detail yet.
How does this deal with idle queue?
It is totally ok for an runnable to stay in idle queue for quite some time.
(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).
We have also other queues.  I guess need to just not care about idle queue.
comes *this* close to building
Attachment #8998998 - Attachment is obsolete: true
down to 2 errors...
Attachment #9040973 - Attachment is obsolete: true
Attachment #9042249 - Attachment is obsolete: true
Attachment #9042366 - Attachment is obsolete: true
implements just the DispatchTime part of responsiveness
just the move from nsIRunnable to Runnable (and the new UnnamedRunnable; we could simply name them all instead)
Attachment #9042517 - Flags: feedback?(nfroyd)
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.
Attachment #9042517 - Flags: feedback?(nfroyd) → feedback+
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
Attachment #9042517 - Attachment is obsolete: true
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)
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.
Attachment #9043193 - Flags: feedback?(nfroyd)
Attachment #9043025 - Attachment is obsolete: true
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`.
Attachment #9043193 - Flags: feedback?(nfroyd) → feedback+
nsIThread version is much cleaner... modulo a bug in AutoProfilerInit (null mThread for MainThread)
Attachment #9043323 - Flags: feedback?(nfroyd)
Attachment #9043323 - Flags: feedback?(mstange)
fixes the pre-existing bug with mThread on the first RegisteredThread being null
Attachment #9043365 - Flags: feedback?(nfroyd)
Attachment #9043365 - Flags: feedback?(mstange)
Attachment #9043323 - Attachment is obsolete: true
Attachment #9043323 - Flags: feedback?(nfroyd)
Attachment #9043323 - Flags: feedback?(mstange)
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
Attachment #9043365 - Attachment is obsolete: true
Attachment #9043365 - Flags: feedback?(nfroyd)
Attachment #9043365 - Flags: feedback?(mstange)

Mostly moot due to the implementation of bug 1572337

Assignee: rjesup → nobody
Status: ASSIGNED → NEW
Priority: -- → P5
You need to log in before you can comment on or make changes to this bug.