1399242 - Background panels cause massive overhead with React rendering

Status: RESOLVED FIXED

(DevTools :: General, defect, P2)

Description

[:Harald Kirschner :digitarald]

https://perfht.ml/2wn6RYD

This profile was recorded while the Debugger panel was active and Slack reloading. Several second hangs cause the devtools are janking the devtools.

Root cause is obvious: NetMonitor 64% and Console (64%) are both consuming most of the CPU time. In their stacks, nearly all of the time is spend in React.

Background panels should be aware of being in the background and *not* cause React updates. Processing data should be kept to a minimum, as much as neede to have the panel react quickly when being activated.

Comment 1

[:Harald Kirschner :digitarald]

Related issues in debugger with more profiles:

https://github.com/devtools-html/debugger.html/issues/3736
https://github.com/devtools-html/debugger.html/issues/3988

Comment 2

[Greg Tatum [:gregtatum]]

It seems like you could create a shared higher order component that would only render when in the foreground. Something along the lines of:


export const renderWhenVisible = Wrapped =>
  class RenderWhenVisible extends PureComponent {
    constructor(props) {
      super(props);
    }

    componentDidMount() {
      document.addEventListener("visibilitychange", function() {
        if (document.visibilityState) {
          this.forceUpdate();
        }
        // TODO - removeEventListener
      });
    }

    componentShouldUpdate() {
      return document.visibilityState === 'visible';
    }

    render() {
      return <Wrapped {...this.props} {...this.state} />
    }
  };

Comment 3

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1399242 - Prevent console react updates while console isn't visible.

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

Comment 4

[Alexandre Poirot [:ochameau]]

I don't know yet if try will be fully green, I had this one:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=3cb124cf84bedd4126e2126533ac24ec1211f115
before adding the change to new-console-output-wrapper.js

But I think we should start the reviews on this patch.
Please review and test this extensively.

We never had to freeze the panels like this in the past,
performances of them were good enough to keep them running in the background.

We will have to followup on each tool to fix their performance, we clearly regressed a lot.
This patch looks more like a workaround the bad performances of netmonitor and console.


Otherwise about this patch.
1/ I didn't introduced a generic React component, for two weak reasons:
  I'm not a react, nor console expert.
  I don't know exactly how and where to put such component.
  Like, should it be a parent of ConsoleOutput or a child? Or a mixin like what Mike did?

2/ Is ConsoleOutput the right place to put this?
  FilterBar will still update. Should we somehow put that in this? But how?
  http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/new-console-output-wrapper.js#171-179

