1659773 - Web console recreates React elements for all messages in each render

Status: RESOLVED DUPLICATE of bug 1753177

(DevTools :: Console, defect, P2)

Description

[Brad Werth [:bradwerth]]

React rendering compares the elements (objects) submitted to it to determine if DOM changes are necessary. In order to minimize the work done by React, it is most efficient for an unchanged console message to be represented by the same object on subsequent renders. This cuts down on calls to React createElement, which shows up in performance profiles as a significant factor when many messages are generated.

Comment 1

[Brad Werth [:bradwerth]]

Attachment: Bug 1659773 Part 1: [devtools] Make the web console reuse message elements in each React render.

This patch trades memory for efficiency. This makes the ConsoleOutput store
the React elements it sent for rendering on the last render call. On the next
render call, it then re-sends any existing objects it is storing, creates the
new ones, and then deletes any forgotten objects.

Comment 2

[Brad Werth [:bradwerth]]

I think this is showing improvement in most console tests. There is a regression in console.objectexpanded.close.DAMP test, but the results are within the margin of error -- analysis marks this one as medium confidence. I'll seek review.

Comment 3

[Alexandre Poirot [:ochameau]]

(In reply to Brad Werth [:bradwerth] from comment #2)

I think this is showing improvement in most console tests. There is a regression in console.objectexpanded.close.DAMP test, but the results are within the margin of error -- analysis marks this one as medium confidence. I'll seek review.

You should toggle "hide uncertain results", and then it only shows improvements.
But this is surprising that we don't see more wins on the console. It might be worth pushing your base revision to DAMP to get more confidences. When using "last x days of m-c" you get mixed results if anything regressed/improved in these last x days.

Comment 4

[Brad Werth [:bradwerth]]

(In reply to Alexandre Poirot [:ochameau] from comment #3)

You should toggle "hide uncertain results", and then it only shows improvements.

Yes, I had seen that, but I didn't want to elide a possible regression. Another low-confidence result is the improvement to complicated.webconsole.reload.DAMP. If reload avoids re-creating the ConsoleOutput object (does it?) then I would expect this test to show the improvement that it apparently does.

Comment 5

[Brad Werth [:bradwerth]]

Attachment: Bug 1659773 Part 2: Make Message and MessageContainer into PureComponents.

Once created, these objects are not modified further. This ensures that React
can skip over some equality checks.

Comment 6

[Brad Werth [:bradwerth]]

Attachment: Bug 1659773 Part 2: [devtools] Give the message store and ui store callbacks to manipulate messageElements.

Depends on D87471

Comment 7

[Brad Werth [:bradwerth]]

Attachment: Bug 1659773 Part 3: [devtools] Make the message store and ui store manipulate messageElements.

Depends on D90757

Comment 8

[Brad Werth [:bradwerth]]

These patches don't yet work, but do represent the only promising approach I've found for reducing the number of calls to React.createElement.

Comment 9

[Brad Werth [:bradwerth]]

Attachment: consoleslow1.html

The patches work as intended now. The speedup is more modest than I anticipated. Here's some times from different browser builds (reload with the console visible) to compare on this test file:

Chrome: 0.1s
Firefox Release (unpatched): 0.5s
Firefox Debug (unpatched): 80s - 100s
Firefox Debug (patched): 65s - 75s

So perhaps this is giving us a 25% reduction in runtime. I would project this would reduce the Release time to 0.4s. I'll run a new profile and see what the new opportunities are for improvement. If they are sufficiently related to this work, I'll keep adding to the patches in this bug. If not, I'll file a new bug.

Comment 10

[Brad Werth [:bradwerth]]

The new profile https://share.firefox.dev/362rRZW confirms that the patch is working as intended. ConsoleOutput.render is now 2.2% of the runtime section of interest. There aren't other obvious large blocks to pursue. Here's some relevant items:

Frame.render: 6.4%
Message.render: 7.1%
MessageContainer.render: 7.8%
ConsoleOutput.render: 2.2%

The rendering methods combined are now about 23% of the runtime -- comparable to the gains already achieved by the reduction to time spent in ConsoleOutput.render. Even if we could somehow reduce render to 0s, we'd only shorten runtime by that much. There aren't obvious bad call patterns here.

MessageContainer.shouldComponentUpdate: 4.1%

There might be gains to be made here. The shouldComponentUpdate method should always be fast in order to be useful. Otherwise, just always update!

Document.createElementNS: 2.4%

This is cost of modifying the DOM.

PresShell::FlushPendingNotifications: 5.5%

This is our layout cost. Seems reasonable, though we might be able to reduce it by calculating the height of each console item (after initial layout). This is evidence that virtualized scrolling is not relevant to this slow case.

ActivityStreamProvider.getTopFrecentSites: 2.8%

I have no idea what this is doing here. Even if it's just a coincidence that this scheduled operation overlapped with my profile, it's still true that this operation is much slower than it should be.

messages reducer: 4.7%

This is split between time in addMessages and cloneState. There may be opportunities here.

Okay, that's not everything, but it's all the notable chunks that we might be able to affect. I'll see if I can add something in this patch stack to reduce time in MessageContainer.shouldComponentUpdate and in the messages reducer. I don't know what to do about ActivityStreamProvider.getTopFrecentSites.

Comment 11

[Brad Werth [:bradwerth]]

Attachment: Bug 1659773 Part 4: [devtools] Make MessageContainer into a PureComponent.

The call to MessageContainer.shouldComponentUpdate function is expensive due
to comparison of native properties. Since MessageContainers are only ever
regenerated when they change, they never need to update and the
shouldComponentUpdate function is totally unnecessary. In React, that is
handled by defining MessageContainer as a PureComponent, which has a fast
default shouldComponentUpdate call.

Depends on D90758

Comment 12

[Brad Werth [:bradwerth]]

That's as far as I can get, performance-wise. I'm going to add another part to address test failures, then seek review.

Comment 13

[Brad Werth [:bradwerth]]

This is starting to look good. New try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f2b8f1a6396474da34076c2ca470f0a609bd33fc

Comment 14

[Brad Werth [:bradwerth]]

Attachment: Bug 1659773 Part 5: [devtools] Modify DevToolsServerConnection to prevent exceptions from send-after-close.

Some tests fail intermittently due to messages being sent after the transport
has been closed. Those messages are safely ignorable.

Depends on D91230

Comment 15

[Brad Werth [:bradwerth]]

Finally ready: https://treeherder.mozilla.org/#/jobs?repo=try&revision=5a4a5d78cb2e9300719b2e4e67347ef30420d900. Seeking review.

Comment 16

[Brad Werth [:bradwerth]]

DAMP try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=9aa8d4c94d72ad40e77d063d764b8833bfa0bb55

Comment 17

[Brad Werth [:bradwerth]]

Attachment: Bug 1659773 Part 6: [devtools] Add a test to ensure bulk logging completes in a reasonable time.

Depends on D91976

Comment 18

[Brad Werth [:bradwerth]]

I'm going to add a blocker bug to this bug that adds a console logging DAMP test, so we have comparable performance before we try to land this.

Comment 19

[Brad Werth [:bradwerth]]

(In reply to Brad Werth [:bradwerth] from comment #18)

I'm going to add a blocker bug to this bug that adds a console logging DAMP test, so we have comparable performance before we try to land this.

It looks like Bug 1593728 will serve as that blocker.

Comment 20

[Brad Werth [:bradwerth]]

New try run that hopefully has comparable DAMP measurements: https://treeherder.mozilla.org/#/jobs?repo=try&revision=08362db24890c3021f30b85bb79e351f294b0d03

Comment 21

[Brad Werth [:bradwerth]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=204f977435f6ecb3f997502c4bc847b0be04976a

Comment 22

[Brad Werth [:bradwerth]]

Attachment: WIP toy version of our React-based console design

To try out alternative approaches, I've built a toy version of our React-based console. The goal is to find a way to make the addition of one message fast even after many thousands of messages are already being tracked.

Comment 23

[Brad Werth [:bradwerth]]

Comment on attachment 9184943 [details]
WIP toy version of our React-based console design

http://www.bradleyjwerth.com/console-toy/

Comment 24

[Brad Werth [:bradwerth]]

I'm not working on this anymore.

Comment 25

[Alexandre Poirot [:ochameau]]

This will probably be fixed by bug 1753177 too.