924582 - track cpu usage by funneling events through per-document queues

Status: NEW

(Core :: DOM: Core & HTML, defect, P5)

Description

[Nathan Froyd [:froydnj]]

A couple people at the summit asked about tracking per-tab CPU usage; it's
been a common request from other places as well.  I realized this weekend
that the work from bug 715376 was a good starting place: if we can funnel
events for a particular document through a common place, then we can add
instrumentation to those events to track things like CPU usage.  Forthcoming
patches provide a proof-of-concept demonstration of this ability.  It's kind
of fun to watch nytimes.com continually consume CPU and have it show up in
about:memory.

In talking with smaug on #perf this morning, I became aware that there are
other codepaths we have to handle, like some sort of time tracking for native
events.  Undoubtedly, there are probably other paths, too, including some
that I missed from rebasing patches from bug 715376.  Please tell me about
problems with the patches!

Comment 1

[Nathan Froyd [:froydnj]]

Attachment: part 1 - redirect all events through the nearest document

This patch comes from bug 715376, lightly retouched to apply properly to tip.
I'm just going to transfer the r+ over.

Comment 2

[Nathan Froyd [:froydnj]]

Attachment: part 2 - post timers to nsIEventTargets associated with documents

This patch also comes from bug 715376.  Carrying over r+ from there as well.

Comment 3

[Nathan Froyd [:froydnj]]

Attachment: part 3 - make documents wrap their events with timekeeping

This is the interesting part, where we start keeping track of the time taken
per event.  I'm not completely happy with the |friend| declarations and whatnot,
but what's there does work...

Comment 4

[Nathan Froyd [:froydnj]]

Attachment: part 4 - surface cpu time in about:memory

about:memory is probably not the best place for this (about:performance?),
but it was a convenient place to stick stuff to see if everything was
actually working.

Comment 5

[Nathan Froyd [:froydnj]]

Adding people who may or may not be interested in the changes here.

Comment 6

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

Comment on attachment 814518 [details] [diff] [review]
part 3 - make documents wrap their events with timekeeping


>+  void AccumulateRunnableTime(double aMilliseconds) {
{ goes to the next line

>+TaskQueueRunnable::Run()
>+{
>+  // TODO: Can we get by with low-res time stamps here?
>+  TimeStamp start = TimeStamp::Now();
>+
>+  nsresult rv = mRunnable->Run();
>+
>+  TimeStamp end = TimeStamp::Now();
>+
>+  nsIDocument* doc = mQueue->GetDocument();
>+  if (doc) {
>+    doc->AccumulateRunnableTime((end - start).ToMilliseconds());
>+  }
>+
>+  return rv;
>+}
>+
>+
extra line

>+NS_IMETHODIMP
>+nsIDocument::TaskQueue::Dispatch(nsIRunnable *aEvent, uint32_t flags)
>+{
>+  NS_ASSERTION(flags == DISPATCH_NORMAL, "unexpected flags");
>+
>+  nsRefPtr<TaskQueueRunnable> wrappedRunnable =
>+    new TaskQueueRunnable(aEvent, this);
Should we perhaps recycle these runnables?


So this misses the time spent in the event listeners when user is interacting with the page.
For that we'd probably need to add something to nsEventDispatcher so that we can collect time
separately for chrome listeners and content listeners depending on which part of the 
event target chain we're handling.

RefreshDriver handling is also rather special.

Comment 7

[(no longer active)]

Comment on attachment 814518 [details] [diff] [review]
part 3 - make documents wrap their events with timekeeping

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

This is only supposed to handle nsIRunnable's, right?  Couldn't you do the same thing much more simply by wrapping the nsIRunnables posted to a document inside another runnable object which knows to update the runtime for the document?  (Of course the dynamic allocation cost of those wrapper objects could very well be unacceptable.)

::: content/base/public/nsIDocument.h
@@ +2424,5 @@
>  
> +  /**
> +   * The total amount of time running events associated with this document.
> +   */
> +  double mRunnableTime;

Please specify the unit of time used here.  Also, if this is milliseconds, please also document that you're tracking microseconds as digits after the decimal point (you are, right? :-)

::: content/base/src/nsDocument.cpp
@@ +1330,5 @@
> +private:
> +  friend class nsDocument;
> +  friend class TaskQueueRunnable;
> +
> +  nsIDocument* mDocument;

This is very fragile.  What if somebody else obtains a strong pointer to TaskQueue and then calls GetDocument() when TaskQueue's reference from nsIDocument has been cleared out?

Comment 8

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

What more feedback should I give?

Comment 9

[(no longer active)]

Also, what about all of the places where we manually create runnables to do work for a given document?  What about the work that we do for a document on a background thread?

Comment 10

[(no longer active)]

(In reply to Olli Pettay [:smaug] from comment #8)
> What more feedback should I give?

No sorry, that was bugzilla being stupid!

Comment 11

[Nathan Froyd [:froydnj]]

I didn't say this was perfect! :)

(In reply to :Ehsan Akhgari (needinfo? me!) from comment #7)
> This is only supposed to handle nsIRunnable's, right?  Couldn't you do the
> same thing much more simply by wrapping the nsIRunnables posted to a
> document inside another runnable object which knows to update the runtime
> for the document?  (Of course the dynamic allocation cost of those wrapper
> objects could very well be unacceptable.)

This sounds very much like what this patch is doing (see TaskQueueRunnable).  Could
you explain a little further the differences between what you're proposing and what
the patch currently does?

> ::: content/base/public/nsIDocument.h
> @@ +2424,5 @@
> >  
> > +  /**
> > +   * The total amount of time running events associated with this document.
> > +   */
> > +  double mRunnableTime;
> 
> Please specify the unit of time used here.  Also, if this is milliseconds,
> please also document that you're tracking microseconds as digits after the
> decimal point (you are, right? :-)

Well, they are certainly getting tracked, but we're truncating this to an integer for
display in about:memory in any event.

> ::: content/base/src/nsDocument.cpp
> @@ +1330,5 @@
> > +private:
> > +  friend class nsDocument;
> > +  friend class TaskQueueRunnable;
> > +
> > +  nsIDocument* mDocument;
> 
> This is very fragile.  What if somebody else obtains a strong pointer to
> TaskQueue and then calls GetDocument() when TaskQueue's reference from
> nsIDocument has been cleared out?

Nobody but nsIDocument can access TaskQueues, at least not as TaskQueues.  As |nsIEventTarget|s, yes, but in those cases I think the non-refcounted pointer here is OK.  I tried to make this work with nsCOMPtrs, but ran into issues.  It's possible I wasn't trying hard enough.

(In reply to :Ehsan Akhgari (needinfo? me!) from comment #9)
> Also, what about all of the places where we manually create runnables to do
> work for a given document?

I suspect I am ignorant of most of those places.  Creating things for nsContentUtils::AddScriptRunner was one place that stuck out to me, though I wasn't sure that time accrued to those runnables wouldn't get double-counted somehow.  Please point out others!

And if you have any ideas for discovering places akin to the purpose DMD serves for about:memory...

> What about the work that we do for a document on
> a background thread?

Like HTML parsing?  That could probably be handled.  Not sure about network bits.

(In reply to Olli Pettay [:smaug] from comment #6)
> RefreshDriver handling is also rather special.

I think refresh driver bits actually get handled by redirecting the timer handlers in the refresh driver (see part 2, attachment 814517 [details] [diff] [review]).  You might be thinking of other refresh driver bits, though.

Comment 12

[(no longer active)]

(In reply to Nathan Froyd (:froydnj) from comment #11)
> I didn't say this was perfect! :)

Haha, sorry if I was being too negative in my comments.  I usually don't point out the parts of a patch that I like explicitly.  :-)

> (In reply to :Ehsan Akhgari (needinfo? me!) from comment #7)
> > This is only supposed to handle nsIRunnable's, right?  Couldn't you do the
> > same thing much more simply by wrapping the nsIRunnables posted to a
> > document inside another runnable object which knows to update the runtime
> > for the document?  (Of course the dynamic allocation cost of those wrapper
> > objects could very well be unacceptable.)
> 
> This sounds very much like what this patch is doing (see TaskQueueRunnable).
> Could
> you explain a little further the differences between what you're proposing
> and what
> the patch currently does?

My approach would only modify nsIDocument::DispatchToTaskQueue, something like this:

 nsresult
 nsIDocument::DispatchToTaskQueue(nsIRunnable* aRunnable)
 {
   return NS_DispatchToCurrentThread(new WrapperRunnable(aRunnable, this));
 }

> > ::: content/base/public/nsIDocument.h
> > @@ +2424,5 @@
> > >  
> > > +  /**
> > > +   * The total amount of time running events associated with this document.
> > > +   */
> > > +  double mRunnableTime;
> > 
> > Please specify the unit of time used here.  Also, if this is milliseconds,
> > please also document that you're tracking microseconds as digits after the
> > decimal point (you are, right? :-)
> 
> Well, they are certainly getting tracked, but we're truncating this to an
> integer for
> display in about:memory in any event.

Sounds good.  It should still be clearly documented.

> > ::: content/base/src/nsDocument.cpp
> > @@ +1330,5 @@
> > > +private:
> > > +  friend class nsDocument;
> > > +  friend class TaskQueueRunnable;
> > > +
> > > +  nsIDocument* mDocument;
> > 
> > This is very fragile.  What if somebody else obtains a strong pointer to
> > TaskQueue and then calls GetDocument() when TaskQueue's reference from
> > nsIDocument has been cleared out?
> 
> Nobody but nsIDocument can access TaskQueues, at least not as TaskQueues. 
> As |nsIEventTarget|s, yes,

Yes, I meant as event targets.

> but in those cases I think the non-refcounted
> pointer here is OK.  I tried to make this work with nsCOMPtrs, but ran into
> issues.  It's possible I wasn't trying hard enough.

I don't understand what the issues were.  You should just tell the cycle collector about this object and the rest should work fine, I guess.

> (In reply to :Ehsan Akhgari (needinfo? me!) from comment #9)
> > Also, what about all of the places where we manually create runnables to do
> > work for a given document?
> 
> I suspect I am ignorant of most of those places.  Creating things for
> nsContentUtils::AddScriptRunner was one place that stuck out to me, though I
> wasn't sure that time accrued to those runnables wouldn't get double-counted
> somehow.  Please point out others!

I am not sure if you're asking for a comprehensive list or not.  If yes, please ask on dev.platform!  If no, here is a particularly tricky example: MediaStreamGraph.  It talks tot he main thread by message passing and it can do work on behalf of one or more documents in its own thread.

> And if you have any ideas for discovering places akin to the purpose DMD
> serves for about:memory...

Hmm, I would start by auditing anywhere that we post something to an event target.  For dynamic analysis, you could potentially look into keeping a hashtable of all runnables that _a_ document knows about and measure the time for all runnables run from the event queue and report those not in that hashtable that take a significant amount of time (potentially using RTTI to get the type names of the runnables or something.)  But that would be a large project, not sure what you're signing up for here!

Another approach is to draw a line in the sand and only decide to go so much of the way.

> > What about the work that we do for a document on
> > a background thread?
> 
> Like HTML parsing?  That could probably be handled.  Not sure about network
> bits.

Those, and lots of other examples...

Comment 13

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

(In reply to Nathan Froyd (:froydnj) from comment #11)
> (In reply to Olli Pettay [:smaug] from comment #6)
> > RefreshDriver handling is also rather special.
> 
> I think refresh driver bits actually get handled by redirecting the timer
> handlers in the refresh driver (see part 2, attachment 814517 [details] [diff] [review]
> [diff] [review]).  You might be thinking of other refresh driver bits,
> though.
I don't see any refreshdriver things there.

We have, IIRC, only two timers for Refreshdrivers, and we end up calling animationframecallbacks and
flushing layout on many documents at once.

Comment 14

[Nathan Froyd [:froydnj]]

(In reply to Olli Pettay [:smaug] from comment #13)
> (In reply to Nathan Froyd (:froydnj) from comment #11)
> > (In reply to Olli Pettay [:smaug] from comment #6)
> > > RefreshDriver handling is also rather special.
> > 
> > I think refresh driver bits actually get handled by redirecting the timer
> > handlers in the refresh driver (see part 2, attachment 814517 [details] [diff] [review]
> > [diff] [review]).  You might be thinking of other refresh driver bits,
> > though.
> I don't see any refreshdriver things there.
> 
> We have, IIRC, only two timers for Refreshdrivers, and we end up calling
> animationframecallbacks and
> flushing layout on many documents at once.

Oh, you're right.  My mistake.  I was thinking of earlier iterations of the refresh driver.

(In reply to :Ehsan Akhgari (needinfo? me!) from comment #12)
> (In reply to Nathan Froyd (:froydnj) from comment #11)
> > I didn't say this was perfect! :)
> 
> Haha, sorry if I was being too negative in my comments.  I usually don't
> point out the parts of a patch that I like explicitly.  :-)

Was there anything you liked? ;)  I kid, I kid!

> > (In reply to :Ehsan Akhgari (needinfo? me!) from comment #7)
> > > This is only supposed to handle nsIRunnable's, right?  Couldn't you do the
> > > same thing much more simply by wrapping the nsIRunnables posted to a
> > > document inside another runnable object which knows to update the runtime
> > > for the document?  (Of course the dynamic allocation cost of those wrapper
> > > objects could very well be unacceptable.)
> > 
> > This sounds very much like what this patch is doing (see TaskQueueRunnable).
> > Could
> > you explain a little further the differences between what you're proposing
> > and what
> > the patch currently does?
> 
> My approach would only modify nsIDocument::DispatchToTaskQueue, something
> like this:
> 
>  nsresult
>  nsIDocument::DispatchToTaskQueue(nsIRunnable* aRunnable)
>  {
>    return NS_DispatchToCurrentThread(new WrapperRunnable(aRunnable, this));
>  }

Ah, but then you miss out on anything that doesn't go through that call (setTimeout &friends is the biggest example).  You need GetTaskQueue() so things off of timers will be properly accounted for.  Of course, that does remind me that I need to modify that function properly to dispatch through the task queue as well--an oversight on my part!

> > Well, they are certainly getting tracked, but we're truncating this to an
> > integer for
> > display in about:memory in any event.
> 
> Sounds good.  It should still be clearly documented.

Indeed.  No argument from me here!

> > but in those cases I think the non-refcounted
> > pointer here is OK.  I tried to make this work with nsCOMPtrs, but ran into
> > issues.  It's possible I wasn't trying hard enough.
> 
> I don't understand what the issues were.  You should just tell the cycle
> collector about this object and the rest should work fine, I guess.

Maybe.  I will try again and see.

> I am not sure if you're asking for a comprehensive list or not.  If yes,
> please ask on dev.platform!  If no, here is a particularly tricky example:
> MediaStreamGraph.  It talks tot he main thread by message passing and it can
> do work on behalf of one or more documents in its own thread.

I don't have a good answer for those sorts of things, especially since e.g. MediaStreamGraph doesn't know about documents itself.  I guess maybe things getting passed to MediaStreamGraph would have to be wrapped appropriately...

I am willing to draw a line in the sand for catching most basic usages of JS (events handlers from javascript, timeouts, etc.) and "a good chunk of" nsIRunnables posted; MediaStreamGraph and things like it would be out of scope for at least the initial implementation.

Comment 15

[Firefox Bug Husbandry Bot]

https://bugzilla.mozilla.org/show_bug.cgi?id=1472046

Move all DOM bugs that haven't been updated in more than 3 years and has no one currently assigned to P5.

If you have questions, please contact :mdaly.