3/ visibilitychange won't work as-is
  We are using xul iframe for loading panels (it won't change much if we were using html iframe).
  We are loading panel documents with chrome privileges and it looks like we can't toggle the visibility of chrome documents.
  http://searchfox.org/mozilla-central/source/docshell/base/nsDocShell.cpp#6296-6302
  It may work with <xul:iframe type="content" /> but then panel would run with content privileges.
  So I came up with a shim to fake visibilitychange, but that's unfortunate, we miss optimizations of C++ code that act
  differently when the document is known to be hidden.

4/ I had to tweak new-console-output-wrapper.js::dispatchMessageAdd
  As performance tool (at least), ends up calling this and this method wouldn't resolve when the console is hidden.

Comment 5

[Alexandre Poirot [:ochameau]]

(In reply to :Harald Kirschner :digitarald from comment #0)
> https://perfht.ml/2wn6RYD
>
> Root cause is obvious: NetMonitor 64% and Console (64%) are both consuming
> most of the CPU time. In their stacks, nearly all of the time is spend in
> React.

This profile is quite actionnable!
Expand the first line of the call tree until you see "render/messageNodes".
The profile says this is the main source of computation and it relates to this code:
  http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/components/console-output.js#111-125
It looks like we re-create all the react elements for all messages.

Here is another patch to see if caching them improves or break anything:
  https://hg.mozilla.org/try/rev/d7f63909545930af0080fb9a325af77ceb5c4c7f
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=3cb124cf84bedd4126e2126533ac24ec1211f115

Comment 6

[Alexandre Poirot [:ochameau]]

Note that while looking into profile details in bug 1399836,
I just realized that the main console slowness comes from redux and its reducers (bug 1371721 may improve)
and the React/shouldComponentUpdate trick won't be of much help here.
I don't know if we could "pause" the reducer somewhere when the console is hidden?
If yes, wouldn't it introduce a hang when switching back to the console?

Otherwise slowness on reload is mostly due to this reducers issue in console and
"newSource" being slow in the debugger, as reported here: https://github.com/devtools-html/debugger.html/issues/3736

Comment 7

[Greg Tatum [:gregtatum]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

https://reviewboard.mozilla.org/r/179674/#review185540

I have some comments about the code, I still need to actually run and try out the changes.

::: devtools/client/framework/toolbox.js:1707
(Diff revision 1)
>          node.setAttribute("aria-selected", "true");
>        } else {
>          node.removeAttribute("selected");
>          node.removeAttribute("aria-selected");
>        }
> +      // The webconsole is very special, its real panel is somewhere else in the DOM!?

Could you neutralize the tone of this comment a bit? webconsole is intentionally different since it needs to be split on the screen. I think it would be more helpful to a new code reader to have that information here.

::: devtools/client/framework/toolbox.js:1711
(Diff revision 1)
>        }
> +      // The webconsole is very special, its real panel is somewhere else in the DOM!?
> +      if (!node.id) {
> +        node = this.webconsolePanel;
> +      }
> +      // Poor's man visibilityState implementation for chrome documents

Please de-gender the comment.

::: devtools/client/framework/toolbox.js:1722
(Diff revision 1)
> +        let state = (node.id == id) ? "visible": "hidden";
> +        let win = iframe.contentWindow;
> +        let doc = win.document;
> +        if (doc.visibilityState != state) {
> +          // Use defineProperty, as by default `document.visbilityState` is read only
> +          Object.defineProperty(doc, "visibilityState", { value: state, configurable: true });

If visibilitychange doesn't work in a privileged document I would much prefer to wrap this logic up into a module, rather than modifying the document global in the middle of a 3000 line class. I believe we have several existing modules that use different code depending in this manner depending on whether they are run in a privileged environment or not. If this added behavior isn't 100% spec compliant I would like to put some safeguards and comments around its usage so we don't introduce unexpected behavior.

::: devtools/client/webconsole/new-console-output/components/console-output.js:52
(Diff revision 1)
>      networkMessagesUpdate: PropTypes.object.isRequired,
>      visibleMessages: PropTypes.array.isRequired,
>      networkMessageActiveTabId: PropTypes.string.isRequired,
>    },
>  
> +  shouldComponentUpdate() {

I would prefer to have a higher order component compared to a one-off component fix. This will let us apply the strategy wherever it is needed, and will separate out the concerns here.

Comment 8

[Greg Tatum [:gregtatum]]

I did some manual testing, and nothing weird happened. I'm not very familiar with the business logic of the console, so I don't trust my testing though.

Comment 9

[Alexandre Poirot [:ochameau]]

Attachment: debugger perf fixes

Harald, are you able to test this STR with a custom build?
The current patch, with the visibility hack doesn't address much performance issue here, if any?
At least, I haven't see any win regarding the webconsole.

This new patch should fix a couple of significant slowness in the debugger.

On this profiler it says SourcesTree.componentWillReceiveProps is 3x faster:
  From 9.9s without the patch https://perfht.ml/2xbiuE2
  To 2.8s with the patch https://perfht.ml/2xbxdi6

The things being slow in the debugger are:
 * using immutable: it really is slow compared to a naive, manual check,
 * using urlparse module: we should avoid using it or use `URL` from the web.

But I'm wondering how much is it going to speed up things on your setup.

Comment 10

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Do we still want this to land since you saw little improvement with it Alex ?

Comment 11

[Alexandre Poirot [:ochameau]]

I mentioned wins for the debugger patch, but I'm not sure about the visibilitychange one.

I don't think it is worth pursuing in the current state of our tools. Better invest time in actually fixing performance issues instead of hiding them like that. We have significant perf issues in all refactored panels that will happen whenever you are on that panel.

We never had to freeze background panels. Before all the react refactorings, panels were efficient enough to all be updated live.

The main slowness in console seems to live before react layer. It may no longer be true with reducer patch? That could be worth profiling again. So do not hesitate to apply this patch and report back if you see any win.

May be the story is different in the netmonitor, but I haven't looked at it yet.

I'm pushing back on this as this is a risky patch that may introduce many issues that won't be covered by any test.
So better it be really worth before enabling it.
Also note that we can't use DAMP to profile this as we close the toolbox before testing each tool.
It may be worth trying a one off run with all panels turned on and try with/without this patch.

Comment 12

[:Harald Kirschner :digitarald]

> We never had to freeze background panels. Before all the react refactorings, panels were efficient enough to all be updated live.

This isn't freezing per se but not doing unnecessary work, leaving the main thread free to do work the user cares about; even more important on the main thread. While they can keep getting data and processing it, tools in the background simply don't need to re-render react. We assume that we can update a UI in a few frames, so there is no overhead in triggering a react update when switching panels.

Comment 13

[Alexandre Poirot [:ochameau]]

(In reply to :Harald Kirschner :digitarald from comment #12)
> > We never had to freeze background panels. Before all the react refactorings, panels were efficient enough to all be updated live.
> 
> This isn't freezing per se but not doing unnecessary work, leaving the main
> thread free to do work the user cares about; even more important on the main
> thread.

I know, but when it comes to performance theory != reality. This is why we should take decisions from data and not theory.
I did wrote the patch, it is here available for anyone to test and tell me if that actually speeds something up.
At first sight, I haven't seen any noticeable win on simple scenarios.
I'm ready to move forward if anyone reports a win or find a STR to highlight one.

I had the exact same experience with trying to load JS in parallel in bug 1397341 and bug 1393086 (parallelize things between parent and content processes). Very appealing idea, some regression risk and hard to see a noticeable win.
Same thing. Patches are here, and I'm open to hear about any proof of win.

Comment 14

[:Harald Kirschner :digitarald]

> Same thing. Patches are here, and I'm open to hear about any proof of win.

I tried to reproduce and the background panels are always below 1%. This is what I would expect from an idle background state so the goal is probably achieved.

Comment 15

[Alexandre Poirot [:ochameau]]

(In reply to :Harald Kirschner :digitarald from comment #14)
> > Same thing. Patches are here, and I'm open to hear about any proof of win.
> 
> I tried to reproduce and the background panels are always below 1%. This is
> what I would expect from an idle background state so the goal is probably
> achieved.

Thanks for testing!

Yes, it looks like the setup significantly changed after bug 1371721 (console batch reducer).

STR:
* open mozilla.slack.com
* open console, switch to debugger
* start recording
* F5
* stop recording once everything is loaded

Profile on today's tip, *without* the visbilitystate patch:
  https://perfht.ml/2xbgMkd
Same profile *with* the patch:
  https://perfht.ml/2yEaFGu

It is quite hard to filter out by console module as netmonitor also contains "console".
"client/webconsole" looks like a pretty good filter.

With such filter, I get, *without* the patch a total of 341ms, i.e. about 8% of parent process computations.
And *with* the patch, 203ms, i.e. 5% of parent process computations.

*without* the patch, I get these frames from the console:
  * 211ms for React's setState
  * 62ms on netProviderEnhancer
  * 26ms for messagesAdd
  * 16ms on networkMessageUpdate
  * 10ms on onNetworkEventUpdate
  * random stuff

*with* the patch, I get these:
  * 25ms for React's setState (why is this still called?!)
  * 64ms on netProviderEnhancer
  * 53ms for messagesAdd
  * 22ms on networkMessageUpdate
  * 25ms on onNetworkEventUpdate
  * random stuff

While the win isn't that big when comparing total numbers (341 versus 203), there should be an extra overhead that isn't under the direct call tree of react frames. Any async operation on document rendering is ignored, so it should save some extra cycles.
I'll try to write a DAMP scenario to experience the background panels.

Comment 16

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/1-2/

Comment 17

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

I just rebased this patch.

Could you look into the console part of this patch?
Such patch would require thoughtful review on what could go wrong.
I have a very limited view on how things work between redux and react on the console, so I'll trust you on this one.
Also, could you help sketching tests to cover this?
Is there a good (complete) integration test we could copy and make it run while being on another panel?

Comment 18

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/2-3/

Comment 19

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

https://reviewboard.mozilla.org/r/179674/#review191052

Comment 20

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

https://reviewboard.mozilla.org/r/179674/#review185540

> If visibilitychange doesn't work in a privileged document I would much prefer to wrap this logic up into a module, rather than modifying the document global in the middle of a 3000 line class. I believe we have several existing modules that use different code depending in this manner depending on whether they are run in a privileged environment or not. If this added behavior isn't 100% spec compliant I would like to put some safeguards and comments around its usage so we don't introduce unexpected behavior.

I'm not sure it justifies its own module, but at least need its own function and some more comments.
See the reference to toolbox's function from react module.
But I'll reach platform folks before proceeding with this patch, to ensure we really can't do it at platform level.

> I would prefer to have a higher order component compared to a one-off component fix. This will let us apply the strategy wherever it is needed, and will separate out the concerns here.

Done. Hopefully it doesn't introduce any overhead.

Comment 21

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1399242 - Prevent console react updates while console isn't visible.

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

Comment 22

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1399242 - Add a test.

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

Comment 23

[Nicolas Chevobbe [:nchevobbe]]

Alex, I added a test for that in https://reviewboard.mozilla.org/r/187240/diff/1#index_header.
The issue is, the test should time out, and it does not (= messages are logged when we are on the inspector).
I think the VisibilityHandler is bypassed because ConsoleOutput is connected to redux directly.

I'm not sure if you saw the performance gains in Comment 15 with that specific patch though (I don't think so, you edited your review after that).

I'm not sure how to address this at the moment, I'll keep on thinking about it.

Comment 24

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8915960 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

https://reviewboard.mozilla.org/r/187238/#review192238

r- because this does not work as intended

Comment 25

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

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

Comment 26

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/3-4/

Comment 27

[Alexandre Poirot [:ochameau]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #23)
> The issue is, the test should time out, and it does not (= messages are
> logged when we are on the inspector).
> I think the VisibilityHandler is bypassed because ConsoleOutput is connected
> to redux directly.

Right, we can't use component hierarchy like that.
We could make VisibilityHandler be a child of ConsoleOutput, but it would complexity it for no good reason and still call its render method, where we compute messages list.
I went for mixin, but we could as well inline it, it is quite simple after all.
Or do a non-react module that we would have to be call on shouldComponentUpdate/componentDidMount/componentWillUnmount.

> Alex, I added a test for that in
> https://reviewboard.mozilla.org/r/187240/diff/1#index_header.

Looks like it now timesout with the new patch:
35 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_visibility_messages.js | Uncaught exception - waitFor - timed out after 500 tries.

Comment 28

[Nicolas Chevobbe [:nchevobbe]]

> Looks like it now timesout with the new patch:
> 35 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_visibility_messages.js | Uncaught exception - waitFor - timed out after 500 tries.

Probably because we never switch back to the console in the test. I did not add it so you can observe the issue.

Comment 29

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

https://reviewboard.mozilla.org/r/179674/#review192994

I'm a bit worried about using mixins. I'm not familiar with them, but it looks like it would be overridden (or override, i'm not sure) a shouldComponentUpdate declared in the class that uses the mixin.
I think this is error-prone, and it would be nice if we could find another solution. Does the higher order component solution would work if on ConsoleOutput we connect a VisibilityHandler component bound to the ConsoleOutput one in some way ? Maybe the VisibilitHandler could expose a `createVisibilityHandler(component)` that would return a component (not an instance), that would always render the `component` we passed to the function ?

::: devtools/client/shared/components/VisibilityHandler.js:8
(Diff revision 4)
> + * You can obtain one at http://mozilla.org/MPL/2.0/. */
> +
> +"use strict";
> +
> +/**
> + * Helper class to disable panel rendering when it is in background.

nit: s/class/object

::: devtools/client/webconsole/new-console-output/new-console-output-wrapper.js:202
(Diff revision 4)
>      // This is just for backwards compatibility with old tests, and should
>      // be removed once it's not needed anymore.
>      // Can only wait for response if the action contains a valid message.
>      let promise;
> -    if (waitForResponse) {
> +    // Also, do not expect any update while the panel is in background.
> +    if (waitForResponse && document.visibilityState === "visible") {

Not sure if we should add this condition.

Here I think the waitForResponse boolean is only used in tests, and we do want to wait for the message, even if the panel is not visible.

There is no risks waiting for those message when the console is hidden because:
- the event is fired here http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/new-console-output-wrapper.js#80
- and the function which emits it is only called in http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/components/Message.js#80 , i.e. when messages are displayed.

Comment 30

[Alexandre Poirot [:ochameau]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #29)
> Comment on attachment 8907996 [details]
> Bug 1399242 - Prevent console react updates while console isn't visible.
> 
> https://reviewboard.mozilla.org/r/179674/#review192994
> 
> I'm a bit worried about using mixins. I'm not familiar with them, but it
> looks like it would be overridden (or override, i'm not sure) a
> shouldComponentUpdate declared in the class that uses the mixin.

React does throw if it detects a collision. But yes, this is a known issue of mixins.

> I think this is error-prone, and it would be nice if we could find another
> solution. Does the higher order component solution would work if on
> ConsoleOutput we connect a VisibilityHandler component bound to the
> ConsoleOutput one in some way ? Maybe the VisibilitHandler could expose a
> `createVisibilityHandler(component)` that would return a component (not an
> instance), that would always render the `component` we passed to the
> function ?

I don't know how to implement such thing.
I don't see how to bind "ConsoleOutput" to VisibilityHandler,
nor confirm if redux props are going to be correctly propagated to ConsoleOutput?
I sounds quick hacky as well. I tried hacking by passing a function to connect()
but react really wants a class here.

> :::
> devtools/client/webconsole/new-console-output/new-console-output-wrapper.js:
> 202
> (Diff revision 4)
> >      // This is just for backwards compatibility with old tests, and should
> >      // be removed once it's not needed anymore.
> >      // Can only wait for response if the action contains a valid message.
> >      let promise;
> > -    if (waitForResponse) {
> > +    // Also, do not expect any update while the panel is in background.
> > +    if (waitForResponse && document.visibilityState === "visible") {
> 
> Not sure if we should add this condition.
> 
> Here I think the waitForResponse boolean is only used in tests, and we do
> want to wait for the message, even if the panel is not visible.

I commented about this in comment 4:
  > 4/ I had to tweak new-console-output-wrapper.js::dispatchMessageAdd
  >   As performance tool (at least), ends up calling this and this method wouldn't resolve when the console is hidden.

If I remember correctly it was for this test:
  devtools/client/performance/test/browser_perf-console-record-02.js

> There is no risks waiting for those message when the console is hidden
> because:
> - the event is fired here
> http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-
> console-output/new-console-output-wrapper.js#80
> - and the function which emits it is only called in
> http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-
> console-output/components/Message.js#80 , i.e. when messages are displayed.

The risk is that this will never resolves dispatchMessagesAdd.
As you say here, the event is only going to be emitted if Message.js::Message.componentDidMounnt is called.
So only when the console is visible.
But here, perf panel test highlights that we do call console APIs when it is hidden and expect jsterm.execute to resolve here:
http://searchfox.org/mozilla-central/source/devtools/client/webconsole/jsterm.js#373-374

Comment 31

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

(In reply to Alexandre Poirot [:ochameau] from comment #30)
> (In reply to Nicolas Chevobbe [:nchevobbe] from comment #29)
> > I think this is error-prone, and it would be nice if we could find another
> > solution. Does the higher order component solution would work if on
> > ConsoleOutput we connect a VisibilityHandler component bound to the
> > ConsoleOutput one in some way ? Maybe the VisibilitHandler could expose a
> > `createVisibilityHandler(component)` that would return a component (not an
> > instance), that would always render the `component` we passed to the
> > function ?
> 
> I don't know how to implement such thing.
> I don't see how to bind "ConsoleOutput" to VisibilityHandler,
> nor confirm if redux props are going to be correctly propagated to
> ConsoleOutput?
> I sounds quick hacky as well. I tried hacking by passing a function to
> connect()
> but react really wants a class here.

React docs have some notes about higher order components[1], which some libraries use when integrating with React.  Essentially they are functions with type component -> component.

Another option is a "wrapping component", like React Router[2].  This would be a component to hold the special functionality (visibility handling here), and then the "actual" components would be children of it.

(No idea if these things help here, just offering ideas.)

[1]: https://reactjs.org/docs/higher-order-components.html
[2]: https://github.com/ReactTraining/react-router/blob/master/packages/react-router-dom/docs/guides/quick-start.md

Comment 32

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/1-2/

Comment 33

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/4-5/

Comment 34

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Note that I submitted a platform patch in bug 1405342 to try to get rid of this patch. But I have no idea if that is going to be that's going to land, nor when.

Comment 35

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/5-6/

Comment 36

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

If some React/Redux expert want to shime in, feel free to do suggest something that actually works.
But I'm not sure it is worth blocking this patch because of this.
So I inlined the visibilitychange code into ConsoleOutput again.

I tweaked the test to ensure that messages are not rendered, but correctly put in the store.
And I fixed the split console, which was completely broken. I imagine I should add a test for this as well.

Comment 37

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8915960 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187238/diff/1-2/

Comment 38

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8915961 [details]
Bug 1399242 - Add a test.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187240/diff/1-2/

Comment 39

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Sorry it took me some times to answer to this.
So I quite liked the higher order component solution you wrote, and I managed to make it work in the console (see https://reviewboard.mozilla.org/r/187236/diff/2#index_header).
At first, I just checked by putting logs in ConsoleOutput's render, which weren't triggered when logging from content with the inspector selected.
I then wrote a test to make sure we do pause the rendering (we check if messages are rendered when the inspector is displayed, and listen for client events to make sure the messages were dispatched).

I think it's working quite well.
The only drawback I can see to this is that we may freeze a bit when switching back to the console if there's a lot of new messages to display.

Another approach in VisibilityHandler would be to allow the rendering when not visible using requestIdleCallback, so we don't freeze when selecting the console back.
A better approach of course would be to not freeze the console no matter how many messages we have to show :)

Comment 40

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/2-3/

Comment 41

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/6-7/

Comment 42

[Alexandre Poirot [:ochameau]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #39)
> Comment on attachment 8907996 [details]
> Bug 1399242 - Prevent console react updates while console isn't visible.
> 
> Sorry it took me some times to answer to this.
> So I quite liked the higher order component solution you wrote, and I
> managed to make it work in the console (see
> https://reviewboard.mozilla.org/r/187236/diff/2#index_header).

Thanks a lot, it was easy I the end, I missed the need of createElement call.
I merged that into my patch.

> At first, I just checked by putting logs in ConsoleOutput's render, which
> weren't triggered when logging from content with the inspector selected.
> I then wrote a test to make sure we do pause the rendering (we check if
> messages are rendered when the inspector is displayed, and listen for client
> events to make sure the messages were dispatched).

I had already augmented your previous test. I do check store to ensure the messages go all up to the store.
I also added a test against split console, which was broken in previous patch versions.

> I think it's working quite well.
> The only drawback I can see to this is that we may freeze a bit when
> switching back to the console if there's a lot of new messages to display.

I imagine we may have the exact same issue when opening the console for the first time.
So I'm not really stressed about that, we should ""just"" ensure the console performs well with bulk messages.

> Another approach in VisibilityHandler would be to allow the rendering when
> not visible using requestIdleCallback, so we don't freeze when selecting the
> console back.

requestIdleCallback isn't so magical. It fires quite quickly and would re-introduce a bunch of react updates.
But feel free to followup on this! I think there is better time spent on other optimizations ;)

> A better approach of course would be to not freeze the console no matter how
> many messages we have to show :)

+1!

Comment 43

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

https://reviewboard.mozilla.org/r/179674/#review194040

Looking good, thanks a lot Alex

Comment 44

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/3-4/

Comment 45

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/7-8/

Comment 46

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/8-9/

Comment 47

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/4-5/

Comment 48

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/9-10/

Comment 49

[Greg Tatum [:gregtatum]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

https://reviewboard.mozilla.org/r/187796/#review194236

This looks like a very reasonable way to get the visibility change behavior on the panels. Thanks for all of the comments to give such good context for the code.

Comment 50

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1399242 - Add DAMP test to track performance of background panels.

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

Comment 51

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/5-6/

Comment 52

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/10-11/

Comment 53

[Alexandre Poirot [:ochameau]]

It look me some time to craft a DAMP test to prevent regressing that as it is very easy to do so.

Here is a DAMP test that regress by 3x slower when you break panel visibility:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=8f45401bbca71ac78ba876279845b191daff0fcc&newProject=try&newRevision=ffd445548aad664621d98f00c5712934da5535a2&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&filter=background&framework=1

Comment 54

[Brian Grinstead [:bgrins]]

Comment on attachment 8925870 [details]
Bug 1399242 - Add DAMP test to track performance of background panels.

https://reviewboard.mozilla.org/r/197086/#review202316

::: testing/talos/talos/tests/devtools/addon/content/damp.js:465
(Diff revision 1)
> +    let url = "data:text/html;charset=UTF-8," + encodeURIComponent(`
> +      <script>
> +      var i = 0;
> +      // First log a significant amount of messages
> +      for(; i < 2000; i++) {
> +        console.log("log in backround", i);

typo: 'background' (here, and in the interval)

::: testing/talos/talos/tests/devtools/addon/content/damp.js:469
(Diff revision 1)
> +      for(; i < 2000; i++) {
> +        console.log("log in backround", i);
> +      }
> +      // Force some render by logging asynchronously
> +      let interval = setInterval(function () {
> +        for(; i < 100; i++) {

shouldn't this be `for (i = 0; i < 100; i++)`? `i` will be 2000 otherwise and this loop will never enter

::: testing/talos/talos/tests/devtools/addon/content/damp.js:474
(Diff revision 1)
> +        for(; i < 100; i++) {
> +          console.log("log in backround", i);
> +        }
> +      }, 0);
> +      window.onload = function () {
> +        clearInterval(interval);

Why is the interval cleared on load?

If we are just trying to measure reload time then maybe we should remove all the interval code from this test? (see comment above - it isn't doing anything right now anyway).

Comment 55

[Alexandre Poirot [:ochameau]]

Comment on attachment 8925870 [details]
Bug 1399242 - Add DAMP test to track performance of background panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/197086/diff/1-2/

Comment 56

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/6-7/

Comment 57

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/11-12/

Comment 58

[Alexandre Poirot [:ochameau]]

(In reply to Brian Grinstead [:bgrins] from comment #54)
> Comment on attachment 8925870 [details]
> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:469
> (Diff revision 1)
> > +      for(; i < 2000; i++) {
> > +        console.log("log in backround", i);
> > +      }
> > +      // Force some render by logging asynchronously
> > +      let interval = setInterval(function () {
> > +        for(; i < 100; i++) {
> 
> shouldn't this be `for (i = 0; i < 100; i++)`? `i` will be 2000 otherwise
> and this loop will never enter
> 
> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:474
> (Diff revision 1)
> > +        for(; i < 100; i++) {
> > +          console.log("log in backround", i);
> > +        }
> > +      }, 0);
> > +      window.onload = function () {
> > +        clearInterval(interval);
> 
> Why is the interval cleared on load?
> 
> If we are just trying to measure reload time then maybe we should remove all
> the interval code from this test? (see comment above - it isn't doing
> anything right now anyway).

Sorry, yes, this changeset was completely wrong.
I must have gone through too many variations of it to finally find what really expose background console issues.

I simplified the test even more by only opening the console to avoid unnecessary noise introduced by other panels that do not correctly freeze while in background.
It help reducing the others tests affected by this new one, but we can still see some having different numbers:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=b936f75369c3b32d4840fe0faf86ddf6c3b9e216&newProject=try&newRevision=4a2ec820a7d60609d915dec0739a67d3cd170d87&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyImportant=1&framework=1

Comment 59

[Alexandre Poirot [:ochameau]]

> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:465
> > +        console.log("log in backround", i);
> 
> typo: 'background' (here, and in the interval)

Note to self, I still need to address that.

Comment 60

[Brian Grinstead [:bgrins]]

Comment on attachment 8925870 [details]
Bug 1399242 - Add DAMP test to track performance of background panels.

https://reviewboard.mozilla.org/r/197086/#review203012

::: testing/talos/talos/tests/devtools/addon/content/damp.js:463
(Diff revision 2)
>  
> +  async _panelsInBackgroundReload() {
> +    let url = "data:text/html;charset=UTF-8," + encodeURIComponent(`
> +      <script>
> +      // Log a significant amount of messages
> +      for(let i = 0; i < 2000; i++) {

Note that we'll only ever 1000 messages rendered before the toolbox opens. Even though in the reload we would render all 2000 I don't see much of a purpose to it being this high - even 500 or 1000 would trigger a dramatic regression if the background panel started rendering

::: testing/talos/talos/tests/devtools/addon/content/damp.js:469
(Diff revision 2)
> +        console.log("log in backround", i);
> +      }
> +      </script>
> +    `);
> +    await this.testSetup(url);
> +    let {toolbox} = await this.openToolbox("webconsole");

Note that as of Bug 1391688, the toolbox will be considered opened once the messages in the viewport get rendered and the remaining ~1980 messages will get rendered after that.  So there will likely be overlap between those messages finishing rendering, and the options panel being opened / page reloading.


I think we should do something similar to allMessagesReceived in the `_consoleBulkLoggingTest` to make sure that we don't have this happen but I'm going to forward the review to Nicolas to see if he has any ideas.

Comment 61

[Alexandre Poirot [:ochameau]]

Comment on attachment 8925870 [details]
Bug 1399242 - Add DAMP test to track performance of background panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/197086/diff/2-3/

Comment 62

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/7-8/

Comment 63

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/12-13/

Comment 64

[Alexandre Poirot [:ochameau]]

(In reply to Brian Grinstead [:bgrins] from comment #60)
> Comment on attachment 8925870 [details]
> Bug 1399242 - Add DAMP test to track performance of background panels.
> 
> https://reviewboard.mozilla.org/r/197086/#review203012
> 
> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:463
> (Diff revision 2)
> >  
> > +  async _panelsInBackgroundReload() {
> > +    let url = "data:text/html;charset=UTF-8," + encodeURIComponent(`
> > +      <script>
> > +      // Log a significant amount of messages
> > +      for(let i = 0; i < 2000; i++) {
> 
> Note that we'll only ever 1000 messages rendered before the toolbox opens.
> Even though in the reload we would render all 2000 I don't see much of a
> purpose to it being this high - even 500 or 1000 would trigger a dramatic
> regression if the background panel started rendering

Using 500 is too low, I'm afraid it would completely disappear with one or two additional optimization made to console:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=7b2e90944eb37fb22c24331dcf7f09bc3b2cb1e7&newProject=try&newRevision=66b52384b1fa52f4f436f579b6e9c63130c07b56&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&framework=1

I remember having tried 1000 and it wasn't quite enough as well.
But I'll try again.

> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:469
> (Diff revision 2)
> > +        console.log("log in backround", i);
> > +      }
> > +      </script>
> > +    `);
> > +    await this.testSetup(url);
> > +    let {toolbox} = await this.openToolbox("webconsole");
> 
> Note that as of Bug 1391688, the toolbox will be considered opened once the
> messages in the viewport get rendered and the remaining ~1980 messages will
> get rendered after that.  So there will likely be overlap between those
> messages finishing rendering, and the options panel being opened / page
> reloading.
> 
> I think we should do something similar to allMessagesReceived in the
> `_consoleBulkLoggingTest` to make sure that we don't have this happen but
> I'm going to forward the review to Nicolas to see if he has any ideas.

Unfortunately, it is hard to track any progress as this patch aims to prevent any progress.
webconsole.hud.ui's "new-messages" event doesn't fire as the UI is frozen.
So we can't listen for that.
The regression we see on the following tests may only exist in the test *without* this perf fix.
*With* the test but *without* the patch, we will render all the messages in background,
this may take a while and most likely overlap.
*With* the test *and* the patch, we may not necessarely overlap.
At least that's the whole point of this test, ensure that reloading a page with lots of logs while
the console is in background has no additional cost. So waiting for page "load" should be enough.

The only thing I could think about is listening for console store updates, but is it really worth?

Comment 65

[Alexandre Poirot [:ochameau]]

(In reply to Alexandre Poirot [:ochameau] from comment #64)
> I remember having tried 1000 and it wasn't quite enough as well.
> But I'll try again.

1000 is even worse, it is hidden by noise. There is a >20% difference, but the base run has a much higher noise factor.
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=023f1473f63415720ffd333464481797e0ab33ca&newProject=try&newRevision=3d57fd8f362e62de36e1d76951f4efbf42ee8e40&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&framework=1

Comment 66

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8925870 [details]
Bug 1399242 - Add DAMP test to track performance of background panels.

https://reviewboard.mozilla.org/r/197086/#review204062

I think the test is fine here.

::: testing/talos/talos/tests/devtools/addon/content/damp.js:464
(Diff revision 3)
> +  async _panelsInBackgroundReload() {
> +    let url = "data:text/html;charset=UTF-8," + encodeURIComponent(`
> +      <script>
> +      // Log a significant amount of messages
> +      for(let i = 0; i < 1000; i++) {
> +        console.log("log in backround", i);

s/backround/background

Comment 67

[Nicolas Chevobbe [:nchevobbe]]

This is tricky to get right since we can't rely on any event or anything because we don't output anything.
I am unsure about what this damp test will serve for: we do have mochitests to make sure we don't do updates when in background right ? So if by mistake we change that, the mochitest will catch this.

Am I missing something ?

Comment 68

[Alexandre Poirot [:ochameau]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #67)
> This is tricky to get right since we can't rely on any event or anything
> because we don't output anything.

> I am unsure about what this damp test will serve for: we do have mochitests
> to make sure we don't do updates when in background right ? So if by mistake
> we change that, the mochitest will catch this.

The mochitest checks that we don't render, yes, but we still do things.
Actors and redux are still in place and may regress.
It may help optimizing console background perf even more.
Also, you can see it as a higher level test, less specific to implementation details,
and should reflect more what users see.

Comment 69

[Alexandre Poirot [:ochameau]]

So here is the DAMP test I would like to land, with 2k messages:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=42e45d7f84da84fe8591428db4a8dbe90b09a8ed&newProject=try&newRevision=6ea5de60af6ff8a2ea742febf1ddd9b87bdb84e3&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&showOnlyImportant=1&framework=1

It shows an impact on other tests, but only without this patch.
I looked at simple.inspector.open value on mozilla-central, and 848ms is what we typically get.
So this test should not introduce noise in the next tests if we have the background fix landed at the same time.

If this test appear to cause any trouble in future, do not hesitate to bug me about it or get rid of it.

Comment 70

[Alexandre Poirot [:ochameau]]

Comment on attachment 8925870 [details]
Bug 1399242 - Add DAMP test to track performance of background panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/197086/diff/3-4/

Comment 71

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/8-9/

Comment 72

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/13-14/

Comment 73

[Alexandre Poirot [:ochameau]]

Comment on attachment 8925870 [details]
Bug 1399242 - Add DAMP test to track performance of background panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/197086/diff/4-5/

Comment 74

[Alexandre Poirot [:ochameau]]

Comment on attachment 8916715 [details]
Bug 1399242 - Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/187796/diff/9-10/

Comment 75

[Alexandre Poirot [:ochameau]]

Comment on attachment 8907996 [details]
Bug 1399242 - Prevent console react updates while console isn't visible.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/179674/diff/14-15/

Comment 76

[Alexandre Poirot [:ochameau]]

Green try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e89d55b333a535e165822340c47d3561c233a192

Comment 77

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7eae6691b2f9
Add DAMP test to track performance of background panels. r=nchevobbe
https://hg.mozilla.org/integration/autoland/rev/84a7751bf23b
Ensure firing visibilitychange event and set document.visibiltyState attribute when hidding devtools panels. r=gregtatum
https://hg.mozilla.org/integration/autoland/rev/3742c29706eb
Prevent console react updates while console isn't visible. r=nchevobbe

Comment 78

[Cristina Coroiu [:ccoroiu]]

https://hg.mozilla.org/mozilla-central/rev/7eae6691b2f9
https://hg.mozilla.org/mozilla-central/rev/84a7751bf23b
https://hg.mozilla.org/mozilla-central/rev/3742c29706eb

Comment 79

[Gerry Chang [:gchang]]

Mass won't fix for 58. Let it ride the train.

Comment 80

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Attachment: Bug 1399242 - Do not render if the Net panel isn't currently selected;

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