1333131 - [meta] Speed up web console startup time

Status: NEW

(DevTools :: Console, task)

Description

[Alexandre Poirot [:ochameau]]

The new console is significantly slower to load compared to the old xul one.
I'm convinced there is low hanging fruits that could be identified via the profiler.
I already saw:
- 3 to 4 instances of react module being loaded during console load.
- All reps modules: devtools/client/shared/components/reps/*.js are loaded at startup and is a significant part of the load time
- there is still framework/toolbox/actors code that may be optimized (protocol.js loaded in the parent process for ex) This is not a "new console" regression but worth looking.

Comment 1

[Alexandre Poirot [:ochameau]]

Also, today we load both xul and html documents. I don't see it clearly as a performance issue in the profiler, but I easily imagine it has a significant impact?
This is being tracked by bug 1326937.

Comment 2

[Alexandre Poirot [:ochameau]]

I was mislead by the fact that we are seeing XUL buttons briefly and thought that two documents we involved.
But that is false assumption. We still only have only one xul document for now. bug 1326937 should not lead to any performance issue at first sight.

Comment 3

[Alexandre Poirot [:ochameau]]

On the cost of duplicated react instances.

Here is a profile of webconsole startup on an empty document:
  https://clptr.io/2jK1gqH
Profiler reports between 30 and 40ms for each isntance.
It is interesting to see you can easily identify the module load versus just some react function call.
See the big block around 2s, the next one just after 2.2s, then around 2.5s and the last one after 2.7s.

On this run I got react module loaded 4 times from:
 - devtools/client/framework/toolbox.js:510:12
 - devtools/client/webconsole/new-console-output/new-console-output-wrapper.js:7:15
 - devtools/client/webconsole/net/net-request.js:7:15
 - devtools/client/webconsole/webconsole.js:232:16

It is not clear why the loader isn't caching the module. I would somewhat understand that we get duplicated instances between internal loader and browser loader but that can't explain 4 instances!

Comment 4

[Tim Nguyen :ntim]

I would assume passing in commonLibRequire like for the netmonitor fixes the issue: https://dxr.mozilla.org/mozilla-central/source/devtools/client/netmonitor/netmonitor.js#18

Comment 5

[Tim Nguyen :ntim]

Attachment: Use toolbox React instance

Profile: https://clptr.io/2loO8aH

(I also recorded a reference for comparison, but somehow cleopatra decided to get rid of it, even though I made it public)

Comment 6

[Tim Nguyen :ntim]

(In reply to Alexandre Poirot [:ochameau] from comment #0)
> - All reps modules: devtools/client/shared/components/reps/*.js are loaded
> at startup and is a significant part of the load time

I was looking at this, and unfortunately, it would require some significant changes to reps to avoid this. We need to load all reps, because the code currently calls supportsObject() on every single rep, to detect which rep to use. See: https://dxr.mozilla.org/mozilla-central/source/devtools/client/shared/components/reps/rep.js#135


One thing that could help, that is currently worked on, is the reps bundle: https://dxr.mozilla.org/mozilla-central/source/devtools/client/shared/components/reps/reps.js

We would probably save a bit of time requiring things I guess.

Comment 7

[Alexandre Poirot [:ochameau]]

Comment on attachment 8834754 [details] [diff] [review]
Use toolbox React instance

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

With this patch:
https://perf-html.io/public/0b39b5f6d5601362b1863773e50c0dcdf52d48fa/calltree/?jsOnly&search=react&thread=0

Without:
https://perf-html.io/public/14f941494d44855ca81c8b5c9818c866ec0cf101/calltree/?jsOnly&search=react&thread=0

Here is the few loads we used to have without with patch:
38ms from toolbox.js - This is the only one load that should happen
28ms for duplicated load from new-console-output.js - Removed, fixed!
26ms from net-request.js - Still happen, reported in bug 1309826 comment 24. This is related to netmonitor.
29ms from webconsole.js - Removed, fixed!

::: devtools/client/webconsole/new-console-output/main.js
@@ +17,5 @@
> +
> +this.NewConsoleOutput = function (parentNode, jsterm, toolbox, owner, serviceContainer) {
> +  NewConsoleOutputWrapper = BrowserLoader({
> +    baseURI: "resource://devtools/client/webconsole/new-console-output/",
> +    commonLibRequire: toolbox.browserRequire,

Should NewConsoleOutputWrapper be cached or is it called only once?

Comment 8

[Alexandre Poirot [:ochameau]]

Could you proceed with this patch in another bug, I would like to keep this one as a meta.
I think there is more to do to improve console load perfs.

Comment 9

[Alexandre Poirot [:ochameau]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=55717cd4db29

Comment 10

[Tim Nguyen :ntim]

(In reply to Alexandre Poirot [:ochameau] from comment #7)
> Comment on attachment 8834754 [details] [diff] [review]
> Use toolbox React instance
> 
> Review of attachment 8834754 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> With this patch:
> https://perf-html.io/public/0b39b5f6d5601362b1863773e50c0dcdf52d48fa/
> calltree/?jsOnly&search=react&thread=0
> 
> Without:
> https://perf-html.io/public/14f941494d44855ca81c8b5c9818c866ec0cf101/
> calltree/?jsOnly&search=react&thread=0

Thanks for the profiles and the talos runs!

> 26ms from net-request.js - Still happen, reported in bug 1309826 comment 24.
Actually, it seems like from here: [0]. The whole net directory (HTTP inspector) is unused by the new console (the plan is to use the network monitor react/redux components instead of HTTPi for the new console). So it should be possible just to avoid loading the script here [1]. This load should just go away once the new console is enabled by default.

[0]: https://dxr.mozilla.org/mozilla-central/source/devtools/client/webconsole/net/main.js#14
[1]: https://dxr.mozilla.org/mozilla-central/source/devtools/client/webconsole/webconsole.xul#32

Comment 11

[Alexandre Poirot [:ochameau]]

The final talos results (still processing):
https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=4b88f6d05f24e140894cdc702b72153bfa4727e8&newProject=try&newRevision=8d32550eac173e64593ccef78823797cda827f3a&framework=1

(In reply to Tim Nguyen :ntim from comment #10)
> 
> > 26ms from net-request.js - Still happen, reported in bug 1309826 comment 24.
> Actually, it seems like from here: [0]. The whole net directory (HTTP
> inspector) is unused by the new console (the plan is to use the network
> monitor react/redux components instead of HTTPi for the new console). So it
> should be possible just to avoid loading the script here [1]. This load
> should just go away once the new console is enabled by default.

I'm all up for even more lazyness/removal of useless!
But I imagine netmonitor will also have to correctly use BrowserLoader and commonLibRequire to prevent loading multiple reacts when opening the netmonitor.

Comment 12

[Julien Wajsberg [:julienw]]

Hey,

here is a new profile I took today with latest nightly: https://perfht.ml/2otWtP8

Its characteristics is that there are a lot of messages (exactly 903) with about 2/3 logging complex objects (sequential redux store states).

Comment 13

[Julien Wajsberg [:julienw]]

> Its characteristics is that there are a lot of messages (exactly 903) with about 2/3 logging complex objects (sequential redux store states).

I mean, they're already in the "console cache" when I open the console panel.

Comment 14

[Brian Grinstead [:bgrins]]

Unblocking Bug 1308219 since this is a metabug - the dependencies block it instead

Comment 15

[Alexandre Poirot [:ochameau]]

Here is some history about console performance seen by DAMP.

* First important fact is that DAMP only covers new frontend since July 25th.
New frontend regressed console.bulklog test by +104%:
https://treeherder.mozilla.org/perf.html#/graphs?timerange=31536000&series=mozilla-central,1418550,1,1&zoom=1500954570662.4949,1501015657146.541,112.70277246047402,248.70532706955532&selected=%5Bmozilla-central,459fda730a723ec8a755cbb7629ea42e070a29b5,231481,302129826,1%5D

Note that the other console API test (console.streamlog) seems to never detect any performance change:
https://treeherder.mozilla.org/perf.html#/graphs?timerange=31536000&series=mozilla-central,1418553,1,1

* console.open test only reports one regression, which seems to be resolved two days after:
https://treeherder.mozilla.org/perf.html#/graphs?timerange=31536000&series=mozilla-central,1418481,1,1&zoom=1502746193470.4434,1503137698582.1895,859.7014286498265,1199.2536286456395&selected=%5Bmozilla-central,0387b9e9be2033aedb2811277a29431cf678b7b9,240787,311261227,1%5D
  It regressed on August 16th by +14% on this changelog:
  https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d25db0546c92afa72d61685c9310104ef28235bd&tochange=6966f27380bf2e3e5ace3507f600852bd3ed9dbd
  And was fixed on August 18th  by -11%:
  https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=2fb6d8f7bac1be26b2b49b68fc34cc6decd7f339&tochange=a6a1f5c1d971dbee67ba6eec7ead7902351ddca2

It looks like there is no devtools change involved in both these changesets, so I'll assume that's just a platform regression.

* console.reload test reports a 28% win when switching to the new frontend on July 25th:
https://treeherder.mozilla.org/perf.html#/graphs?timerange=31536000&series=mozilla-central,1418483,1,1&zoom=1500672155916.405,1506894724000,1000,4313.432380334655&selected=%5Bmozilla-central,515d28c4b965a595b371a6313daaefc792e420d0,231481,302129802,1%5D
Then a 27% win is also reported on August 4th on this changelog:
  https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=5742919ec43f834cc061a96d87c767af1a1f7f75&tochange=32083f24a1bb2c33050b4c972783f066432194eb
  But again, no devtools changeset are in there. console.reload, until very recently was only looking at the time the debugged document took to reload, not at how much time the panel used to update after page reload. So I can easily imagine some platform changes for Quantum improved page load here.

On September 22% there is a 42% regression, but this is when I improved this test to cover panel update time in bug 1401187.

At the end, except the console.bulklog regression, there isn't much lesson to learn from recent DAMP history.