Closed Bug 1170848 Opened 9 years ago Closed 9 years ago

Inspector mutation handling slows page when there are many rapid mutations

Categories

(DevTools :: Inspector, defect)

Product:
DevTools
Component:
Inspector
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox41 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 41
Tracking Flags:
Tracking Status
firefox41 --- fixed

People

(Reporter: jryans, Assigned: jryans)

References

(Blocks 1 open bug,
URL
)

Details

Attachments

(5 files)

MozReview Request: Bug 1170848 - Only record numChildren for childList changes. r=pbrosset
39 bytes, text/x-review-board-request
pbro
: review+
Details
queue-mutations-WIP.patch
4.25 KB, patch
Details | Diff | Splinter Review
queue-mutations-skip-attributes.patch
6.85 KB, patch
Details | Diff | Splinter Review
mutation-perf-comparison.mp4
5.08 MB, video/mp4
Details
Page for Reproduction Steps
1.63 KB, text/html
Details 
STR:

1. Go to http://rcocks.github.io/
2. Let the page finish loading (there will be 10 entries)
3. Open the Inspector
4. Reload page

ER:

Page speed should stay as close to normal as possible

AR:

Page speed becomes massively slower.  A user in bug 1125322 comment 4 reported it actually crashes the tab for them.  For me, it just takes ~100x longer than without the Inspector open.

This page is basically is running a benchmark, so it's somewhat artificial, but still I think it shows we can optimize here.

