Meta bug: Console performance investigation

[gregtatum]

This is a meta bug to track some of my performance investigations.

[gregtatum]

Initially loading DevTools with heavy console use:

Imagine 200 mixed messages are in the console.log queue. On average they take 15ms each to mount and do an initial render. Loading up DevTools for the first time naively requires each one to have an initial render. This takes 3000ms to display the window in a usable state.

Potential fix:

If each message is at most 20px tall, and the window is 500px tall, then there will be at most 25 messages in view. These last 25 will be of mixed height, but can all be safely rendered initially. The messages are will then only have 26 components on the initial load, 1 spacer element, and then 25 messages. The total render time would be 375ms.

This could theoretically reduce a 3000ms amount of work down to 375ms.

[gregtatum]

Analysis for slow console.log() streaming in perf.html

In perf.html development mode, console ends up being a bottleneck on performance. In development mode, perf.html logs messages of timing information for individual functions, and logs the entire redux state on every action dispatch. In console, the newly introduced message batching the behavior has helped contain the impact of these frequent updates quite a bit, but a large amount of time is still being spent in React. Here is an example profile, where the content thread is running perf.html, and doing a non-trivial amount of work in rapid succession, with lots of console.log() messages. The content thread is a bit slow, but is healthy in being able to redraw the screen in a non-blocking manner.

https://perfht.ml/2xblTpm

The main thread contains DevTools' client code, and each batch of updates from content, is followed by a long single update of the console's React components. These end up being long pauses of 170-280ms dealing with the batched messages coming in. Diving into the call tree, it quickly shows 80% of the time is being spent in _performComponentUpdate. This is a React internal, and going deeper into the call stack does not reveal much more information about where time is being spent.

Attempting to instrument

As a next step I attempted instrumenting some of the draw calls with UserTimings.

measure.id = 0
function measure (name) {
  const id = measure.id++
  const start = name + "start" + id
  const end = name + "end" + id
  performance.mark(start);
  return () => {
    performance.mark(end);
    performance.measure(name, start, end)
  }
}

Here is a zoomed in view. It looks like it's spending a lot of time going through each new message and rendering it.

https://perfht.ml/2xalT9j

Enabling perf profiling.

Next I applied Mike Ratcliffe's patch to add the new React, and did a search and replace to manually enable the React profiler.

https://perfht.ml/2xagwHb

It turns out that most of the time is being spent in Object Inspector.

Logging 1000 numbers

I ran the following from console and recorded it.

for(var i = 0; i < 1000; i++) { console.log(i) }

https://perfht.ml/2xbHD4x

It appears that it takes about 2-3ms to mount a single message, even if it's a trivial number message. This becomes quite intense when quickly logging many messages. This evidence strongly suggests

Top leaf functions in a profile:

22%: markBegin/markEnd (this is the React profiler)
14%: mountComponent
10%: ReactElement.createElement
 4%: updateDOMProperties
 3%: setValueForProperty
 2%: <Message> render()

Finally here is performing the same for loop of 1000 elements, but modifying the code to only show the DefaultRenderer, which is rendering a message as a single div.

https://perfht.ml/2xcfs0E