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.

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.

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. 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.

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. https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=de638693d3cb&newProject=try&newRevision=38f731b0cec6&framework=1&showOnlyImportant=0

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

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

Extended from PureComponent, which should improve scrolling

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

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"; // }

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.

Looks better than when I tested it with a previous patch

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

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

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.

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 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.

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.

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

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

This fixes one of the issues.

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

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)

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

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.

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.

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.

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>