817543 - [toolbox] is slow to start

Status: RESOLVED FIXED

(DevTools :: Framework, defect, P1)

Description

[Paul Rouget [:paul]]

Starting the inspector in a pre-toolbox build is pretty fast.

In a post-toolbox, it takes several seconds. This can be explained by bug 796006. But I have the feeling that it's not the only reason.

We need to have some real measurements, and understand where the regression lies (toolbox? inspector? both? are the other tools affected?).

Comment 1

[Rob Campbell [:rc] (:robcee)]

Also curious to know if the regression happens once the first time the tools are loaded or if it's repeatable. I think it's the latter, but need data.

Comment 2

[Girish Sharma [:Optimizer]]

After observing a little, I also think its the latter.

Comment 3

[Paul Rouget [:paul]]

Starting an empty tool (about:blank):

first time: ~350ms
second time: ~160ms

By "starting" I mean: from the XUL command to the "ready" event from the toolbox (fired once all the toolbox DOM operations are done). So it doesn't include loading the tool itself. Once "ready" is fired, the toolbox is built, the iframe that will hold the default tool is built too, but the tool is still loading.

In the case of the empty tool, the tool is loaded 50ms after the "ready" event. More data about that will come later.

One important thing: opening the toolbox feels jumpy because we first show a grey box, that then gets filled with the toolbox content. This happens because we first load "about:blank" in the host. Avoiding that and loading toolbox.xul directly will probably improve the performance and avoid this grey screen. But apparently, we need to load about:blank for some docshell swapping reasons that I don't understand yet.

Comment 4

[Paul Rouget [:paul]]

The "first time" value can go up to 500ms.

Comment 5

[Paul Rouget [:paul]]

All the Tilt code was loaded while opening the toolbox. Lazy loading makes us win ~50ms.

Not loading about:blank doesn't change much.

Comment 6

[Paul Rouget [:paul]]

First startup: 270ms is spent loading gcli.jsm.

Comment 7

[Victor Porof [:vporof][:vp]]

