Compile a list of the most frequently run unlabeled runnables

RESOLVED FIXED in Firefox 54

Status

()

defect
RESOLVED FIXED
3 years ago
Last year

People

(Reporter: billm, Assigned: billm)

Tracking

unspecified
mozilla54
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox54 fixed)

Details

Attachments

(8 attachments, 1 obsolete attachment)

16.76 KB, patch
Ehsan
: review+
Details | Diff | Splinter Review
3.32 KB, patch
Ehsan
: review+
Details | Diff | Splinter Review
4.10 KB, patch
bkelly
: review+
Details | Diff | Splinter Review
7.72 KB, patch
Ehsan
: review+
Details | Diff | Splinter Review
3.72 KB, patch
njn
: review+
Details | Diff | Splinter Review
802 bytes, patch
kanru
: review+
Details | Diff | Splinter Review
2.94 KB, patch
Ehsan
: review+
benjamin
: review+
Details | Diff | Splinter Review
10.94 KB, patch
Details | Diff | Splinter Review
The goal here is to get a list that people can use to label runnables in order of urgency.
Using a pretty ugly patch, I've come up with this list:

1. PVsync::Msg_Notify
This one will be hard to fix since it applies to whichever tab is in the foreground at the time it runs.

#2. SelectorCacheKeyDeleter
http://searchfox.org/mozilla-central/rev/790b2cb423ea1ecb5746722d51633caec9bab95a/dom/base/nsDocument.cpp#1241

#3. PCompositorBridge::Msg_DidComposite
This one should be easier than Vsync to fix. The layers ID is part of the message, so we should be able to look this up when the message is received. We'll have to put a lock around sTabChildren though.

#4. PCompositable::Msg___delete__
This doesn't seem to do very much. We might be able to get away with assigning it to no DocGroup (i.e., the SystemGroup, which doesn't exist yet).

#5. nsHtml5SVGLoadDispatcher

#6. LogMessageRunnable
http://searchfox.org/mozilla-central/rev/790b2cb423ea1ecb5746722d51633caec9bab95a/xpcom/base/nsConsoleService.cpp#164

#7. NS_ProxyRelease/NS_ReleaseOnMainThread
This could be tricky since it seems like it depends on what we're releasing. Some destructors might touch content and need to be in a certain DocGroup.

#8. IDecodingTask::NotifyDecodeComplete / IDecodingTask::NotifyProgress
http://searchfox.org/mozilla-central/rev/790b2cb423ea1ecb5746722d51633caec9bab95a/image/IDecodingTask.cpp#86
http://searchfox.org/mozilla-central/rev/790b2cb423ea1ecb5746722d51633caec9bab95a/image/IDecodingTask.cpp#53

#9. StorageNotifierRunnable
http://searchfox.org/mozilla-central/rev/790b2cb423ea1ecb5746722d51633caec9bab95a/dom/storage/Storage.cpp#234

#10. PAPZ::Msg_RequestContentRepaint
I think we can get the right TabChild via the APZChild's mController->mBrowser (assuming it's a ContentProcessController).

I'll stop there for now.
This first patch just adds a bunch of runnable names.
Assignee: nobody → wmccloskey
Status: NEW → ASSIGNED
Attachment #8827702 - Flags: review?(ehsan)

Updated

3 years ago
Attachment #8827702 - Flags: review?(ehsan) → review+
This patch gives some somewhat generic names to a few dispatch sites where we would otherwise have nothing. We should remove these calls as we get better names for the runnables they're dispatching.
Attachment #8828159 - Flags: review?(ehsan)
This patch allows us to "see through" a ThrottledEventQueue to get the name of the runnable inside it.
Attachment #8828160 - Flags: review?(bkelly)
I've decided that we should have a standard way of naming runnables. For most runnables, let's name them according to their C++ class name, excluding namespaces unless the name is otherwise too general. For functions, we'll use the name of the function, including the class name but excluding namespaces.

If you're okay with this, I'll update the wiki page on Quantum DOM.
Attachment #8828162 - Flags: review?(ehsan)
The name of a setTimeout runnable will be the filename and line number of the script. This is bad if we want to report these to telemetry. So I've added an "anonymize" option to the nsITimer name callback.
Attachment #8828163 - Flags: review?(n.nethercote)
The IPC message name is used as the runnable name for IPC runnables. When the name is "???", this is pretty ambiguous. I'd rather use a name that makes it clear that it's an IPC runnable.
Attachment #8828164 - Flags: review?(kchen)
Comment on attachment 8828163 [details] [diff] [review]
anonymize nsITimer names

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

