Open Bug 1308216 Opened 3 years ago Updated 16 days ago

Improve performance of bulk logging


(DevTools :: Console, task, P3)



(Not tracked)


(Reporter: linclark, Unassigned)


(Depends on 1 open bug, Blocks 3 open bugs)



(5 files, 11 obsolete files)

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
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.
Assignee: nobody → lclark
Severity: normal → enhancement
Priority: -- → P1
Whiteboard: new-console
Attached image Nightly_and_webconsole_js_-_devtools.png (obsolete) —
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.
Attached patch Bug1308216.patchSplinter Review
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.
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.
Introducing the CellMeasurer component actually seems to make things considerably slower :-/ I was looking at 10000 ms for the same testing scenario.
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
Took a little hacking, but I got it working with arbitrary heights reasonably well.


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.
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.
Combining React Virtualized + removing Reps brings us down to 2024.239999999998
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.
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]

Attached patch virtualized.patch (obsolete) — Splinter Review
Super hacky patch that people can test. Will be cleaning up the code.
See Also: → 1308217
Blocks: 1308842
See Also: → 1307932
Attached patch virtualized.patch (obsolete) — Splinter Review
Extended from PureComponent, which should improve scrolling
Attachment #8803368 - Attachment is obsolete: true
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
Depends on: 1312481
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";
  // }
Attached patch virtualized.patch (obsolete) — Splinter Review
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+
Attached patch virtualized.patch (obsolete) — Splinter Review
Attachment #8806077 - Attachment is obsolete: true
Attached patch virtualized.patch (obsolete) — Splinter Review
Attachment #8806771 - Attachment is obsolete: true
Attached patch Bug1308217.patch (obsolete) — Splinter Review
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]

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)
Attached patch Bug1308217.patch (obsolete) — Splinter Review
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]

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-
Attached patch Bug1308217.patch (obsolete) — Splinter Review
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
Attached patch Bug1308217.patch (obsolete) — Splinter Review
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:

Attachment #8807623 - Attachment is obsolete: true
Attached patch Bug1308217.patch (obsolete) — Splinter Review
This fixes one of the issues.
Attachment #8808267 - Attachment is obsolete: true
Attached patch Bug1308217.patchSplinter Review
Discussion with bgrins helped figure out that KeyboardPager is actually not necessary. This patch removes that component.
Attachment #8808271 - Attachment is obsolete: true
Attached patch tweaks.patchSplinter Review
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)
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
Flags: qe-verify-
Priority: P1 → P2
Whiteboard: new-console → [new-console]
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.
Assignee: nobody → jdescottes
Iteration: --- → 53.5 - Jan 23
Priority: P2 → P1
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.
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
Blocks: 1333131
Assignee: jdescottes → nobody
Whiteboard: [new-console] → [console-html]
Depends on: 1363768
Depends on: 1364150
Keywords: meta
Priority: P2 → --
Summary: Improve performance of bulk logging → [meta] Improve performance of bulk logging
Whiteboard: [console-html]
Summary: [meta] Improve performance of bulk logging → Improve performance of bulk logging
Product: Firefox → DevTools
Priority: -- → P3
Summary: Improve performance of bulk logging → [meta] Improve performance of bulk logging

In 71.0b7 with "Requests" logging enabled when loading 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

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

Type: enhancement → task
Keywords: meta
Summary: [meta] Improve performance of bulk logging → Improve performance of bulk logging
You need to log in before you can comment on or make changes to this bug.