1308216 - Improve performance of bulk logging

Status: RESOLVED DUPLICATE of bug 1753177

(DevTools :: Console, task, P3)

Description

[Lin Clark [:linclark]]

When you are creating lots of new messages at nearly the same time, the new console's performance isn't so great. There's a chance we could improve this.

Comment 1

[Lin Clark [:linclark]]

Attachment: Nightly_and_webconsole_js_-_devtools.png

My working theory for (one reason) why this is slow is that we are creating a new state object for each message. A little bit of profiling (see attachment) seems to lend some support to this.

We can potentially make this faster by doing something in the batching. Before we dispatch, we could iterate through the actions and combine any that are simple MESSAGE_ADD actions into a single MESSAGES_ADDED action. In the reducer, this could add the messages as a group using withMutations. 

This has the downside of obscuring what's going on in the action flow a bit. I think it would be worth it if the performance gains are substantial, though.

Comment 2

[Lin Clark [:linclark]]

Attachment: Bug1308216.patch

Ok, I gave the idea of consolidating message add actions a shot.

Here are local DAMP results when bulklog is increased to output 1000 messages

old console: 4503.955000000002
new console: 7345.492500000008
new console with patch: 6708.542500000025

The downside is that it makes bugs easier to introduce.

I'm going to put this on hold. For Bug 1308217 I'm planning to do a quick POC where we use virtualization. I wonder how that would impact this case as well.

Comment 3

[Lin Clark [:linclark]]

Tested with React Virtualized... it brings the time down to 2122.9725000000035.

If I can get arbitrary row heights to work, then that looks like the best solution to me.

Comment 4

[Lin Clark [:linclark]]

Introducing the CellMeasurer component actually seems to make things considerably slower :-/ I was looking at 10000 ms for the same testing scenario.

Comment 5

[Lin Clark [:linclark]]

React virtualized doesn't have extension points where we would need them in order to change the algorithm. We could add our own RV inspired virtualization, but I figured I'd check out fixed-data-table too. It's not as actively maintained, but it might be worth that tradeoff.

Testing with fixed heights, it's quite fast - 1683.2275000000009

Comment 6

[Lin Clark [:linclark]]

Took a little hacking, but I got it working with arbitrary heights reasonably well.

2251.0800000000017

The scroll isn't 100%, though. That's an existing issue with fixed data table and arbitrary heights. Since we only have one use case to support, I think we should be able to hack it to work though.

Comment 7

[Lin Clark [:linclark]]

fixed-data-table ended up having too many bugs to be workable.

I went back to React Virtualized and have something that kind of works. It gives us bulk logging times that are about the same as old console. When it's under heavy load it breaks, though.

I did discover that part of our problem is the performance of Reps. When testing, I noticed that there was one test case that was abysmal. 

> for (let i=0; i<100; i++) {console.log(...Array(100).fill(i))}

When I changed formatReps in console-api-call.js to just return parameters.join(" "), it could handle this case as well as old console or Chrome. So I tried running DAMP with that change... 4318.227500000008 (a little faster than old console).

It might be that it makes sense to special case the console and not use reps for simple values (strings, numbers, etc). I know that kind of goes against the original vision for Reps, but we can't take the performance hit.

Comment 8

[Lin Clark [:linclark]]

Combining React Virtualized + removing Reps brings us down to 2024.239999999998

Comment 9

[Lin Clark [:linclark]]

I fixed the issue with it breaking under heavy loads. I still have to add support for clearing out the cached heights when you clear the console or filter, but I think this approach will work.

Here's a try run with a (slightly outdated) version of the new code. The baseline I'm using here is the new console without RV.

https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=de638693d3cb&newProject=try&newRevision=38f731b0cec6&framework=1&showOnlyImportant=0

Comment 10

[Lin Clark [:linclark]]

I believe the code is fully working now. Here are some numbers. Some jobs are still running, so not high certainty yet, but it matches what I've been seeing in my local testing

new console status quo VS. new console virtualized:
47% improvement [1]

old console vs new console virtualized:
35% improvement [2]

[1] https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=de638693d3cb&newProject=try&newRevision=50ff223a55cf&framework=1&showOnlyImportant=0
[2] https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=2b5a90c274dc&newProject=try&newRevision=50ff223a55cf&framework=1&showOnlyImportant=0

Comment 11

[Lin Clark [:linclark]]

Attachment: virtualized.patch