::: dom/base/Timeout.cpp
@@ +71,2 @@
>  {
> +  if (aAnonymize) {

Please add a brief comment here about filenames being sensitive.

::: xpcom/threads/nsTimerImpl.cpp
@@ +547,5 @@
>        if (mName.is<NameString>()) {
>          name = mName.as<NameString>();
>  
>        } else if (mName.is<NameFunc>()) {
> +        mName.as<NameFunc>()(mITimer, false, mClosure, buf, buflen);

I would write: 

> mName.as<NameFunc>()(mITimer, /* anonymize = */ false, mClosure, buf, buflen);

Some people would insist on a two-value enum, but I won't.

@@ +658,5 @@
>          aName.Assign(mName.as<NameString>());
>        } else if (mName.is<NameFunc>()) {
>          static const size_t buflen = 1024;
>          char buf[buflen];
> +        mName.as<NameFunc>()(mITimer, true, mClosure, buf, buflen);

Ditto.
Attachment #8828163 - Flags: review?(n.nethercote) → review+
Comment on attachment 8828164 [details] [diff] [review]
change default IPC message name

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

::: ipc/ipdl/ipdl.py
@@ +219,5 @@
>      return "%s::%s";""" % (protocol, msg, protocol, msg)
>  
>  print >>ipc_msgtype_name, """
>    default:
> +    return "<unknown msg name>";

Could this be even clearer? Perhaps "<unknown IPC runnable msg name>"?
This is the hacky patch I used to find the filename and line number of many unlabeled dispatch sites.
(In reply to Bill McCloskey (:billm) from comment #1)
> #4. PCompositable::Msg___delete__
> This doesn't seem to do very much. We might be able to get away with
> assigning it to no DocGroup (i.e., the SystemGroup, which doesn't exist yet).

PCompositable is removed in bug 1323957

> 
> #5. nsHtml5SVGLoadDispatcher
> 
> #6. LogMessageRunnable
> http://searchfox.org/mozilla-central/rev/
> 790b2cb423ea1ecb5746722d51633caec9bab95a/xpcom/base/nsConsoleService.cpp#164
> 
> #7. NS_ProxyRelease/NS_ReleaseOnMainThread
> This could be tricky since it seems like it depends on what we're releasing.
> Some destructors might touch content and need to be in a certain DocGroup.
> 
> #8. IDecodingTask::NotifyDecodeComplete / IDecodingTask::NotifyProgress
> http://searchfox.org/mozilla-central/rev/
> 790b2cb423ea1ecb5746722d51633caec9bab95a/image/IDecodingTask.cpp#86
> http://searchfox.org/mozilla-central/rev/
> 790b2cb423ea1ecb5746722d51633caec9bab95a/image/IDecodingTask.cpp#53
> 
> #9. StorageNotifierRunnable
> http://searchfox.org/mozilla-central/rev/
> 790b2cb423ea1ecb5746722d51633caec9bab95a/dom/storage/Storage.cpp#234
> 
> #10. PAPZ::Msg_RequestContentRepaint
> I think we can get the right TabChild via the APZChild's
> mController->mBrowser (assuming it's a ContentProcessController).
> 
> I'll stop there for now.
Comment on attachment 8828164 [details] [diff] [review]
change default IPC message name

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

Like njn said maybe we can make it even more clearer. Consider that the default name is also used else where, I'd use "<unknown IPC msg name>".
Attachment #8828164 - Flags: review?(kchen) → review+
This patch counts the number of times a runnable has run as well as how long it took.

Benjamin, the histogram keys here are the names of runnables. They should be names of IPC messages and C++ runnable classes and methods. We want to collect this data so that we can compile a list of the runnables that run most often. We'll use this list to focus effort on these runnables when labeling them with DocGroups for Quantum DOM.
Attachment #8828211 - Flags: review?(ehsan)
Attachment #8828211 - Flags: review?(benjamin)
Comment on attachment 8828160 [details] [diff] [review]
ThrottledEventQueue naming

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

::: xpcom/threads/ThrottledEventQueue.cpp
@@ +75,5 @@
>        return NS_OK;
>      }
> +
> +    NS_IMETHODIMP
> +    GetName(nsACString& aName)

Looking at this I'm surprised we don't need to specify `overrides` here and on Run().
Attachment #8828160 - Flags: review?(bkelly) → review+
Just FYI, I added the concept of a SystemGroup in bug 1332494 and used it for the LogMessageRunnable.

Comment 16

3 years ago
Comment on attachment 8828159 [details] [diff] [review]
give names to a few generic dispatch sites

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

::: xpcom/threads/nsTimerImpl.cpp
@@ +678,5 @@
>      case CallbackType::Observer:
>        if (nsCOMPtr<nsINamed> named = do_QueryInterface(mCallback.o)) {
>          named->GetName(aName);
> +      } else {
> +        aName.AssignLiteral("Anonymous interface timer");

Nit: Perhaps call this "Anonymous observer timer" even though the distinction may not necessarily matter?
Attachment #8828159 - Flags: review?(ehsan) → review+

Comment 17

3 years ago
Comment on attachment 8828163 [details] [diff] [review]
anonymize nsITimer names

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

::: dom/base/Timeout.cpp
@@ +71,3 @@
>  {
> +  if (aAnonymize) {
> +    snprintf(aBuf, aLen, "setTimeout/Interval");

Drive-by: If you move this block below the declaration of |timeout|, you can use |timeout->mIsInterval| to check which one you have.

Comment 18

3 years ago
Comment on attachment 8828162 [details] [diff] [review]
new naming scheme for runnables

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

Nice, this does look much better!
Attachment #8828162 - Flags: review?(ehsan) → review+
Comment on attachment 8828160 [details] [diff] [review]
ThrottledEventQueue naming

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

::: xpcom/threads/ThrottledEventQueue.cpp
@@ +118,5 @@
>      MOZ_ASSERT(!mExecutor);
>      MOZ_ASSERT(mShutdownStarted);
>    }
>  
> +  NS_IMETHODIMP

Why is this NS_IMETHODIMP?  Shouldn't it just be nsresult?  Is it actually defined in an IDL interface somewhere?

I think it should be clear this cannot get called outside of the private details of ThrottledEventQueue since we have the "must not be empty" requirement.  We can't guarantee that if its not the ExecutorRunnable making the call.  A comment to that effect would be nice as well.

::: xpcom/threads/nsEventQueue.cpp
@@ +46,5 @@
> +{
> +  MOZ_ASSERT(aEvent);
> +  *aEvent = nullptr;
> +
> +  MOZ_RELEASE_ASSERT(!IsEmpty());

Actually, I'm curious what actually guarantees this in the patch.  It seems ThrottledEventQueue calls into this without checking the length of the queue.
Comment on attachment 8828211 [details] [diff] [review]
telemetry for runnable times

I read through nsINamed, and I want to see if this is *always* correct, or only for C++-things: "should be a compile-time literal"

We don't want key names to ever expose private/browsing data. If these are always class names or other compiled-in data, this is perfectly fine, data-r=me

If there is any uncertainty about whether that's the case, please ping me and let's talk.

I did not review any code.
Attachment #8828211 - Flags: review?(benjamin) → review+
(In reply to Ben Kelly [:bkelly] from comment #19)
> Comment on attachment 8828160 [details] [diff] [review]
> ThrottledEventQueue naming
> 
> Review of attachment 8828160 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: xpcom/threads/ThrottledEventQueue.cpp
> @@ +118,5 @@
> >      MOZ_ASSERT(!mExecutor);
> >      MOZ_ASSERT(mShutdownStarted);
> >    }
> >  
> > +  NS_IMETHODIMP
> 
> Why is this NS_IMETHODIMP?  Shouldn't it just be nsresult?  Is it actually
> defined in an IDL interface somewhere?

Yes, it should be nsresult.

> I think it should be clear this cannot get called outside of the private
> details of ThrottledEventQueue since we have the "must not be empty"
> requirement.  We can't guarantee that if its not the ExecutorRunnable making
> the call.  A comment to that effect would be nice as well.

OK.

> ::: xpcom/threads/nsEventQueue.cpp
> @@ +46,5 @@
> > +{
> > +  MOZ_ASSERT(aEvent);
> > +  *aEvent = nullptr;
> > +
> > +  MOZ_RELEASE_ASSERT(!IsEmpty());
> 
> Actually, I'm curious what actually guarantees this in the patch.  It seems
> ThrottledEventQueue calls into this without checking the length of the queue.

Well, it relies on people not calling GetName on a ThrottledEventQueue runnable before it's been dispatched or after it's been run. We already have a similar condition on the Run method. I can make this check for empty if you prefer though. Then it could just return "Empty ThrottledEventQueue runnable" or something.
(In reply to Bill McCloskey (:billm) from comment #21)
> (In reply to Ben Kelly [:bkelly] from comment #19)
> > Comment on attachment 8828160 [details] [diff] [review]
> > ThrottledEventQueue naming
> > 
> > Review of attachment 8828160 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > ::: xpcom/threads/ThrottledEventQueue.cpp
> > @@ +118,5 @@
> > >      MOZ_ASSERT(!mExecutor);
> > >      MOZ_ASSERT(mShutdownStarted);
> > >    }
> > >  
> > > +  NS_IMETHODIMP
> > 
> > Why is this NS_IMETHODIMP?  Shouldn't it just be nsresult?  Is it actually
> > defined in an IDL interface somewhere?
> 
> Yes, it should be nsresult.
> 
> > I think it should be clear this cannot get called outside of the private
> > details of ThrottledEventQueue since we have the "must not be empty"
> > requirement.  We can't guarantee that if its not the ExecutorRunnable making
> > the call.  A comment to that effect would be nice as well.
> 
> OK.
> 
> > ::: xpcom/threads/nsEventQueue.cpp
> > @@ +46,5 @@
> > > +{
> > > +  MOZ_ASSERT(aEvent);
> > > +  *aEvent = nullptr;
> > > +
> > > +  MOZ_RELEASE_ASSERT(!IsEmpty());
> > 
> > Actually, I'm curious what actually guarantees this in the patch.  It seems
> > ThrottledEventQueue calls into this without checking the length of the queue.
> 
> Well, it relies on people not calling GetName on a ThrottledEventQueue
> runnable before it's been dispatched or after it's been run. We already have
> a similar condition on the Run method. I can make this check for empty if
> you prefer though. Then it could just return "Empty ThrottledEventQueue
> runnable" or something.

Ah, I thought I deleted that comment.

Anyway, I think it would make sense for nsEventQueue::PeakEvent() return a nullptr event if the queue is empty.  But I convinced myself the current patch is ok.  Just might be confusing if someone tries to use it in a different context.
(In reply to Benjamin Smedberg [:bsmedberg] from comment #20)
> Comment on attachment 8828211 [details] [diff] [review]
> telemetry for runnable times
> 
> I read through nsINamed, and I want to see if this is *always* correct, or
> only for C++-things: "should be a compile-time literal"
> 
> We don't want key names to ever expose private/browsing data. If these are
> always class names or other compiled-in data, this is perfectly fine,
> data-r=me
> 
> If there is any uncertainty about whether that's the case, please ping me
> and let's talk.

Well, I can say for certain the currently the code only returns compile-time constants. However, the interface does allow for arbitrary strings, so people could make mistakes in the future. How much assurance do you think we need? I can think of three options:

1. Leave it the way it is, but with a comment on the |name| property in nsINamed.
2. Change the |name| property to something like telemetryName so people are aware that it can be used in telemetry.
3. Change the interface so that only const char* can be returned. This should work now, but it might make it harder to do certain things in the future. It also might be a source of bugs if people make mistakes and return a stack buffer or something.
See previous comment.
Flags: needinfo?(benjamin)
I think it should be ok to add a comment to the `name` in nsINamed making clear that this must only be build data. Let's be ultra-clear in that comment though.
Flags: needinfo?(benjamin)
We could ensure compile-time constants with something like:

%{C++

  // Whatever the precise syntax is and the args for nsDependentCString.
  template<size_t N>
  void SetName(const char (&aName)[N])
  {
    SetName(nsDependentCString(aName, N));
  }

protected:
  virtual void SetName(nsACString& aName) = 0;
public:
%}

This is a little gross, but there is at least precedent for it:

https://dxr.mozilla.org/mozilla-central/search?q=protected%3A+ext%3Aidl&redirect=false

Comment 27

3 years ago
Comment on attachment 8828211 [details] [diff] [review]
telemetry for runnable times

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

::: xpcom/threads/nsThread.cpp
@@ +1242,4 @@
>        if (MAIN_THREAD == mIsMainThread) {
>          HangMonitor::NotifyActivity();
> +
> +        nsCString name;

Given that these names are #ifdef'ed out on beta or release, perhaps we should only collect these probes on Aurora and Nightly.  r=me with that fixed.
Attachment #8828211 - Flags: review?(ehsan) → review+
Comment on attachment 8828159 [details] [diff] [review]
give names to a few generic dispatch sites

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

::: xpcom/threads/AbstractThread.cpp
@@ +60,5 @@
>  
> +    if (nsCOMPtr<nsINamed> named = do_QueryInterface(r)) {
> +      named->SetName("XPCOMThreadWrapper");
> +    }
> +

Oh, I've done something similar and is landed in bug 1314833, FYI:
https://hg.mozilla.org/mozilla-central/file/8ab1b5ce5bbc/xpcom/threads/AbstractThread.cpp#l175
(In reply to Bevis Tseng[:bevistseng][:btseng] from comment #28)
> Oh, I've done something similar and is landed in bug 1314833, FYI:
> https://hg.mozilla.org/mozilla-central/file/8ab1b5ce5bbc/xpcom/threads/
> AbstractThread.cpp#l175

Thanks! I'll take that part out of my patch.

Comment 30

2 years ago
Pushed by wmccloskey@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/be72b7763910
Add more runnable names (r=ehsan)
https://hg.mozilla.org/integration/mozilla-inbound/rev/2810212347fd
Give runnable names to some generic dispatch sites (r=ehsan)
https://hg.mozilla.org/integration/mozilla-inbound/rev/8b751230fa23
Name each runnable from the ThrottledEventQueue queue (r=bkelly)
https://hg.mozilla.org/integration/mozilla-inbound/rev/c76432c9954e
New naming scheme for runnables (r=ehsan)
https://hg.mozilla.org/integration/mozilla-inbound/rev/3a5b5b9ecace
Anonymize nsITimer runnable names (r=njn)
https://hg.mozilla.org/integration/mozilla-inbound/rev/600c0b9026c2
Change default IPC message name to make it clearer (r=kanru)
https://hg.mozilla.org/integration/mozilla-inbound/rev/8bf7f0e27c6c
Measure runnable times keyed by name for telemetry (r=ehsan,bsmedberg)
(In reply to Wes Kocher (:KWierso) from comment #31)
> I had to back these out for causing Win7 VM debug dt5 runs to fail like
> https://treeherder.mozilla.org/logviewer.html#?job_id=71655985&repo=mozilla-
> inbound
> 
> https://hg.mozilla.org/integration/mozilla-inbound/rev/
> 6abcbe944f8f36edf1f710c9ab32dec6b371d392

See bug 1333597 for the log spam details.

Comment 33

2 years ago
Pushed by wmccloskey@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e402c75016e0
Add more runnable names (r=ehsan)
https://hg.mozilla.org/integration/mozilla-inbound/rev/28998c282974
Give runnable names to some generic dispatch sites (r=ehsan)
https://hg.mozilla.org/integration/mozilla-inbound/rev/ea5f76e45be0
Name each runnable from the ThrottledEventQueue queue (r=bkelly)
https://hg.mozilla.org/integration/mozilla-inbound/rev/ea9be6b31ed0
New naming scheme for runnables (r=ehsan)
https://hg.mozilla.org/integration/mozilla-inbound/rev/181f7c8d957d
Anonymize nsITimer runnable names (r=njn)
https://hg.mozilla.org/integration/mozilla-inbound/rev/4ef27d3ca122
Change default IPC message name to make it clearer (r=kanru)
https://hg.mozilla.org/integration/mozilla-inbound/rev/f0248c53cef7
Measure runnable times keyed by name for telemetry (r=ehsan,bsmedberg)
Bug 1333624 was causing the log spam. I worked around it.
Flags: needinfo?(wmccloskey)
I filed bug 1333984 to analyze the telemetry data from this bug. I also filed a bunch of bugs for the runnables in comment 1. They all block the labeling bug (bug 1321812).
Attachment #8828177 - Attachment is obsolete: true
Depends on: 1382908
See Also: → 1447747
You need to log in before you can comment on or make changes to this bug.