Closed Bug 1368100 Opened 3 years ago Closed 2 years ago

Get better performance on the messages reducer

Categories

(DevTools :: Console, enhancement)

enhancement
Not set

Tracking

(Not tracked)

RESOLVED INVALID

People

(Reporter: nchevobbe, Assigned: nchevobbe)

References

(Blocks 1 open bug)

Details

Attachments

(5 obsolete files)

At the moment, we are checking for each messages if we should prune the store so we don't go over the log limit in Prefs.
This can be costly because there's a lot of going on here :
- we check the number of top messages (messages who are not in a group)
- we then run through a loop that gets us an array of the removed messages ids
- and we take care of removing the message reference in the store properties (messagesById, messagesUi, messagesTableById, visibleMessages, ...)

Since we are batching our actions, it would be nice to only do this once per batch. It would be the more efficient way and the user would have the same functionnality.
Also, we could take care of this to only deal with the messagesById and visibleMessages properties, and do the cleanup of the other properties (and the proxy.releaseActors call) when the console isn't working hard, using requestIdleCallback.
Assignee: nobody → nchevobbe
Priority: -- → P1
Summary: Investigate doing the limit logic on the reducer only once per MESSAGE_ADD batch → Get better performance on the store limit logic
Whiteboard: [console-html]
Status: NEW → ASSIGNED
Iteration: --- → 55.6 - May 29
Flags: qe-verify?
Iteration: 55.6 - May 29 → 55.7 - Jun 12
Flags: qe-verify? → qe-verify-
Iteration: 55.7 - Jun 12 → 56.1 - Jun 26
This might be fixed by Bug 1371721.
The time spent in the reducer when streaming is quite low, and I think the only advantage of delaying things would be on bulk log, which is likely to be impacted if we have only one action for a batch.
See Also: → 1371721
Iteration: 56.1 - Jun 26 → 56.2 - Jul 10
Iteration: 56.2 - Jul 10 → 56.3 - Jul 24
Assignee: nchevobbe → nobody
Status: ASSIGNED → NEW
Iteration: 56.3 - Jul 24 → ---
Priority: P1 → P3
Whiteboard: [console-html] → [reserve-console-html]
Nicolas, is this one still relevant after Bug 1371721?
Flags: needinfo?(nchevobbe)
I think it could be re-use to do cleanup (removing message data in other places than messagesById when it is pruned) on the store with requestIdleCallback
Flags: needinfo?(nchevobbe)
Summary: Get better performance on the store limit logic → Cleanup the store in requestIdleCallback
Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
Priority: P3 → P1
Changing the title again as it better reflects the original goal.

I am currently trying to introduce some mutability to *not* clone things when we don't need to.
Basically all the store properties that does not trigger a UI change could be mutable so we can save time.
I do have a WIP patch that works pretty well.

I need to clean things up, maybe put mutable data in a specific store property, rename selectors that fetch mutable data, …
I will then post numbers and profiles with and without the patch.
Summary: Cleanup the store in requestIdleCallback → Get better performance on the messages reducer
I ran (and fixed) the test_render_perf.html test to see if the patch gives us some benefits.

Base revision: https://perf-html.io/public/481880d67b089036e6f4cbbd827b71086203fd62/calltree/?hiddenThreads=&implementation=js&thread=0&threadOrder=0&v=2

- BULK: On average, it took 13602.235 ms (median 13651.96 ms) to render 4000 messages
- Filter toggle time (off): 1112.320000000007
- Filter toggle time (on): 11901.199999999997
- STREAMING AND PRUNING: On average, it took 284.4891500000011 ms (median 254.50750000000698 ms) for each message
- STREAMING: On average, it took 71.22254999999976 ms (median 65.77750000001106 ms) for each message


With the patch: https://perf-html.io/public/6b702a4f57b26820dded6a0cde1f9981d1d4e6f0/calltree/?hiddenThreads=&implementation=js&search=messages&thread=0&threadOrder=0&v=2

