1764501 - Browser console still takes 20 to 30s to respond on long-lived sessions

Status: RESOLVED FIXED

(DevTools :: Console, enhancement)

Description

[Alexandre Poirot [:ochameau]]

The virtualization speeds up the browser console opening, but there is still something making it freeze and very slow in the reducers.

STR:

• open firefox with many tabs (70 in the profile)
• browse the web for a day
• open the browser console
• try to evaluate document.body (or anything it doesn't matter what) ASAP

AR: the console will show message quickly, but it will take many tens of second to see the evaluation result and eventually freeze for 10 to 20seconds.

ER: the console may be slow while fetching all content process messages, but evaluation should respond quickly and the console shouldn't completely freeze.

Here is a profile:
https://share.firefox.dev/3E53fit

It looks like this codepath is more usual than expect in the browser console:
https://searchfox.org/mozilla-central/rev/d34f9713ae128a3138c2b70d8041a535f1049d19/devtools/client/webconsole/reducers/messages.js#261-276
We spend 13s in addMessages function, and most of the line is spent on these 3 lines

264:    const entries = Array.from(state.mutableMessagesById.entries()); // 3.5s
265:    const newMessageIndex = entries.findIndex(...); // 1s
...
274:    state.mutableMessagesById = new Map(entries); // 7.3s

It would be nice to avoid cloning the map, even in this code branch and/or make this code branch happen only once in a while.

Comment 1

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

I was testing this today, some comments:

1. My setup:
   1 browser window, 95 opened tabs
   youtube.com, bild.de, cnn.com

2. Memory consumption
   The Browser with 95 tabs, created about 62 processes and took 11-12 MB
   The Browser Toolbox (including one browser window used to run the profiler) created about 9 processes and took 2-3 MB

3. There is a lot of errors displayed in the Console panel (20K generated in couple of minutes) and constant incoming stream of HTTP requests (all from content I think, thousands), I switched ON the console filters and paused HTTP interception (in the Network panel) to avoid some perf penalties, it seemed to help.

4. I was usually starting with the Console panel enabled by default and the Browser Toolbox is slowing down as I was activating more panels. (Network, Inspector, Debugger). It seems that Debugger has significant impact on performance.

Example STRs:

• Open Browser with 95 tabs
• Open Browser Toolbox, with the Console panel being the default one
• Execut 1+1 in the Command line, should be quick
• Select the Debugger panel, wait till it's initialized (can take 10-20 sec)
• Go back to the Console panel, execute 1+1, takes significantly more time (I am trying to profile this, but facing issues with responsiveness)

5. Another way to test this is activating other panels step by step and measure the time needed for expression evaluation in the Command line. The panel I've been mostly trying are: Network, Debugger and Inspector. As soon as they are all activated, the Browser Toolbox is very slow and mostly frozen.

Comment 3

[Nicolas Chevobbe [:nchevobbe]]

Attachment: Bug 1764501 - [devtools] Speedup adding messages out of order. r=ochameau.

In the console we might receive messages that need to be inserted at a specific
position in the output to respect the chronological order.
This is very visible when evaluating an expression in the console while we are
fetching cached messages, or when the expression is logging lots of messages, since
the evaluation result doesn't go through the ResourceCommand itself.
Since we were relying on the order of insertion in mutableMessagesById for the
order of messages in the output, we had no choice but clone the Map to insert
the new message at the specific position.
With lots of messages, this can be utterly slow, and is something people are experiencing.

To fix this, we're adding a new state property, mutableMessagesOrder, which holds
message ids in the chronological order. It's then used to compute visibleMessages.
As we don't have to clone the Map anymore, it makes reordering as fast as looking
for an index in the array and splicing it (which is fast).

We also take this opportunity to switch away from our findIndex usage; most often
than not, the messages will be reinserted at the end of the array, so we can loop
through it backward to find the index faster.

We still keep mutableMessagesById as a Map so lookup are fast, and we don't have
to deal with impacts we'd have if we'd switch to an object.

The existing node test helper to get a message at a specific index are migrated
to make use of mutableMessagesOrder, and a few test cases and assertions are
added to check that the new property is handled correctly.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c678f7219982
[devtools] Speedup adding messages out of order. r=ochameau.

Comment 5

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/c678f7219982