Super hacky patch that people can test. Will be cleaning up the code.

Comment 12

[Lin Clark [:linclark]]

Attachment: virtualized.patch

Extended from PureComponent, which should improve scrolling

Comment 13

[Lin Clark [:linclark]]

One thing to note with the latest patch is that it will potentially make things seem slower for us in testing (even though I think that last patch will still make scrolling smoother. regardless). React 15's dev mode is slower than the previous version, but React 15 is faster in production. See https://medium.com/modus-create-front-end-development/component-rendering-performance-in-react-df859b474adc#.dwsjxrnev

Comment 14

[Lin Clark [:linclark]]

Anyone testing this should probably comment out these lines in browser-loader.js

  // if (AppConstants.DEBUG || AppConstants.DEBUG_JS_MODULES) {
  //   dynamicPaths["devtools/client/shared/vendor/react"] =
  //     "resource://devtools/client/shared/vendor/react-dev";
  // }

Comment 15

[Lin Clark [:linclark]]

Attachment: virtualized.patch

Nicolas, when you get a chance could you test this out? If you log a lot, it might still be janky on the first scroll, but should be better than the previous patch after that. Let me know, though.

Comment 16

[Nicolas Chevobbe [:nchevobbe]]

Looks better than when I tested it with a previous patch 

Comment 17

[Lin Clark [:linclark]]

Attachment: virtualized.patch

Comment 18

[Lin Clark [:linclark]]

Attachment: virtualized.patch

Comment 19

[Brian Grinstead [:bgrins]]

Here's a try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=7660b863d9ba83c57319cd4a8d0e3bddaaedd0a1

Comment 20

[Lin Clark [:linclark]]

Attachment: Bug1308217.patch

This patch does not include React Virtualized, which will land in the blocking bug.

Comment 21

[Brian Grinstead [:bgrins]]

Comment on attachment 8807372 [details] [diff] [review]
Bug1308217.patch

Review of attachment 8807372 [details] [diff] [review]:
-----------------------------------------------------------------

Nicolas, would appreciate any code feedback / review you could give to have another set of eyes on it if you have time.  If not, no problem, I'll grab it later on.

Comment 22

[Lin Clark [:linclark]]

Attachment: Bug1308217.patch

This should fix the tests (or at least most of them). It also includes a little hack to React Virtualized which fixes scrolling when the "Show scroll bars: Always" setting is turned on in OSX. Will have to find a better way to fix that.

Comment 23

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8807401 [details] [diff] [review]
Bug1308217.patch

Review of attachment 8807401 [details] [diff] [review]:
-----------------------------------------------------------------

Overall the code looks more complex and not as elegant as it used to be, but I guess it's unavoidable if we want better perf.
I had not tested the patch manually, will do in the evening.

f- because of the isSubset function, but I can be wrong about it.

