1366693 - DevTools inspector slows down opening a site loading scripts sequentially

Status: NEW

(DevTools :: Inspector, enhancement, P2)

Description

[Julian Descottes [:jdescottes]]

Attachment: load_issue.zip

In the development environment for a side project, I sequentially load scripts as follows: 
- create a script tag for script N
- onload of the script tag, load script N+1

All this is served via localhost, so despite being a bit terrible, it should still be fast.
As of now I have ~200 scripts, and if some devtools are started when I reload the page I will experience really slow load times. I think only the inspector and netmonitor impact significantly the load time.

I isolated the loading part of my app in a small example attached here.

STRs:
- unzip the attachment
- serve the root and open it in FF (can not be reproduced if serving via file://)
- the time necessary to load all scripts should be displayed on the page when the load finishes
- compare the load times in a few scenarios:
  - devtools closed
  - devtools where only the console was opened
  - devtools where only the inspector was opened
  - devtools where only the netmonitor was opened

On my machine I get the following results (with cache enabled):
  - devtools closed: 0.5 seconds
  - devtools with console: 3 seconds
  - devtools with inspector: 32 seconds
  - devtools with netmonitor: 15 seconds

(all the other tools seem to perform the same way as the console, so not logging their results here)

Profiles (not sure the are super relevant, since the browser mostly seems to pause between two calls):
  - devtools closed: https://perfht.ml/2rsImuE
  - devtools with console: https://perfht.ml/2rsFLRz
  - devtools with inspector: https://perfht.ml/2rswDfn
  - devtools with netmonitor: https://perfht.ml/2rsDZja

Disclaimer: I know this looks like a stupid way of requesting scripts, but it's actually coming from the development environment of a side project I have.

Comment 1

[Patrick Brosset <:pbro>]

DevTools bug triage (filter on CLIMBING SHOES).

Comment 2

[Patrick Brosset <:pbro>]

I found that one thing that's taking time is creating new DocumentWalker instances in the WalkerActor (devtools/server/actors/inspector.js).
Indeed, any time we want to walk the DOM, we create a new instance of this thing, so to get siblings, parents, children, all sorts of things.
In the test page, we currently do this 4 times per node, so at least 1200 times (since 300 script nodes are added).

On my machine, adding some basic caching of DocumentWalkers improves from 35s to 30s the entire load time.
So, it's not huge, but it's still measurable. And doing this should help in the general case too.

I'll continue investigating other areas of improvements. I know a lot of time is spent on the client creating DOM for each script tag too, but I don't know how much impact this has on the network request slow down yet. I suspect it has one.

Comment 3

[Julian Descottes [:jdescottes]]

Attachment: Bug 1366693 - add throttling when retrieving mutations in inspector front;

Review commit: https://reviewboard.mozilla.org/r/187710/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/187710/

Comment 4

[Julian Descottes [:jdescottes]]

Comment on attachment 8916561 [details]
Bug 1366693 - add throttling when retrieving mutations in inspector front;

Let's just discuss about this. Throttling basically fixes the issue for my test case, brings down the loading time of the page to ~2 seconds which makes it usable.

Not sure if we want to go for this + I'd also like to discuss other improvements we could implement.

Comment 5

[Julian Descottes [:jdescottes]]

The patch attached above really only works because this specific test case is triggering a LOT of childList mutations on the same node, consecutively. While it solves my issue, we should try to find some more generic improvements for the inspector's performance. 

(In reply to Patrick Brosset <:pbro> from comment #2)
> I found that one thing that's taking time is creating new DocumentWalker
> instances in the WalkerActor (devtools/server/actors/inspector.js).
> Indeed, any time we want to walk the DOM, we create a new instance of this
> thing, so to get siblings, parents, children, all sorts of things.
> In the test page, we currently do this 4 times per node, so at least 1200
> times (since 300 script nodes are added).
> 
> On my machine, adding some basic caching of DocumentWalkers improves from
> 35s to 30s the entire load time.
> So, it's not huge, but it's still measurable. And doing this should help in
> the general case too.
> 
> I'll continue investigating other areas of improvements. I know a lot of
> time is spent on the client creating DOM for each script tag too, but I
> don't know how much impact this has on the network request slow down yet. I
> suspect it has one.

Same conclusion as you, I think we can improve the inspector actor performances by reusing DocumentWalkers. I guess I tried the same thing as you in the end, creating a map to cache documentwalkers etc... (the improvement was not dramatic so I investigated in a different direction after a bit)

One thing to note: one of the most costly operation when we create a walker is on our side to determine the starting node (with the logic for skipping to parent etc ...). Particularly the filter seems very costly with the following check taking most of the time:

>   if (!isInXULDocument(node) && (isXBLAnonymous(node) || isNativeAnonymous(node))) {

Looking at the perf profiles it is also interesting to see why we are creating so many walkers. The NodeActor form requires to create walkers in order to build three properties
- numChildren: which is not always used, could be retrieved later on demand
- parent: we get parentNode() to return the parent actorID (not sure this is actually used)
- inlineTextChild: this one seems harder to delay, but maybe we can speed it up by doing more checks on the rawNode and avoid creating a walker unless really necessary

It feels like our inspector actor forms have grown a bit too much. We can try to make the most frequent code paths faster (creating node actor forms for instance) and clearly flag all the methods that rely on document walkers as expensive and try as much as possible to reduce their usage.

Comment 6

[Julian Descottes [:jdescottes]]

Attachment: node actor improvements

Patrick: please also have a look at this patch. This one is focused around potential improvements for the creation of the node actor form. The main ideas are:
- pass the parent node actor ID to the constructor when possible
- cache the form object (and remove the cache whenever a mutation is received for this node)
- cache the standard tree filter results

With this, the scenario of the bug is 2 times faster. 

Some useful order of magnitude here, for each reload:
- children() is called 400 times
- NodeActor::form() is called 30,000 times

After that, the perf profiles don't seem to highlight another main perf bottleneck. Maybe after that we should focus on the perf of the client as well.

Comment 7

[Julian Descottes [:jdescottes]]

Attachment: node actor improvements

(had a debugger.js workaround leftover in the previous patch)

Comment 8

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8916819 [details] [diff] [review]
node actor improvements

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

::: devtools/server/actors/inspector.js
@@ +3195,5 @@
>           doc.documentElement &&
>           doc.documentElement.namespaceURI === XUL_NS;
>  }
>  
> +const filterMap = new Map();

`WeakMap` seems better if it can be used here (to avoid holding nodes alive).

Comment 9

[Patrick Brosset <:pbro>]

Comment on attachment 8916819 [details] [diff] [review]
node actor improvements

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

::: devtools/server/actors/inspector.js
@@ +244,5 @@
> +      form = this._formMemo;
> +    } else {
> +      let parentNodeActorID = this.parentNodeActorID;
> +      if (!parentNodeActorID) {
> +        let parentNode = this.walker.parentNode(this);

The filter and form caching seem to me like they would be responsible for a lot of the improvements you're seeing. Is avoiding this call to this.walker.parentNode also responsible for a visible improvement? Especially with the form caching in place.
Only looking at the code, it looks like it might not be worth the trouble of changing all of these call sites. But if it does make a big difference then I'm fine with it (in which case adding some jsdoc comments to the initialize method would be good).

@@ +3195,5 @@
>           doc.documentElement &&
>           doc.documentElement.namespaceURI === XUL_NS;
>  }
>  
> +const filterMap = new Map();

Please precede this line with a comment explaining why it's important to cache these filters.

@@ +3206,5 @@
>  function standardTreeWalkerFilter(node) {
> +  if (filterMap.has(node)) {
> +    return filterMap.get(node);
> +  }
> +  let result;

nit: please add an empty line before let result;

Comment 10

[Patrick Brosset <:pbro>]

(In reply to Julian Descottes [:jdescottes] from comment #4)
> Comment on attachment 8916561 [details]
> Bug 1366693 - add throttling when retrieving mutations in inspector front;
> 
> Let's just discuss about this. Throttling basically fixes the issue for my
> test case, brings down the loading time of the page to ~2 seconds which
> makes it usable.
> 
> Not sure if we want to go for this + I'd also like to discuss other
> improvements we could implement.
We discussed quickly on IRC yesterday. Do you still want me to take a look at this particular patch? I think you attached a new patch to bug 1171482 which might be better.

Comment 11

[Julian Descottes [:jdescottes]]

(In reply to Patrick Brosset <:pbro> from comment #10)
> (In reply to Julian Descottes [:jdescottes] from comment #4)
> > Comment on attachment 8916561 [details]
> > Bug 1366693 - add throttling when retrieving mutations in inspector front;
> > 
> > Let's just discuss about this. Throttling basically fixes the issue for my
> > test case, brings down the loading time of the page to ~2 seconds which
> > makes it usable.
> > 
> > Not sure if we want to go for this + I'd also like to discuss other
> > improvements we could implement.
> We discussed quickly on IRC yesterday. Do you still want me to take a look
> at this particular patch? I think you attached a new patch to bug 1171482
> which might be better.

Still interested in your feedback, mostly if you have concerns about the approach (holding on too many pending mutations for instance). Let's move the conversation to bug 1171482 for this part.

Comment 12

[Julian Descottes [:jdescottes]]

(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #8)
> Comment on attachment 8916819 [details] [diff] [review]
> node actor improvements
> 
> Review of attachment 8916819 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: devtools/server/actors/inspector.js
> @@ +3195,5 @@
> >           doc.documentElement &&
> >           doc.documentElement.namespaceURI === XUL_NS;
> >  }
> >  
> > +const filterMap = new Map();
> 
> `WeakMap` seems better if it can be used here (to avoid holding nodes alive).

Thanks for taking a look, you're right WeakMap is a better fit.

Comment 13

[Julian Descottes [:jdescottes]]

(In reply to Patrick Brosset <:pbro> from comment #9)
> Comment on attachment 8916819 [details] [diff] [review]
> node actor improvements
> 
> Review of attachment 8916819 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: devtools/server/actors/inspector.js
> @@ +244,5 @@
> > +      form = this._formMemo;
> > +    } else {
> > +      let parentNodeActorID = this.parentNodeActorID;
> > +      if (!parentNodeActorID) {
> > +        let parentNode = this.walker.parentNode(this);
> 
> The filter and form caching seem to me like they would be responsible for a
> lot of the improvements you're seeing. Is avoiding this call to
> this.walker.parentNode also responsible for a visible improvement?
> Especially with the form caching in place.
> Only looking at the code, it looks like it might not be worth the trouble of
> changing all of these call sites. But if it does make a big difference then
> I'm fine with it (in which case adding some jsdoc comments to the initialize
> method would be good).

Thanks for having a look!

I need to measure with and without the parentActor thing. Passing the parentActor was the first thing I tried, and then I added the caching, so they might be redundant. 

I don't think I have a good grasp of the lifecycle of the node actors, and I was a bit afraid that adding this caching mechanism might be too aggressive. Normally for a given node, if anything happens to the node or its descendants, we should get a mutation that will clear our caches. I am not really sure about what happens if the node gets reattached to a new parent. I don't want to clear the caches for the descendants of a node on every mutation because that would defeat the purpose of the improvement.

I am mostly concerned about:
- caching the filter: for instance there is a call to isInXULDocument(). This information might go stale if the node moves to a XUL document
- property hasEventListeners on NodeActor's form: this can be modified without getting a mutation for the node
- property parent on NodeActor's form: this can be modified if we move the node to another part of the tree

I will do more testing on scenarios where nodes are being moved around. Any other property I should be worried about?

Comment 14

[Patrick Brosset <:pbro>]

(In reply to Julian Descottes [:jdescottes] from comment #13)
> I don't think I have a good grasp of the lifecycle of the node actors, and I
> was a bit afraid that adding this caching mechanism might be too aggressive.
> Normally for a given node, if anything happens to the node or its
> descendants, we should get a mutation that will clear our caches. I am not
> really sure about what happens if the node gets reattached to a new parent.
> I don't want to clear the caches for the descendants of a node on every
> mutation because that would defeat the purpose of the improvement.
> 
> I am mostly concerned about:
> - caching the filter: for instance there is a call to isInXULDocument().
> This information might go stale if the node moves to a XUL document
Moving a node from one doc to another doc causes 2 mutation records. One addition for the new parent node in the new doc, and one removal from the old parent in the old doc.
> - property hasEventListeners on NodeActor's form: this can be modified
> without getting a mutation for the node
You could nullify the formMemo in _onEventListenerChange for this, or in queueMutation instead as a way to catch all types of "mutations".
> - property parent on NodeActor's form: this can be modified if we move the
> node to another part of the tree
When that happens, we receive 2 mutation records: one on the old parent (telling us that a child node was removed), and one of the new parent (telling us that a new child node was added). So I think your approach would work here, but you would also need to clear the cache on the child node being added.
> I will do more testing on scenarios where nodes are being moved around. Any
> other property I should be worried about?
- pseudoClassLocks can change too, but we fire a fake mutation when that happens I think, so queueMutation would be a good place to catch that.
- isDisplayed may change as a result of CSS changes that will be detected in _onReflows, so you'd need to clear the cache there too.

Comment 15

[Julian Descottes [:jdescottes]]

Attachment: reduced_test_case.html

Thanks for the detailed info Patrick! I'll try to see if we can workaround these use cases.

Now that we understand what triggers the slowdown, here is a reduced test that simply adds elements instead of loading script elements.

The key things to trigger the performance slowdown are:
- nodes must be added to a parent which is expanded in the markup view
- nodes need to be added asynchronously

This scenario triggers many childList mutations that are being sent to the markupview. Each childList mutation processed by the markup view results in a call to children(), which in turn will create many NodeActor forms (up to 30,000 total in my first test case). For now I tried two things:
- reduce the number of mutations by using throttling (patch now in Bug 1171482)
- improve the performance of NodeActor's form creation (current patch attached here)

The third option we can use here is to add some logic in the client, in markup-view.js, in order to stop spamming the server with children() calls.

Comment 16

[Fitti]

Super slow and colours all over the sight on https://news.futufit.com/