For each of the 10 runs, the Inspector's |onMutations| handler is hit with 100,000 mutations to process.
Component: Developer Tools: WebIDE → Developer Tools: Inspector
I should add that this page also slows Chrome's inspector slightly, but our tools take much, much longer than Chrome's do for this page.
Assignee: nobody → jryans
Status: NEW → ASSIGNED
Bug 1170848 - Only record numChildren for childList changes. r=pbrosset
Attachment #8614445 - Flags: review?(pbrosset)
This first patch makes things much better, and seems to preserve semantics.  There's still room for more optimization, but this helps a lot.
(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #4)
> This first patch makes things much better, and seems to preserve semantics. 
> There's still room for more optimization, but this helps a lot.

Thanks for looking into this
(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #2)
> Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=2894ae322220

Seems to work much better. My one concern is that the markup view does not indicate anything is going on until the end, I wonder if there could be some way to visually indicate something like DOM Mutation Rate in the ui.
(In reply to Jeff Griffiths (:canuckistani) from comment #6)
> (In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #2)
> > Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=2894ae322220
> 
> Seems to work much better. My one concern is that the markup view does not
> indicate anything is going on until the end, I wonder if there could be some
> way to visually indicate something like DOM Mutation Rate in the ui.

Yeah, I notice this too.  STR: open http://rcocks.github.io/, quickly open inspector, then notice that <body> is empty for a while (even after the elements have been added).  Ryan, do you know why this is happening?  I can't tell if this is due to some kind of lag on the server side or what - it doesn't seem like this change should be causing the mutation to be delayed.
If there are 100000+ mutations then maybe the delay is just lag as those childList mutations wait to get sent to the frontend?
(In reply to Brian Grinstead [:bgrins] from comment #8)
> If there are 100000+ mutations then maybe the delay is just lag as those
> childList mutations wait to get sent to the frontend?
Most definitely. As we discussed some time ago Brian, I believe we need to throttle on the server-side. It's not going to be a big deal if mutations become visible in the markup-view only ~200ms after they really happen, and this would allow us to save a lot of processing server-side (and a lot of traffic) if we batched mutations on the server.
(In reply to Patrick Brosset [:pbrosset] [:patrick] [:pbro] from comment #9)
> (In reply to Brian Grinstead [:bgrins] from comment #8)
> > If there are 100000+ mutations then maybe the delay is just lag as those
> > childList mutations wait to get sent to the frontend?
> Most definitely. As we discussed some time ago Brian, I believe we need to
> throttle on the server-side. It's not going to be a big deal if mutations
> become visible in the markup-view only ~200ms after they really happen, and
> this would allow us to save a lot of processing server-side (and a lot of
> traffic) if we batched mutations on the server.

This is certainly meant for another bug, but here's a quick WIP where I am throttling the mutation notification.  It's not fully tested - and the childList mutations still seem to lag even with this applied, so I'm not sure what's going on with that.
(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #1)
> I should add that this page also slows Chrome's inspector slightly, but our
> tools take much, much longer than Chrome's do for this page.
What I'm seeing on Chrome (canary) with the devtools open is that the page slows down quite a bit too, less than in Firefox, but honestly, with Ryan's and Brian's patches applied, the difference isn't huge at all.
However the chromedevtools freeze completely. At first some of the page updates make it to the inspector, but then it freezes for a long time, well after the page has finished processing (it's purely a devtools UI problem because the page remains responsive). In Firefox, the inspector show the page updates a lot closer to when they actually happen. When the page has finished processing, everything up to date in the inspector, there's no freeze.
So with those two patches, I believe we're not that bad. I haven't looked if that comes primarily from one of the 2 patches or not.
Of course, without e10s, the firefoxdevtools UI freezes while the page processes.
I spent some more time playing with this, here are my thoughts about this:

- The simple fact of adding a mutation observer and running some code when mutations do occur is always going to slow down the page by some amount. As Ryan pointed out, this isn't a realistic case so we can live with the fact that the devtools slow down the page noticeably. But we can definitely do better than today.
A more realistic use case is something like http://bgrins.github.io/devtools-demos/inspector/jquery-animation.html
Indeed, there are a lot of js animations out there that simply mutate attributes really fast.

- I believe there's some room for experimentation with Brian's deferredTask fix.
It relies on a timeout that is used to batch the mutation events. Just out of curiosity, I've set that timeout to be 1 second. This made the performance of the page similar to Chrome's. Of course 1 second is way to much, but I believe we could run a few tests on more realistic use cases and decide what is the best timeout.

- I think we can also take Brian's patch one step further: instead of looping on all mutations in onMutations, just store them, and only loop when the deferredTask is executed.
In fact, by then, we might have stored a number of mutations that don't make sense anymore. Indeed, some nodes that were mutated might have been removed and, more importantly in this use case, some attributes might have been changed several times.
So, if we agree that the mutations events sent by the Walker don't need to represent exactly *all* mutations that occurred, then we have even more room for improvement.
We can:
- skip dead nodes when looping over the concatenated list of mutations,
- avoid attribute changes if there are later attribute changes for the same node/attributeName in the list.
I took this approach for a spin and witnessed a non negligible improvement with the test page.
Knowing the current consumers of the mutation events in the toolbox, I believe skipping some now-invalid mutations in event batches isn't going to be a problem (if it turns out that it becomes one in the future, we can always introduce an opt-in potentially lower-performance feature for this).

I'll upload the quick test patch I used for this and a comparison video.
Here's a side-by-side video of the page's performance:
- with the current devtools opened (no fix),
- with the numChildren fix applied,
- with the deferredTask fix applied on top,
- with the slightly different deferredTask approach + attribute skipping fix applied instead,
- and with the devtools closed.
Comment on attachment 8614445 [details]
MozReview Request: Bug 1170848 - Only record numChildren for childList changes. r=pbrosset

https://reviewboard.mozilla.org/r/9965/#review8929

Looks good to me, thanks for spotting this.
Attachment #8614445 - Flags: review?(pbrosset) → review+
(In reply to Patrick Brosset [:pbrosset] [:patrick] [:pbro] from comment #15)
> - with the deferredTask fix applied on top,
> - with the slightly different deferredTask approach + attribute skipping fix
> applied instead,
Hmm, after re-watching the video, it isn't obvious that skipping attributes helps, one seems to start a little earlier than the other, that's just an offset problem on the recording side, and then they seem to follow each other.
It felt like a bigger difference locally when I experimented, but I'd need numbers to back this.
The thing also is that in my patch I store the latest index of any given attribute change in a WeakMap, indexed by node, and I don't know the performance of indexing by nodes, we could use actorIDs instead but that would require looking them up in the refMap. Anyway, to be investigated ...
Comment on attachment 8615244 [details] [diff] [review]
queue-mutations-skip-attributes.patch

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

Thanks for putting together that comparison video, that's really helpful.  I think the numChildren fix is sufficient to 'fix' this bug and we should probably move this discussion into a separate bug - I filed Bug 1171482 for that.

::: toolkit/devtools/server/actors/inspector.js
@@ +2764,2 @@
>      if (needEvent) {
>        events.emit(this, "new-mutations");

Are you intentionally sending out the new-mutations event here?  I believe this will go back to the original behavior, where the server will send N new-mutations events (one for each change).

@@ +2777,5 @@
> +      this._mutationsToBeHandled = [];
> +      this._attributeChangingNodes = new WeakMap();
> +    }
> +
> +    // Run an inexpensive loop to store the last index of a given attribute

Note that there is similar logic in getMutations (which filters out changes on identical attribute names): https://github.com/mozilla/gecko-dev/blob/b3caa9d676228f9dca25a32ff2899b4c2380363d/toolkit/devtools/server/actors/inspector.js#L2712.  I'm not sure if this is doing the exact same thing or something different, but it could make sense to clear them out at this stage instead

@@ +2791,5 @@
> +      let index = this._mutationsToBeHandled.length + i;
> +
> +      let attributeIndexes = this._attributeChangingNodes.get(change.target);
> +      if (!attributeIndexes) {
> +        this._attributeChangingNodes.set(change.target, {

you could get a unique string ID to store in here instead of the node by doing something like this:

 let targetActor = this._refMap.get(change.target);
 targetActor.actorID
Hi, thanks all for looking into this, I am pleased that there were improvements that could be made.

I am attaching the index.html from http://rcocks.github.io so that it is preserved in case I later change what is available at that page.
(In reply to richard.cocks from comment #19)
> Created attachment 8615427 [details]
> Page for Reproduction Steps
> 
> Hi, thanks all for looking into this, I am pleased that there were
> improvements that could be made.
> 
> I am attaching the index.html from http://rcocks.github.io so that it is
> preserved in case I later change what is available at that page.

Thanks for sharing the test case, it's much easier to track down problems like this with a simple page like that.
(In reply to Brian Grinstead [:bgrins] from comment #18)
> Comment on attachment 8615244 [details] [diff] [review]
> queue-mutations-skip-attributes.patch
> 
> Review of attachment 8615244 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thanks for putting together that comparison video, that's really helpful.  I
> think the numChildren fix is sufficient to 'fix' this bug and we should
> probably move this discussion into a separate bug - I filed Bug 1171482 for
> that.
Thanks for that.
> ::: toolkit/devtools/server/actors/inspector.js
> @@ +2764,2 @@
> >      if (needEvent) {
> >        events.emit(this, "new-mutations");
> 
> Are you intentionally sending out the new-mutations event here?  I believe
> this will go back to the original behavior, where the server will send N
> new-mutations events (one for each change).
Well, yes, but I'm not calling queueMutation anymore at the end of onMutations. It only gets called when the deferred task gets executed.
> @@ +2777,5 @@
> > +      this._mutationsToBeHandled = [];
> > +      this._attributeChangingNodes = new WeakMap();
> > +    }
> > +
> > +    // Run an inexpensive loop to store the last index of a given attribute
> 
> Note that there is similar logic in getMutations (which filters out changes
> on identical attribute names):
> https://github.com/mozilla/gecko-dev/blob/
> b3caa9d676228f9dca25a32ff2899b4c2380363d/toolkit/devtools/server/actors/
> inspector.js#L2712.  I'm not sure if this is doing the exact same thing or
> something different, but it could make sense to clear them out at this stage
> instead
Wow, I had never noticed this! That's great, it means we already skip previous attribute mutations for given node/attributeName pairs, which means what I proposed doesn't break any assumption, it's already what we do.
However, I believe we can do better than the filter in getMutations. With this, we wait right until the front-end requests the list of mutations to filter, while with my approach, the filtering is done earlier, in onMutations, so we never need to store large amount of mutations and loop through them.
> @@ +2791,5 @@
> > +      let index = this._mutationsToBeHandled.length + i;
> > +
> > +      let attributeIndexes = this._attributeChangingNodes.get(change.target);
> > +      if (!attributeIndexes) {
> > +        this._attributeChangingNodes.set(change.target, {
> 
> you could get a unique string ID to store in here instead of the node by
> doing something like this:
> 
>  let targetActor = this._refMap.get(change.target);
>  targetActor.actorID
Yes but I wanted to avoid a lookup in this map, especially if the target hasn't been referenced yet, this will force the creation of an actor.
https://hg.mozilla.org/mozilla-central/rev/43eb38452b24
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
status-firefox41: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 41
(In reply to Patrick Brosset [:pbrosset] [:patrick] [:pbro] from comment #22)

Responded to this in Bug 1171482: https://bugzilla.mozilla.org/show_bug.cgi?id=1171482#c1
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: