Skip to content

Instantly share code, notes, and snippets.

@gregtatum
Created October 2, 2017 21:51
Show Gist options
  • Save gregtatum/4d5dbf3df558de2dd26e39dbe1413b73 to your computer and use it in GitHub Desktop.
Save gregtatum/4d5dbf3df558de2dd26e39dbe1413b73 to your computer and use it in GitHub Desktop.

Perf bottleneck with using console in perf.html development

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment