1523937 - The console is very slow on debug builds

Status: NEW

(DevTools :: Console, defect, P2)

Description

[Alexandre Poirot [:ochameau]]

Opening the console takes 4 seconds.
Inspection windows takes 6 seconds.
Writing in the console input is quite painful as there is a high latency between keystrokes and updates in the input field.

Here is a profile with bug 1517210 applied, which already speed things up by getting rid of cross compartment wrappers.
http://bit.ly/2RqCwTr
The STR is the following:

• open the webconsole (for the first time since firefox started)
• execute: console.log("foo") <= this is pretty fast except the sluggish typing
• execute: inspect(window) <= Window appears first, but seeing all its properties is very slow and freeze

In the content process, there is clearly some optimizations to be done around the thread and source actors. We spend a lot of time creating SourceActor's form/url. We end up calling this method/getter multiple times without caching it.

In the parent process, it is harder for me to analyse.
The profile is 13.7s long, and we spend:

• 7s in devtools
• 3s in react
• 2.1s in codemirror
• 1.4s in reps
• 0.5s in protocol.js
• 0.4s in autocomplete

I see three things to improve:

• load time of the console
• faster typing
• faster object inspection, without/with less freezes

Comment 1

[Alexandre Poirot [:ochameau]]

In case that can help, here is a profile of STR focusing on typing performance.:

• type: console.log("foo") in the console input, without pressing enter

http://bit.ly/2RrRfxf
Again, I see a lot of codemirror frames and don't really know what is really slow here.

Comment 2

[Nicolas Chevobbe [:nchevobbe]]

Typing in CodeMirror fires a Redux action to fetch the autocomplete popup items (and if there are some, we display the grey completion text).

For the specific case of window, https://github.com/devtools-html/debugger.html/issues/7383 should help as we show nodes that could be hidden (but that's not helping the overall performance of the object inspector).

Comment 3

[Florian Quèze [:florian]]

Here is a profile of typing quickly in the console on the 2018 quantum reference hardware: https://perfht.ml/2Grj8UG This is on today's nightly.

Two things in this profile look worth optimizing:

• for each 'input' event, we cause several style/layout flushes (ie. sync reflows).
• We update more than once per refreshDriverTick.

I think coaleascing the events into a single update per refresh driver tick and avoiding sync reflows by only changing the DOM from a requestAnimationCallback callback would dramatically improve perceived performance here.

Comment 4

[Alexandre Poirot [:ochameau]]

I thought that the removal of cross compartment would speed this up a lot, but not really.

I looked a bit into this and the autocomplete RDP request is made for every single key stroke.
So, when you quickly type "window", we do 6 requests, once per character.

Unfortunately, because the codepath is cut in pieces between JSTerm, actions and reducers, it is quite challenging to throttle correctly.

Here is what happens.

It starts from JSTerm, receiving events for each key stroke:
https://searchfox.org/mozilla-central/rev/7c20ad925005fbad7b8e08813115f1ec7fa1c248/devtools/client/webconsole/components/JSTerm.js#803-810

  _inputEventHandler() {
    const value = this._getValue();
    if (this.lastInputValue !== value) {
      this.resizeInput();
      this.props.autocompleteUpdate();
      this.lastInputValue = value;
    }
  }

We do call autocompleteUpdate action, that, for each character. This action will dispatch another action:
https://searchfox.org/mozilla-central/rev/7c20ad925005fbad7b8e08813115f1ec7fa1c248/devtools/client/webconsole/actions/autocomplete.js#73-79

    return dispatch(autocompleteDataFetch({
      input,
      frameActorId,
      client: services.getWebConsoleClient(),
      authorizedEvaluations,
      force,
    }));

A autocompleteDataFetch action, which does the RDP autocomplete request:
https://searchfox.org/mozilla-central/rev/7c20ad925005fbad7b8e08813115f1ec7fa1c248/devtools/client/webconsole/actions/autocomplete.js#132-140

    const id = generateRequestId();
    dispatch({type: AUTOCOMPLETE_PENDING_REQUEST, id});
    client.autocomplete(
      input,
      undefined,
      frameActorId,
      selectedNodeActor,
      authorizedEvaluations
    ).then(data => {

At first, you may think that throttling the input event listener from JSTerm would be enough, by doing:

  const { throttle } = require("devtools/shared/throttle");
  this._inputEventHandler = throttle(this._inputEventHandler, 100, this);

But that doesn't work because the input events are actually delayed by the autocompletion overhead.
The input events aren't spammed. We do receive one, then spawn a first autocompletion. This autocompletion will be heavy enough processing to delay the next key stroke.

Otherwise, we may cancel autocomplete fetch if there is already a pending request, in autocompleteDataFetch:

  const state = getState().autocomplete;
  const { pendingRequestId } = state;
  if (pendingRequestId) return;

But that breaks the autocompletion by displaying outdated suggestions.

So I don't know how to fix that, but the goal would be to:

• have only one pending autocomplete RDP request. i.e. never have more than one being done at a time. Right now we can have one for each character and have them all resolve at the end of the word typing.
• reduce the number of autocomplete RDP request to the bare minimum. The overall idea would be to do only one when we think the user ends typing and is looking for a suggestion.

I imagine that by doing that, we would reduce the number of RDP request response and the number of popup/codemirror updates?

Comment 5

[Nicolas Chevobbe [:nchevobbe]]

At first, you may think that throttling the input event listener from JSTerm would be enough

throttle might not work well because for the first key stroke we do call the function (which is the most likely to send a big list).
I'm trying something with debounce (so, wait for Xms until calling the function, unless there's another keystroke, which reset the timer), and it looks okay. I'm still not sure how that would feel, since we need to set a timeout big enough so 2 consequent keystrokes only causes 1 server call, without making the autocomplete feels to slow to respond. I'm trying with 150ms which seems okay-ish for now.
I've pushed to TRY to check there's no side effect on tests.