1396633 - devtools/client/framework/components/toolbox-controller.js::setCanRender is slow

Status: NEW

(DevTools :: Framework, defect, P3)

Description

[Alexandre Poirot [:ochameau]]

http://searchfox.org/mozilla-central/source/devtools/client/framework/components/toolbox-controller.js#88-91
This setCanRender method takes a significant part of the JS processing in the parent process when opening the inspector:
  https://perfht.ml/2eylj9K
(it is the first one to appear in the profiler when expanding the call tree)

It is unclear why it takes so much time, it looks like no module loading is involved here and only react is computing here.

Comment 1

[Alexandre Poirot [:ochameau]]

Using patch from bug 1390093, I get these two reports during setCanRender call:

ToolboxToolbar
props
Unavoidable re-render.
before  Object { L10N: Object, currentToolId: null, selectTool: function (), closeToolbox: function (), focusButton: function (), toggleMinimizeMode: function (), toolbox: Object, focusedButton: "toolbox-close", canRender: false, highlightedTool: "", 8 more… }
after  Object { L10N: Object, currentToolId: null, selectTool: function (), closeToolbox: function (), focusButton: function (), toggleMinimizeMode: function (), toolbox: Object, focusedButton: "toolbox-close", canRender: true, highlightedTool: "", 8 more… }
ToolboxController
state
Unavoidable re-render.
before  Object { focusedButton: "toolbox-close", currentToolId: null, canRender: false, highlightedTool: "", areDockButtonsEnabled: true, panelDefinitions: Array[8], hostTypes: Array[2], canCloseToolbox: true, toolboxButtons: Array[10], buttonIds: Array[22], 2 more… }

I'm not sure how to move from here.

Comment 2

[Alexandre Poirot [:ochameau]]

I'm wondering if someone with React knowledges can understand what is going on.
Here is profile focused on just this method: https://perfht.ml/2eycuwk

There is a lot of createInitialChildren (first part) and updateChildren (last part).
But there is a bunch of missing JS frame, we may miss some valuable information here.

Comment 3

[Alexandre Poirot [:ochameau]]

Attachment: Bug 1396633 - Prevent updating toolbox react component until it is ready to be displayed. ?

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

Comment 4

[Alexandre Poirot [:ochameau]]

Comment on attachment 8906952 [details]
Bug 1396633 - Prevent updating toolbox react component until it is ready to be displayed. ?

Greg, `canRender` was set to true slightly too soon, so that it had to update multiple times for nothing during toolbox load.
1/ _buildButtons calls setToolboxButtons after setCanRender()
http://searchfox.org/mozilla-central/source/devtools/client/framework/toolbox.js#1195
2/ setFocusedButton is also called after setCanRender()
But it was called with the same button, so no need to update either.
3/ shouldComponentUpdate should now prevent rendering at all until canRender is set

We go from:
  https://perfht.ml/2w3Ip38
  26.6ms for all JS files in framework/components/
to:
  https://perfht.ml/2w3IqEe
  36.2ms for all JS files in framework/components/

And this time, DAMP reports a win, between 3% to 9% for all panels open:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=mozilla-central&newProject=try&newRevision=0d223b985f81746880da0b1c6608fd0fa542297a&originalSignature=edaec66500db21d37602c99daa61ac983f21a6ac&newSignature=edaec66500db21d37602c99daa61ac983f21a6ac&filter=.open&framework=1&selectedTimeRange=172800

But setCanRender didn't changed. It still take a significant time:
  https://perfht.ml/2w40kXu
  14.1ms or 5.2% of overall js computation in parent process during toolbox opening.
Would you have any idea of why it do so many computations?
I see mostly react stacks: mountComponent, insertTreeBefore, setValueProperty:
  https://perfht.ml/2w3NqbV

Comment 5

[Greg Tatum [:gregtatum] (REO Fx132)]

Looking into it's taking 11ms to do the initial react render for the buttons, then an additional 4.8ms to update the buttonIDs. But without the React profiler markers you can't tell from the all tree what specifically it's spending time on. 11ms for an initial react render seems reasonable to me, but not ideal. The idea behind setCanRender was to defer any component updates until after the state changes had time to settle down.

A more disciplined approach which is beyond the scope and consideration of this bug would be to change over the state management of the toolbox and toolbar over to Redux. This would make reasoning about the performance of loading times better and easier to track state changes. My initial approach on de-XULing this component was to have feature parity with the existing logic, and I did that through trying to keep the state in the toolbar component, and then passing it all down or using connected components to better understand our update cycles.

I would recommend making this bug blocking bug 1399493, so that we could have more insight into what is going on here.

Comment 6

[Alexandre Poirot [:ochameau]]

(In reply to Greg Tatum [:gregtatum] [@gregtatum] from comment #5)
> I would recommend making this bug blocking bug 1399493, so that we could
> have more insight into what is going on here.

I would like to move forward with the first patch I already have for FF57.
This patch removes unnecessary updates/render while it doesn't really address the setCanRender slowness.

I may move it to a another bug if you want to keep this one to investigate setCanRender and block on bug 1399493.

Comment 7

[Greg Tatum [:gregtatum] (REO Fx132)]

Comment on attachment 8906952 [details]
Bug 1396633 - Prevent updating toolbox react component until it is ready to be displayed. ?

https://reviewboard.mozilla.org/r/178696/#review184430

::: devtools/client/framework/components/toolbox-controller.js:92
(Diff revision 1)
>      // Also set the currently focused button to this tool.
>      this.setFocusedButton(currentToolId);
>    },
>  
> +  shouldComponentUpdate() {
> +    return this.state.canRender;

Ah, nice one.

::: devtools/client/framework/toolbox.js:498
(Diff revision 1)
>          this._defaultToolId = "webconsole";
>        }
>  
>        // Start rendering the toolbox toolbar before selecting the tool, as the tools
>        // can take a few hundred milliseconds seconds to start up.
> +      buttonsPromise.then(() => {

Can you explain here in a comment that you are deferring until the buttons are built so that the component doesn't update twice? Otherwise it's not obvious why this is needed.

Comment 8

[Greg Tatum [:gregtatum] (REO Fx132)]

Thanks, I think these look like nice additions to lower the number of updates.

Comment 9

[Alexandre Poirot [:ochameau]]

Comment on attachment 8906952 [details]
Bug 1396633 - Prevent updating toolbox react component until it is ready to be displayed. ?

Moving this patch to bug 1399548.
In order to keep this bug for setCanRender still unexplained slowness.

Comment 10

[Alexandre Poirot [:ochameau]]

This setCanRender is still one of the slowest step in toolbox opening.
https://perfht.ml/2wQYMMB
  39ms or 6% of overall computation in parent process.

I just realized there is a bunch of calls to l10n during this method call.
There is only 6ms, but may be that is one reason of its slowness?

May be we could lazy load the tooltip:
  http://searchfox.org/mozilla-central/source/devtools/client/framework/components/toolbox-tab.js#27,42
Like what is done in netmonitor in bug 1407561, bug 1406312.