- BULK: On average, it took 13005.232000000004 ms (median 13070.470000000001 ms) to render 4000 messages
- Filter toggle time (off): 644.1949999999924
- Filter toggle time (on): 11085.979999999996
- STREAMING AND PRUNING: On average, it took 290.9850000000004 ms (median 250.9574999999968 ms) for each message
- STREAMING: On average, it took 63.85915000000037 ms (median 62.59999999999127 ms) for each message

Even if it's not the most meaningful measurement, the total time spent in reducer:
- Without the patch: 1.5s
- With the patch 385ms

Overall this does not give us a massive improvement (most of the time is still spent on rendering), but this is a nice to have given it does not complicate the code too much.

This patch still need some work, I am going to put all the mutable data into a "mutable" property in the message store (store.messages.messagesById -> store.messages.mutable.messagesById) as well as rename the selectors that fetch mutable data (getAllMessagesById -> getMutableMessagesById) so their usage is more obvious for developers.
Comment on attachment 8929451 [details]
Bug 1368100 - Improve reducer performance by introducing  mutability;.

Adding people who showed interests/concerns about this approach
Attachment #8929451 - Flags: feedback?(poirot.alex)
Attachment #8929451 - Flags: feedback?(odvarko)
Attachment #8929451 - Flags: feedback?(felash)
Attachment #8929452 - Flags: feedback?(poirot.alex)
Attachment #8929452 - Flags: feedback?(odvarko)
Attachment #8929452 - Flags: feedback?(felash)
Comment on attachment 8929450 [details]
Bug 1368100 - Fix batchMessageAdd for test-perf.html; .

