1331804 - Compile a list of the most frequently run unlabeled runnables

Status: RESOLVED FIXED

(Core :: DOM: Content Processes, defect)

Description

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

The goal here is to get a list that people can use to label runnables in order of urgency.

Comment 1

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

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.

Comment 2

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: add more runnable names

This first patch just adds a bunch of runnable names.

Comment 3

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: give names to a few generic dispatch sites

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.

Comment 4

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: ThrottledEventQueue naming

This patch allows us to "see through" a ThrottledEventQueue to get the name of the runnable inside it.

Comment 5

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: new naming scheme for runnables

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.

Comment 6

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: anonymize nsITimer names

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.

Comment 7

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: change default IPC message name

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.

Comment 8

[Nicholas Nethercote [inactive]]

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.

Comment 9

[Nicholas Nethercote [inactive]]

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>"?

Comment 10

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: hacky patch to get filename/lineno info

This is the hacky patch I used to find the filename and line number of many unlabeled dispatch sites.

Comment 11

[Kan-Ru Chen [:kanru] (UTC+9)]

(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 12

[Kan-Ru Chen [:kanru] (UTC+9)]

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>".

Comment 13

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: telemetry for runnable times

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.

Comment 14

[Ben Kelly [:bkelly, not reviewing]]

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().

Comment 15

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Just FYI, I added the concept of a SystemGroup in bug 1332494 and used it for the LogMessageRunnable.

Comment 16

[(no longer active)]

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?

Comment 17

[(no longer active)]

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

[(no longer active)]

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!

Comment 19

[Ben Kelly [:bkelly, not reviewing]]

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 20

[Benjamin Smedberg]

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.

Comment 21

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

(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.

Comment 22

[Ben Kelly [:bkelly, not reviewing]]

(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.

Comment 23

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

(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.

Comment 24

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

See previous comment.

Comment 25

[Benjamin Smedberg]

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.

Comment 26

[Nathan Froyd [:froydnj]]

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

[(no longer active)]

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.

Comment 28

[Bevis Tseng[:bevis][:btseng](Exited)]

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

Comment 29

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

(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

[Pulsebot]

Pushed by [e-mail]:
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)

Comment 31

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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

Comment 32

[Eric Rahm [:erahm]]

(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

[Pulsebot]

Pushed by [e-mail]:
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)

Comment 34

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Bug 1333624 was causing the log spam. I worked around it.

Comment 35

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/e402c75016e0
https://hg.mozilla.org/mozilla-central/rev/28998c282974
https://hg.mozilla.org/mozilla-central/rev/ea5f76e45be0
https://hg.mozilla.org/mozilla-central/rev/ea9be6b31ed0
https://hg.mozilla.org/mozilla-central/rev/181f7c8d957d
https://hg.mozilla.org/mozilla-central/rev/4ef27d3ca122
https://hg.mozilla.org/mozilla-central/rev/f0248c53cef7

Comment 36

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

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).

Comment 37

[Andrew McCreight [:mccr8]]

Attachment: Hacky parts of patch to show unlabeled runnables. DO NOT LAND