::: devtools/client/performance/test/browser_perf-console-record-02.js
@@ +15,5 @@
>  const { times } = require("devtools/client/performance/test/helpers/event-utils");
>  const { getSelectedRecording } = require("devtools/client/performance/test/helpers/recording-utils");
>  
>  add_task(function* () {
> +  yield SpecialPowers.pushPrefEnv({

I guess this is the fix for the tests you were talking about ? 
It would be nice if all the test fix are in their own patch/commit

::: devtools/client/themes/webconsole.css
@@ +685,5 @@
>  }
>  
>  .webconsole-output-wrapper {
>    display: flex;
> +  overflow: hidden;

I can't test it now, but doesn't this affect horizontal scrolling ?

::: devtools/client/webconsole/new-console-output/actions/filters.js
@@ +21,3 @@
>  function filterTextSet(text) {
> +  return (dispatch) => {
> +    cellSizeCache.clearAllRowHeights();

Maybe this deserve a comment to explain why we clear the cache ?

::: devtools/client/webconsole/new-console-output/actions/messages.js
@@ +39,2 @@
>      return batchActions([
> +      // @TODO make batchActions support thunks so we can use messagesClear() instead.

could you file a bug for this if there isn't one already ?

::: devtools/client/webconsole/new-console-output/components/console-output.js
@@ +69,4 @@
>    },
>  
>    componentDidMount() {
> +    // For mochitests.

could you elaborate on this and tell why it is needed for mochitest ?

@@ +158,5 @@
> +    if (this._scrollState.resizedWidth !== width) {
> +      this._scrollState.resizedWidth = width;
> +      cellSizeCache.clearAllRowHeights();
> +    }
> +    this.forceUpdate();

do we need to force update if resizedWidth is equal to width ?

@@ +168,5 @@
> +    this._scrollState.rowStopIndex = rowStopIndex;
> +  },
> +
> +  _onScroll({ clientHeight, scrollHeight, scrollTop}) {
> +    this._scrollState.clientHeight = clientHeight;

nit: maybe we could use Object.assign to make this cleaner

`Object.assign(this._scrollState, {clientHeight, scrollTop, scrollHeight}` 

what do you think of this ?

@@ +284,5 @@
> +    || prevList.size == 0
> +    || nextList.size == 0
> +    || nextList.size < prevList.size
> +    || prevList.get(0).id !== nextList.get(0).id
> +    || prevList.get(prevList.size - 1).id !== nextList.get(prevList.size - 1).id

I'm wondering if we could hit some edge case here.
Let's say we have the following list of message
- id:1 , messageText: ab
- id:2 , messageText: a
- id:3 , messageText: b
- id:4 , messageText: ab

Now let's say we filter with "a", we get 1,2,4
If we replace "a" with "b", we have 1,3,4 

We can't say we have a subset, since 3 is now visible and wasn't before
But with this function, we would return true.
  previous = 1,3,4
  next: 1,3,4
  previous.size != 0
  next.size != 0
  previous.size == next.size
  previous[0] == next[0]
  previous[2] == next[2]

::: devtools/client/webconsole/new-console-output/components/message-container.js
@@ +57,5 @@
> +    this._cacheMessageHeight();
> +  },
> +
> +  _cacheMessageHeight() {
> +    const innerNode = findDOMNode(this).firstChild.firstChild;

nit: I find this prone to break if the structure change, could we target a className or something else?

::: devtools/client/webconsole/new-console-output/selectors/messages.js
@@ +18,5 @@
>  
>    let groups = getAllGroupsById(state);
>    let messagesUI = getAllMessagesUiById(state);
>  
> +  return messages.filter(message => {

okay, so since we use virtualization, we don't need to prune because we only show the messages that fit in the viewport, that's nice.

Comment 24

[Lin Clark [:linclark]]

Attachment: Bug1308217.patch

Thanks for the feedback. I haven't addressed much of it in this patch, but did try to reduce the complexity by breaking out a ScrollPositionManager and KeyboardPager (alternate names for those are welcome).

Will post another patch addressing the other feedback later today.

Comment 25

[Brian Grinstead [:bgrins]]

New try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1199c1f06181856ff6d93167c0bee348228056eb

Comment 26

[Lin Clark [:linclark]]

Attachment: Bug1308217.patch

Most of the feedback has been addressed here. There is an issue with the scrollbars that we need to work out. You can see it where I use the SCROLLBAR_SIZE constant.

Basically, right now I have to monkey patch RV for it to get the correct scrollTop when there is a horizontal scrollbar. I also have to reduce the width of the inner scroller, but that makes nodes with backgrounds (errors, warnings) stop 15px short of the right hand side when there isn't a scrollbar.

I'm not sure that this is something that can be easily handled with RV as it is. We may need to get fixes into RV itself (or fork it). Here are a couple of existing issues/related commits I found:

- https://github.com/bvaughn/react-virtualized/issues/401
- https://github.com/bvaughn/react-virtualized/issues/222
- https://github.com/bvaughn/react-virtualized/commit/ccd48498bfc43fc1d5a49d4f398320c03ab98fe9

Comment 27

[Lin Clark [:linclark]]

Attachment: Bug1308217.patch

This fixes one of the issues.

Comment 28

[Lin Clark [:linclark]]

Attachment: Bug1308217.patch

Discussion with bgrins helped figure out that KeyboardPager is actually not necessary. This patch removes that component.

Comment 29

[Brian Grinstead [:bgrins]]

Attachment: tweaks.patch

A few things to be applied after Lin's patch:

1) The main thing is that it gets rid of cache invalidation needed for filtering by always querying by ID instead of index.  I believe this means we can simplify the cellsizecache implementation to not worry about index at all.
2) A CSS fix so that this doesn't cause lack of overflow on old console
3) Match default cell size to at least what I see in local dev to in theory prevent a re-render (if/when shouldComponentUpdate is working on the message container)

Comment 30

[Brian Grinstead [:bgrins]]

After Bug 1291815, the current results of DAMP with the new console on seem much more sensible: https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=98cfa65715b3624a1f5a5ba82a05105f5cf8c030&newProject=try&newRevision=4b389044e1da5d5055aa3fd29be02985f29c05b4&framework=1&filter=damp&showOnlyImportant=0.

The subtests are now closer to what I'd expect - open is slower, close is faster, bulklog is slower, streamlog is faster: https://treeherder.mozilla.org/perf.html#/comparesubtest?framework=1&newProject=try&newRevision=4b389044e1da5d5055aa3fd29be02985f29c05b4&newSignature=63c652b34bd8fcf3623be048bdd3104906f70f02&originalProject=try&originalRevision=98cfa65715b3624a1f5a5ba82a05105f5cf8c030&originalSignature=63c652b34bd8fcf3623be048bdd3104906f70f02

This should give us a better baseline to compare the patches here with

Comment 31

[Lin Clark [:linclark]]

Talked this over with :bgrins. There are a couple of things that we would like to happen on this.

1. Brian made a good catch and found some caching logic that was more complicated than in needs to be (comment 29). He wants to look into simplifying that more.
2. The monkey patching (which is there for scroll offset management) is less than ideal. However, we don't currently have the kind of rapid feedback loop for development that would make it easy to debug. :jlast has put some work into moving the console output to a tab. If that happens, that could make this easier to debug.

Besides the DAMP issue, I think those are the only two things holding this back.

To move forward, we have two options:
1. Hold this until tab development workflow is done to see if the scroll offset issue is easier to debug then.
2. Commit this and then remove the monkey patch later.

Unfortunately, I won't have the focus available to push this one through, so unassigning. However, always available to answer questions, clarify things, etc.

Comment 32

[Brian Grinstead [:bgrins]]

Attachment: test-render-perf.patch

Updates to fix test_render_perf.html, which will hopefully make local perf testing easier.  Might want to pull in some different stubs to the test if we want more varied data but it should hopefully give a good sense as-is.

One thing to also investigate is if this test is faster than it is when running in the webconsole frame, and if so if that's because of CSS, XUL, or something else.

Comment 33

[Julian Descottes [:jdescottes]]

Attachment: react-virtualized.patch

Comment 34

[Julian Descottes [:jdescottes]]

Did some quick measuring of the DOM generated by Reps compared to the one generated by the old console.

For a test message:
> console.log(...(new Array(100)).fill({a: [1,2,3]}))

The old console generates a markup of 600 nodes.
The new console (and therefore reps) generate a markup of 1412 nodes. That's 2.3 times more than the old console.  

Given that the new console is roughly 50% slower than the new one, I will try to simplify rep's markup to achieve the same DOM tree size and see if this improves the situation.

Comment 35

[Julian Descottes [:jdescottes]]

For reference here is the markup generated for "Object { a: Array[3] }" (coming from the test message console.log(...(new Array(100)).fill({a: [1,2,3]}))

Old console (6 dom nodes):
> <span>
>   <a>Object</a>
>    { 
>   <span>a</span>
>   : 
>   <span>
>     <a>Array</a>
>     [
>     <span>3</span>
>     ]
>   </span> }
> </span>

New console (13 dom nodes):
> <span>
>   <a>Object</a>
>   <a> { </a>
>   <span>
>     <span>a</span>
>     <span>: </span>
>     <span>
>       <a>[</a>
>       <span>3</span>
>       <a>]</a>
>       <span></span>
>     </span>
>     <span></span>
>   </span>
>   <a> }</a>
> </span>

Comment 36

[gwarser]

https://perfht.ml/2WRQ3YG

In 71.0b7 with "Requests" logging enabled when loading https://addons.mozilla.org/en-US/firefox/user/4757633/ where many __cspreport__ requests are logged switching tabs can easily take ~15 seconds.

A script on this page may be busy...
Script: resource://devtools/client/shared/vendor/react.js:1595

A script on this page may be busy...
Script: resource://devtools/client/web…onents/Output/ConsoleOutput.js:188

For some reason most of this is not recorded in profiler https://perfht.ml/2NopsiO

Comment 37

[:Harald Kirschner :digitarald]

Un-meta since this has patches attached but isn't worked atm. The problem is important though.

Comment 38

[Nicolas Chevobbe [:nchevobbe]]

Closing as dupe of Bug 1753177 , as it improved performances in a way we wanted to.