https://reviewboard.mozilla.org/r/200764/#review206042
Attachment #8929450 - Flags: review?(bgrinstead) → review+
Flags: qe-verify-
Whiteboard: [reserve-console-html] → [newconsole-mvp]
Duplicate of this bug: 1417446
(In reply to Nicolas Chevobbe [:nchevobbe] from comment #6)
> I ran (and fixed) the test_render_perf.html test

That's an interesting practice (mochitest to test perf).
Ideally, you should be able to write such script directly in DAMP,
but Talos is so slow to startup that I easily understand you using mochitest instead!

> Even if it's not the most meaningful measurement, the total time spent in
> reducer:
> - Without the patch: 1.5s
> - With the patch 385ms

Are you using the profiler to get that number?

What about DAMP? Is there any win reported?
If not, either the patch isn't so worth it, or the existing test cases are not good enough.
Comment on attachment 8929451 [details]
Bug 1368100 - Improve reducer performance by introducing  mutability;.

I'm not experience enough to have a strong feedback here,
but I can confirm that getting rid of Immutable can provide very significant wins (bug 1408182 for netmonitor).
May be the win is mostly related to getting rid of Immutable abstraction and not so much about the reducer rewrite? (in netmonitor we didn't had to rewrite the reducer that much, but may be you have a different setup that forces you to do so?)
Attachment #8929451 - Flags: feedback?(poirot.alex) → feedback+
Attachment #8929452 - Flags: feedback?(poirot.alex)
> Are you using the profiler to get that number?

Yes. The test creates a profile and let you upload it to perf-html (and put markers using performance.measure/mark). Here i ran the test with and without the patch, and checked the total time spent in the reducer function with perf-html indeed.

> What about DAMP? Is there any win reported?

I thought I did use it but can't find the results anymore. I'll push again, but yes, there were improvements for sure in damp too.



> May be the win is mostly related to getting rid of Immutable abstraction and not so much about the reducer rewrite? 

I did not tested the 2 things separately but what I can say is that we were cloning the state for every message in the batch, and now we clone it once, for all the messages in the batch. Even without measurement, I feel like we can assert that this does improve performances (only the magnitude of the improvement is unknown :D)
Blocks: console-perf
Comment on attachment 8929452 [details]
Bug 1368100 - Adapt console to the new messages state;

https://reviewboard.mozilla.org/r/200768/#review206898

::: devtools/client/webconsole/new-console-output/selectors/messages.js:66
(Diff revision 1)
> +  getFilteredMessagesCount,
> +  getMessage,
> +  getMutableCurrentGroup,
> +  getMutableGroupsById,
> +  getMutableMessagesById,
> +  getMutableRemovedActors,

why exposing these if we don't use them ?
Comment on attachment 8929451 [details]
Bug 1368100 - Improve reducer performance by introducing  mutability;.

https://reviewboard.mozilla.org/r/200766/#review206896

I think we discussed about it already: I'm not convinced by introducing some mutable state until we haven't tried other more "redux-y" things. As soon as you introduce mutable state, you introduce complexity. 

I'm fine doing it if:
* we tried other things before (especially the "chunk" idea) and it didn't work (or not enough).
* it brings significant improvements

I think I noticed other issues that could be fixed separately, see the various comments for more information.

::: devtools/client/webconsole/new-console-output/reducers/messages.js:36
(Diff revision 1)
>  } = require("devtools/client/netmonitor/src/utils/request-utils");
>  
> -const MessageState = Immutable.Record({
> +const MessageState = () => ({
> +  // This property contains all the data that can be mutated by this reducer.
> +  // These are not consumed directly by the UI so we can save on copy computation
> +  // and have faster reducer. See Bug 1368100.

well, some _are_ consumed directly by the UI, I see at least `messagesById` is.

::: devtools/client/webconsole/new-console-output/reducers/messages.js
(Diff revision 1)
> -        newState = addMessage(newState, filtersState, prefsState, message);
> -      });
> -
> -      return limitTopLevelMessageCount(newState, logLimit);
> -
> -    case constants.MESSAGE_ADD:

Wow, we had twice the same value, before ? :)

::: devtools/client/webconsole/new-console-output/reducers/messages.js:88
(Diff revision 1)
> -      return new MessageState({
> -        // Store all actors from removed messages. This array is used by
> +      // Store all actors from removed messages. This array is used by
> -        // `releaseActorsEnhancer` to release all of those backend actors.
> +      // `releaseActorsEnhancer` to release all of those backend actors.
> -        "removedActors": [...state.messagesById].reduce((res, [id, msg]) => {
> -          res.push(...getAllActorsInMessage(msg, state));
> -          return res;
> +      const removedActors = [];
> +      for (let [, msg] of mutable.messagesById) {
> +        removedActors.push(...getAllActorsInMessage(msg, state));

If you can have a lot of actors (I don't know ! :) ), you should consider making `getAllActorsInMessage` a generator to avoid all array creations and copying.

::: devtools/client/webconsole/new-console-output/reducers/messages.js:112
(Diff revision 1)
> -                record,
> +              state,
> -                filtersState,
> +              filtersState,
> -                // We want to check if the message is in an open group
> +              // We want to check if the message is in an open group
> -                // only if it is not a direct child of the group we're opening.
> +              // only if it is not a direct child of the group we're opening.
> -                message.groupId !== action.id
> +              message.groupId !== action.id
> -              ).visible
> +            ).visible

You should consider eventually moving this condition out of the `if`, in a boolean const, and even split it. It's very difficult to read in the current form.

::: devtools/client/webconsole/new-console-output/reducers/messages.js:123
(Diff revision 1)
> -          // We can then insert the messages ids right after the one of the group.
> +        // We can then insert the messages ids right after the one of the group.
> -          const insertIndex = visibleMessages.indexOf(action.id) + 1;
> +        const insertIndex = visibleMessages.indexOf(action.id) + 1;
> -          record.set("visibleMessages", [
> +        stateOverride.visibleMessages = [
> -            ...visibleMessages.slice(0, insertIndex),
> +          ...visibleMessages.slice(0, insertIndex),
> -            ...messagesToShow,
> +          ...messagesToShow,
> -            ...visibleMessages.slice(insertIndex),
> +          ...visibleMessages.slice(insertIndex),

This is not really the goal of this patch, but I need to comment here: I believe this is really not efficient here: all messages are sliced twice -- ok, maybe the JS engine optimizes out the second slice, but still.

Maybe we should use a Set instead, as we don't care about the order. I'm really not sure of this :) but I intuitively think a Set will be faster.

::: devtools/client/webconsole/new-console-output/reducers/messages.js:146
(Diff revision 1)
> +        .concat(state.expandedMessageIds.slice(index + 1));
>  
> -        // If the message is a group
> +      // If the message is a group
> -        if (isGroupType(messagesById.get(messageId).type)) {
> +      if (isGroupType(mutable.messagesById.get(messageId).type)) {
> -          // Hide all its children
> +        // Hide all its children
> -          record.set(
> +        stateOverride.visibleMessages = [...visibleMessages].filter(id =>

Why `visibleMessages` is sliced before calling filter here ?

::: devtools/client/webconsole/new-console-output/reducers/messages.js:281
(Diff revision 1)
> -    }
> +      }
> +      partial.expandedMessageIds.push(addedMessage.id);
> -  }
> +    }
>  
> -  return groups;
> +    const visibility =
> +      getMessageVisibility(addedMessage, applyPartialState(state, partial), filtersState);

I'm surprised `applyPartialState` is called both here and at the end -- and at both places we get a new object with `Object.assign`. Moreover here we're right in the loop! So this means we're creating a new state -- that we barely use -- for each message!

Can't you get the message visibility without doing this here ?

::: devtools/client/webconsole/new-console-output/reducers/messages.js:344
(Diff revision 1)
> +        list.unshift(message);
> +      } else {
> +        break;
> +      }
> +    } else {
> +      list.unshift(message);

Be careful, as "unshift" can be costly as this needs to move all elements to the end. I don't know if this is costly here but I feel like it can be because we could loop over a lot of messages here.

Maybe try to know beforehand what's the list length will be and directly create it with `const list = Array(length)` and then populate it?

Or maybe we can just return the id where we need to stop, so that we don't need to copy all elements over to a new list ?
Attachment #8929451 - Flags: feedback?(felash)
Attachment #8929452 - Flags: feedback?(felash)
Comment on attachment 8929451 [details]
Bug 1368100 - Improve reducer performance by introducing  mutability;.

https://reviewboard.mozilla.org/r/200766/#review206896

Thanks for the valuable feedback Julien. 
The mutability still makes sense to me, performance are improved for batching (a bit) and filtering (a lot) (I need to write damp tests and run it on this patch). 
I am going to test the chunk approach in the next days too.

> well, some _are_ consumed directly by the UI, I see at least `messagesById` is.

yeah, I should rather say: are not directly used as props in components :)

> Wow, we had twice the same value, before ? :)

Nope, this is MESSAGE_ADD (singular), we keep MESSAGES_ADD (plural)

> If you can have a lot of actors (I don't know ! :) ), you should consider making `getAllActorsInMessage` a generator to avoid all array creations and copying.

good idea

> You should consider eventually moving this condition out of the `if`, in a boolean const, and even split it. It's very difficult to read in the current form.

getMessageVisibility is relatively costly, so having it here allow us to only call it when the previous condition are truthy (e.e. not always)
But I guess we can still do that even if we break conditions in multiple variables.

> This is not really the goal of this patch, but I need to comment here: I believe this is really not efficient here: all messages are sliced twice -- ok, maybe the JS engine optimizes out the second slice, but still.
> 
> Maybe we should use a Set instead, as we don't care about the order. I'm really not sure of this :) but I intuitively think a Set will be faster.

we do care about the order :D

> Why `visibleMessages` is sliced before calling filter here ?

good point

> I'm surprised `applyPartialState` is called both here and at the end -- and at both places we get a new object with `Object.assign`. Moreover here we're right in the loop! So this means we're creating a new state -- that we barely use -- for each message!
> 
> Can't you get the message visibility without doing this here ?

yeah, I think we can

> Be careful, as "unshift" can be costly as this needs to move all elements to the end. I don't know if this is costly here but I feel like it can be because we could loop over a lot of messages here.
> 
> Maybe try to know beforehand what's the list length will be and directly create it with `const list = Array(length)` and then populate it?
> 
> Or maybe we can just return the id where we need to stop, so that we don't need to copy all elements over to a new list ?

I'll try to find a better way
(In reply to Nicolas Chevobbe [:nchevobbe] from comment #17)
> > May be the win is mostly related to getting rid of Immutable abstraction and not so much about the reducer rewrite? 
> 
> I did not tested the 2 things separately but what I can say is that we were
> cloning the state for every message in the batch, and now we clone it once,
> for all the messages in the batch. Even without measurement, I feel like we
> can assert that this does improve performances (only the magnitude of the
> improvement is unknown :D)

About that, me and Honza have been quite surprised to see that Map duplication was very cheap.
I've also been really impressed by Immutable overhead in the netmonitor codebase (Around 8%, which is a lot on netmonitor).
Now, may be console better uses it and doesn't suffer from the same overhead?
But if it happens to be the same experience than in netmonitor, most of the win
may come from it.

Do you think that could be easy to craft a patch to only replace Immutable by plain JS structures?
  (In reply to Nicolas Chevobbe [:nchevobbe] from comment #21)
> Comment on attachment 8929451 [details]
> Bug 1368100 - Improve reducer performance by introducing  mutability;.
> 
> https://reviewboard.mozilla.org/r/200766/#review206896
> 
> Thanks for the valuable feedback Julien. 
> The mutability still makes sense to me, performance are improved for
> batching (a bit) and filtering (a lot) (I need to write damp tests and run
> it on this patch). 
> I am going to test the chunk approach in the next days too.
> 
> > well, some _are_ consumed directly by the UI, I see at least `messagesById` is.
> 
> yeah, I should rather say: are not directly used as props in components :)

Well yes, one of them is used directly as a prop: in devtools/client/webconsole/new-console-output/components/ConsoleOutput.js, getMutableMessagesById is called directly, and its result is passed as the prop `messages`. So _yes_ it's used directly as a prop.

Now I don't know if this is an issue. But I suspect this can be an issue...
(In reply to Alexandre Poirot [:ochameau] from comment #22)
> (In reply to Nicolas Chevobbe [:nchevobbe] from comment #17)
> > > May be the win is mostly related to getting rid of Immutable abstraction and not so much about the reducer rewrite? 
> > 
> > I did not tested the 2 things separately but what I can say is that we were
> > cloning the state for every message in the batch, and now we clone it once,
> > for all the messages in the batch. Even without measurement, I feel like we
> > can assert that this does improve performances (only the magnitude of the
> > improvement is unknown :D)
> 
> Do you think that could be easy to craft a patch to only replace Immutable
> by plain JS structures?

I'd also be interested in how much of the perf improvement comes from Immutable replacement, assuming that it's relatively easy to split apart from the rewrite. At the least, it'd be easier to review the changes if the patch was split into two where the first did a replacement of Immutable and the second did the rewrite.
Okay, I can do that.
Depends on: 1422841
Attachment #8929453 - Attachment is obsolete: true
Attachment #8929453 - Flags: review?(bgrinstead)
Attachment #8929452 - Attachment is obsolete: true
Attachment #8929452 - Flags: review?(bgrinstead)
Attachment #8929452 - Flags: feedback?(odvarko)
Attachment #8929451 - Attachment is obsolete: true
Attachment #8929451 - Flags: review?(bgrinstead)
Attachment #8929451 - Flags: feedback?(odvarko)
Attachment #8929450 - Attachment is obsolete: true
Attachment #8928979 - Attachment is obsolete: true
Attachment #8928979 - Flags: review?(bgrinstead)
Marking patches as obsolete since Bug 1422841 is removing immutable, and might be enough as a first step, or at least, give us the data on if removing Immutable or/and introducing immutability here was responsible for performance gain. Which should then drive our decision whether or not introducing mutability
With Bug 1425577, I think reducers are now fast enough. The major culprit in console performance is React rendering, so let's close this and focus on the rendering part.
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → INVALID
Priority: P1 → --
Whiteboard: [newconsole-mvp]
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.