Improve performance of bulk logging

NEW
Unassigned

Status

DevTools
Console
--
enhancement
2 years ago
a month ago

People

(Reporter: linclark, Unassigned)

Tracking

(Depends on: 1 bug, Blocks: 5 bugs, {meta})

unspecified
Dependency tree / graph
Bug Flags:
qe-verify -

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(5 attachments, 11 obsolete attachments)

9.72 KB, patch
Details | Diff | Splinter Review
90.51 KB, patch
Details | Diff | Splinter Review
9.42 KB, patch
Details | Diff | Splinter Review
3.00 KB, patch
Details | Diff | Splinter Review
283.72 KB, patch
Details | Diff | Splinter Review
(Reporter)

Description

2 years ago
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.
(Reporter)

Updated

2 years ago
Assignee: nobody → lclark
Severity: normal → enhancement
Priority: -- → P1
Whiteboard: new-console
(Reporter)

Updated

2 years ago
Blocks: 1308219
(Reporter)

Comment 1

2 years ago
Created attachment 8798907 [details]
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.
(Reporter)

Comment 2

2 years ago
Created attachment 8799052 [details] [diff] [review]
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.
(Reporter)

Comment 3

2 years ago
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.
(Reporter)

Comment 4

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

Comment 5

2 years ago
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
(Reporter)

Comment 6

2 years ago
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.
(Reporter)

Comment 7

2 years ago
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.
(Reporter)

Comment 8

2 years ago
Combining React Virtualized + removing Reps brings us down to 2024.239999999998
(Reporter)

Comment 9

2 years ago
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
(Reporter)

Comment 10

2 years ago
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
(Reporter)

Comment 11

2 years ago
Created attachment 8803368 [details] [diff] [review]
virtualized.patch

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

Updated

2 years ago
See Also: → bug 1308217
(Reporter)

Updated

2 years ago
Blocks: 1308842
(Reporter)

Updated

2 years ago
See Also: → bug 1307932
(Reporter)

Comment 12

2 years ago
Created attachment 8803641 [details] [diff] [review]
virtualized.patch

Extended from PureComponent, which should improve scrolling
Attachment #8803368 - Attachment is obsolete: true
(Reporter)

Comment 13

2 years ago
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
(Reporter)

Updated

2 years ago
Depends on: 1312481
(Reporter)

Comment 14

2 years ago
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";
  // }
(Reporter)

Comment 15

2 years ago
Created attachment 8806077 [details] [diff] [review]
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.
Attachment #8798907 - Attachment is obsolete: true
Attachment #8803641 - Attachment is obsolete: true
Attachment #8806077 - Flags: feedback?(chevobbe.nicolas)
Looks better than when I tested it with a previous patch 
Attachment #8806077 - Flags: feedback?(chevobbe.nicolas) → feedback+
(Reporter)

Comment 17

2 years ago
Created attachment 8806771 [details] [diff] [review]
virtualized.patch
Attachment #8806077 - Attachment is obsolete: true
(Reporter)

Comment 18

2 years ago
Created attachment 8807259 [details] [diff] [review]
virtualized.patch
Attachment #8806771 - Attachment is obsolete: true
Status: NEW → ASSIGNED
(Reporter)

Comment 20

2 years ago
Created attachment 8807372 [details] [diff] [review]
Bug1308217.patch

This patch does not include React Virtualized, which will land in the blocking bug.
Attachment #8807259 - Attachment is obsolete: true
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.
Attachment #8807372 - Flags: feedback?(chevobbe.nicolas)
(Reporter)

Comment 22

2 years ago
Created attachment 8807401 [details] [diff] [review]
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.
Attachment #8807372 - Attachment is obsolete: true
Attachment #8807372 - Flags: feedback?(chevobbe.nicolas)
Attachment #8807401 - Flags: feedback?(chevobbe.nicolas)
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.
Attachment #8807401 - Flags: feedback?(chevobbe.nicolas) → feedback-
(Reporter)

Comment 24

2 years ago
Created attachment 8807623 [details] [diff] [review]
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.
Attachment #8807401 - Attachment is obsolete: true
Attachment #8799052 - Attachment is obsolete: true
Attachment #8799052 - Attachment is obsolete: false
Blocks: 1308217
(Reporter)

Comment 26

2 years ago
Created attachment 8808267 [details] [diff] [review]
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
Attachment #8807623 - Attachment is obsolete: true
(Reporter)

Comment 27

2 years ago
Created attachment 8808271 [details] [diff] [review]
Bug1308217.patch

This fixes one of the issues.
Attachment #8808267 - Attachment is obsolete: true
(Reporter)

Comment 28

2 years ago
Created attachment 8808420 [details] [diff] [review]
Bug1308217.patch

Discussion with bgrins helped figure out that KeyboardPager is actually not necessary. This patch removes that component.
Attachment #8808271 - Attachment is obsolete: true
Created attachment 8808437 [details] [diff] [review]
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)
(Reporter)

Comment 31

2 years ago
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.
Assignee: lclark → nobody
Status: ASSIGNED → NEW

Updated

2 years ago
Flags: qe-verify-
Priority: P1 → P2
Whiteboard: new-console → [new-console]
Blocks: 1325997
Created attachment 8828973 [details] [diff] [review]
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.

Updated

2 years ago
Assignee: nobody → jdescottes
Status: NEW → ASSIGNED
Iteration: --- → 53.5 - Jan 23
Priority: P2 → P1

Updated

2 years ago
Iteration: 53.5 - Jan 23 → 54.1 - Feb 6
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.

Updated

2 years ago
Iteration: 54.1 - Feb 6 → 54.2 - Feb 20
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>
Iteration: 54.2 - Feb 20 → ---
Priority: P1 → P2

Updated

a year ago
Blocks: 1333131
Assignee: jdescottes → nobody
Status: ASSIGNED → NEW
Whiteboard: [new-console] → [console-html]
Depends on: 1363768
Depends on: 1364150
Blocks: 1336833
Keywords: meta
Priority: P2 → --
Summary: Improve performance of bulk logging → [meta] Improve performance of bulk logging

Updated

8 months ago
Whiteboard: [console-html]
Summary: [meta] Improve performance of bulk logging → Improve performance of bulk logging

Updated

a month ago
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.