(In reply to Paul Rouget [:paul] from comment #6)
> First startup: 270ms is spent loading gcli.jsm.

holy moley

Comment 8

[Paul Rouget [:paul]]

Most of the time is spent in:

220ms in this.gcli = require('gcli/index');
 60ms between Toolbox._host.open() and Toolbox._host.once("ready")
 40ms to "just" load (DOM loaded) toolbox.xul
 25ms in Toolbox._buildTabs()
130ms in Toolbox._buildButtons() (gcli buttons)
 15ms in  Toolbox.selectTool()

Gcli is seriously slowing us down (220ms + 130ms).

I think the first 60ms can be avoided.

Comment 9

[Paul Rouget [:paul]]

The above numbers represents 83% of the time spent between clicking on a the menuitem and the final "ready" event (589ms).

Comment 10

[Paul Rouget [:paul]]

When the gcli start, we read and sort all the preferences in gcli/settings.startup. This takes 160ms (27% of total time). We can probably do that in a lazy way.

http://mxr.mozilla.org/mozilla-central/source/browser/devtools/commandline/gcli.jsm#4694

Comment 11

[Paul Rouget [:paul]]

These 3 lines, combined, take 30 extra milliseconds:

>  canon.addCommand(prefShowCmdSpec);
>  canon.addCommand(prefSetCmdSpec);
>  canon.addCommand(prefResetCmdSpec);

Comment 12

[Paul Rouget [:paul]]

15% spent in:

> let toolbarSpec = CommandUtils.getCommandbarSpec("devtools.toolbox.toolbarSpec");

Comment 13

[Paul Rouget [:paul]]

Reaching the pref doesn't take time. But loading the DeveloperToolbar.jsm does.

Comment 14

[Paul Rouget [:paul]]

This:

Cu.import("resource:///modules/devtools/CmdAddon.jsm");
Cu.import("resource:///modules/devtools/CmdBreak.jsm");
Cu.import("resource:///modules/devtools/CmdCalllog.jsm");
Cu.import("resource:///modules/devtools/CmdCalllogChrome.jsm");
Cu.import("resource:///modules/devtools/CmdConsole.jsm");
Cu.import("resource:///modules/devtools/CmdCookie.jsm");
Cu.import("resource:///modules/devtools/CmdDbg.jsm");
Cu.import("resource:///modules/devtools/CmdEcho.jsm");
Cu.import("resource:///modules/devtools/CmdEdit.jsm");
Cu.import("resource:///modules/devtools/CmdExport.jsm");
Cu.import("resource:///modules/devtools/CmdInspect.jsm");
Cu.import("resource:///modules/devtools/CmdJsb.jsm");
Cu.import("resource:///modules/devtools/CmdPagemod.jsm");
Cu.import("resource:///modules/devtools/CmdResize.jsm");
Cu.import("resource:///modules/devtools/CmdRestart.jsm");
Cu.import("resource:///modules/devtools/CmdScreenshot.jsm");
Cu.import("resource:///modules/devtools/CmdTilt.jsm");
Cu.import("resource:///modules/devtools/CmdScratchpad.jsm");

Is killing us.

This is called because:
Commands.jsm is loaded because:
DeveloperToolbar is loaded because:
CommandUtils is needed to build the buttons in the toolbox.

We should move CommandUtils into Toolbox.jsm (or at least the functions, not the exported symbol).

Comment 15

[Paul Rouget [:paul]]

Apparently, we need to load all of these to know if the command-button is a known command or not.
So moving commandUtils code into Toolbox.jsm won't help.

Comment 16

[Paul Rouget [:paul]]

To summarize my current research:

For an basic tool:

220ms in this.gcli = require('gcli/index'); Because we read and then sort all the preferences (gcli/settings).startup(). (comment 10).


130ms in Toolbox._buildButtons() (gcli buttons); Because to build the buttons, we need to know if the commands exist, so we have to load all the commands (comment 14 and comment 15).

There are other places where we can improve the code, but these are the 2 most obvious things we need to fix.

Comment 17

[Paul Rouget [:paul]]

Loading about:blank in the host doesn't have any significant impact.

Comment 18

[Paul Rouget [:paul]]

(In reply to Paul Rouget [:paul] from comment #17)
> Loading about:blank in the host doesn't have any significant impact.

We actually need it (to have something to swap in the devtools window).

Comment 19

[Paul Rouget [:paul]]

Using "visibility:collapse" on the iframe and switching it to "visibility:visible" prevents the empty pane. Less flickering, but the box shows up a little later. But it feels better.

Comment 20

[Paul Rouget [:paul]]

Conclusion:
- lazy load Tilt
- don't show the host iframe until ready (not the tool iframe)
- fix gcli loading (the pref thing and the multiple JSMs loading)

For the Gcli, we can:
- move this big chunk of JSMs into one JSM
- postpone the creation of the buttons (timeout 500ms?)
- not require to read all the commands, and assume they exist, and load all the commands only when the button is pressed

For the pref thing, I don't know. I need Joe here.

Comment 21

[Paul Rouget [:paul]]

Joe - can you take a look at comment 16 and comment 20 and tell me what you think.

Comment 22

[Joe Walker [:jwalker]]

Attachment: This should solve the gcli/settings/prefs part of the puzzle

Comment 23

[Paul Rouget [:paul]]

Comment on attachment 691784 [details] [diff] [review]
This should solve the gcli/settings/prefs part of the puzzle

The preferences are still read and sorted as soon as gcli.jsm is loaded.

Comment 24

[Paul Rouget [:paul]]

Work in progress (see PR here: https://github.com/paulrouget/mozilla-central/pull/1).

Starting the WebConsole:
- without this patch: ~750ms
- with this patch:    ~450ms

Lazy pref loading will probably bring us to a 50% improvement.

Comment 25

[Joe Walker [:jwalker]]

Attachment: v2

Comment 26

[Joe Walker [:jwalker]]

Paul - see also https://github.com/joewalker/gcli/pull/5

Comment 27

[Joe Walker [:jwalker]]

Attachment: v3

Just noticed a stray 'console.trace' in the patch. Removed.

Comment 28

[Paul Rouget [:paul]]

Attachment: patch v1

~40% improvements + better cold-startup experience.

Comment 29

[Paul Rouget [:paul]]

Attachment: patch v1

PR:  https://github.com/paulrouget/mozilla-central/pull/1
try: https://tbpl.mozilla.org/?tree=Try&rev=cf4006473118

Comment 30

[Paul Rouget [:paul]]

Not green:

- (NS_ERROR_FILE_NOT_FOUND)" location: "JS frame :: chrome://mochitests/content/browser/browser/devtools/commandline/test/browser_cmd_addon.js

- TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/markupview/test/browser_inspector_markup_edit.js | Test timed out (not intermittent as in bug 816953)

Comment 31

[Joe Walker [:jwalker]]

Not being able to find a test file really is bizarre. I re-triggered the Linux platform to see if there might be a build error that a clobber might help.
Maybe makefile commenting could have cause it?

Comment 32

[Paul Rouget [:paul]]

Not, it's normal. It's because we use CmdAddons.jsm and not BuiltinCommands.jsm in the test.

Comment 33

[Paul Rouget [:paul]]

Attachment: addendum

I'm still working actively on this. This patch fixes most of the problems, but I need to find something smarter than visibility:collapse because this has an effect on our focus mechanism.

Comment 34

[Paul Rouget [:paul]]

Attachment: addendum

This patches fixes the different test failures. Also, I removed the `show` mechanism, because hiding the toolbox before it's loaded causes problems in the tests that I didn't manage to fix (focus problems), and I want to get the remaining optimizations in Firefox 20.

Comment 35

[Paul Rouget [:paul]]

https://tbpl.mozilla.org/?tree=Try&rev=cc4f3c3d70db

Comment 36

[Joe Walker [:jwalker]]

Comment on attachment 697409 [details] [diff] [review]
addendum

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

::: browser/devtools/styleinspector/CssHtmlTree.jsm
@@ +61,5 @@
>     * Schedule a new batch on the main loop.
>     */
>    schedule: function UP_schedule()
>    {
> +    if (this.canceled) {

I think 'canceled' is US English, 'cancelled' is UK/Ca/Au English (to the extent that English can be tied down at all). I'm ok with the change but I'm not sure that the 'll' version is actually wrong.

Comment 37

[Paul Rouget [:paul]]

still some oranges.

Comment 38

[Paul Rouget [:paul]]

Attachment: final patch

Comment 39

[Paul Rouget [:paul]]

I failed my push to try (pushed some old code).

https://tbpl.mozilla.org/?tree=Try&rev=6f9243cbba48

Comment 40

[Paul Rouget [:paul]]

green.

Comment 41

[Paul Rouget [:paul]]

https://hg.mozilla.org/integration/fx-team/rev/1730cf59bcfc

Comment 42

[Panos Astithas (he/him) [:past] (please ni?)]

https://hg.mozilla.org/mozilla-central/rev/1730cf59bcfc