Closed Bug 1363678 Opened 7 years ago Closed 7 years ago

Do the filtering logic on the reducer

Categories

(DevTools :: Console, enhancement, P1)

Product:
DevTools
Component:
Console
Type:
enhancement

Tracking

(firefox55 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 55
Iteration:
55.7 - Jun 12
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: nchevobbe, Assigned: nchevobbe)

References

Details

(Whiteboard: [console-html])

Attachments

(4 files)

Bug 1363678 - Move the filtering logic to the reducer.
59 bytes, text/x-review-board-request
bgrins
: review+
Details
Bug 1363678 - Refactor how we do the messages limit on the reducer.
59 bytes, text/x-review-board-request
Honza
: review+
Details
Bug 1363678 - Adapt tests to the new filtering logic.
59 bytes, text/x-review-board-request
bgrins
: review+
Honza
: review+
Details
Bug 1363678 - Allow to pass a custom logLimit to configureStore.
59 bytes, text/x-review-board-request
bgrins
: review+
Details 
At the moment, we're having all the filtering logic in the selector, which means it's run on every message of the store for each message, which can be really costly.

We would have a `visibleMessages` array in the store that would contain all the ids of the messages that should be shown.

Something that we could do is:
- when we add a message, check if a message should be filtered out
- when we open a group, check if the messages inside should be filtered
- when we close a group, hide the messages inside the group
- when we change a filter or set a new filter text, check for each messages in the store if they should be filtered. We can even only work on a subset of the messages of the store depending how the filter change :
  - if the new text filter start with the same content as the old text filter, we can only check the already visible messages
  - if we turn off a filter button (log, xhr, ...), we can also only check the visible messages
Assignee: nobody → nchevobbe
Priority: -- → P1
Blocks: 1363682
Whiteboard: [console-html]
Summary: Do the filtering console on the reducer → Do the filtering logic on the reducer
Status: NEW → ASSIGNED
Iteration: --- → 55.5 - May 15
Flags: qe-verify?
Flags: qe-verify? → qe-verify-
Iteration: 55.5 - May 15 → 55.6 - May 29
Blocks: 1367318
Comment on attachment 8871818 [details]
Bug 1363678 - Move the filtering logic to the reducer.

https://reviewboard.mozilla.org/r/142242/#review147096

::: commit-message-1bfa4:5
(Diff revision 1)
> +Bug 1363678 - Move the filtering logic to the reducer. r=bgrins
> +
> +We used to do the filtering on the selector, which can be costly because
> +we're looping through all the messages of the store on each new message.
> +Moving the logic to the reducer allow us to be more thoughful about which

'thoughful' -> 'thoughtful' and possibly 'then' is meant as 'when'?

::: devtools/client/webconsole/new-console-output/reducers/messages.js:107
(Diff revision 1)
>              record.set("messagesUiById", messagesUiById.push(newMessage.id));
>            }
>          }
>  
> +        if (shouldMessageBeVisible(addedMessage, record, filtersState)) {
> +          record.set("visibleMessages", [...visibleMessages, newMessage.id]);

Why is visibleMessages and array of ints? They seem to always be cast back into a message before using.

::: devtools/client/webconsole/new-console-output/reducers/messages.js:232
(Diff revision 1)
> +      }
> +
> +      return state.set(
> +        "visibleMessages",
> +        visibleMessages.concat(messagesToShow)
> +          .sort((idA, idB) => {

Is this sorting logic definitely always right (even with grouped messages)?  If so, I actually kind of like this method as opposed to having to insert visible messages in just the right place when a group is opened like on line 156 (aka just go ahead and push everything that should be added onto the back of visibleMessages and then do a sort before setting it back into state). Up to you

::: devtools/client/webconsole/new-console-output/reducers/messages.js:242
(Diff revision 1)
> +      );
> +
> +    case constants.FILTER_TEXT_SET:
> +      let {oldValue = "", newValue = ""} = action;
> +
> +      if (newValue.startsWith(oldValue)) {

Is there a need for this optimization (and the subtracting one below)? If it's not critical we could cut out lines 242-288.

This would also get rid of the need for the view to pass the old value to the action (which seems like it could be error prone).  If the optimization is necessary, then it seems we should be keeping track of the 'old value' in the state here instead of relying on the component

::: devtools/client/webconsole/new-console-output/selectors/messages.js:33
(Diff revision 1)
>  function getCurrentGroup(state) {
>    return state.messages.currentGroup;
>  }
>  
> -function isUnfilterable(message) {
> -  return [
> +function getVisibleMessages(state) {
> +  return state.messages.visibleMessages;

If visibleMessages makes the most sense as an array of IDs then I think this selector function should fold in the behavior from getMessage in as well.  This way getVisibleMessages returns an array of messages and the component doesn't have to worry about casting the ID into a message type
Attachment #8871818 - Flags: review?(bgrinstead)
Comment on attachment 8871818 [details]
Bug 1363678 - Move the filtering logic to the reducer.

https://reviewboard.mozilla.org/r/142242/#review147096

> 'thoughful' -> 'thoughtful' and possibly 'then' is meant as 'when'?

Yes, thanks !

> Why is visibleMessages and array of ints? They seem to always be cast back into a message before using.

I tried to have a normalized store, i.e. the data is only in one property (messagesById), and all the other properties that refer to it only deal with ids. This way, if we have to change the data of one message (which we do, even if it's planned to remove this behaviour), we only change it in the "source of truth".

> Is this sorting logic definitely always right (even with grouped messages)?  If so, I actually kind of like this method as opposed to having to insert visible messages in just the right place when a group is opened like on line 156 (aka just go ahead and push everything that should be added onto the back of visibleMessages and then do a sort before setting it back into state). Up to you

I do think it is always right, the timestamp is set by the server iirc, so we should be able to sort without issues.
For the insertion after group, I thought it would be faster that way instead of doing a sort on the whole array, although I didn't make any measurements to back that up.
I'll setup some quick tests to see what performs best.

> Is there a need for this optimization (and the subtracting one below)? If it's not critical we could cut out lines 242-288.
> 
> This would also get rid of the need for the view to pass the old value to the action (which seems like it could be error prone).  If the optimization is necessary, then it seems we should be keeping track of the 'old value' in the state here instead of relying on the component

I do think it's critical.
The search function is quite costly, and whatever we can do to reduce the number of messages to check is a good idea I think.
I agree that it could be error prone, I'll add tests to be sure we cover it the right way.

> If visibleMessages makes the most sense as an array of IDs then I think this selector function should fold in the behavior from getMessage in as well.  This way getVisibleMessages returns an array of messages and the component doesn't have to worry about casting the ID into a message type

I like this better too, I'll change it.
Comment on attachment 8871818 [details]
Bug 1363678 - Move the filtering logic to the reducer.

https://reviewboard.mozilla.org/r/142242/#review147096

> I do think it is always right, the timestamp is set by the server iirc, so we should be able to sort without issues.
> For the insertion after group, I thought it would be faster that way instead of doing a sort on the whole array, although I didn't make any measurements to back that up.
> I'll setup some quick tests to see what performs best.

So here's my test case:
- a store with 1000 messages
- a group with 5 messages in it

And the perf test in the code where we open a group in the reducer :
```
const iterations = 100;
console.time("sort");
for(let i = 0; i < iterations; i++) {
  let x = [...visibleMessages].sort((idA, idB) => {
    let messageA = messagesById.get(idA);
    let messageB = messagesById.get(idB);
    return messageA.timeStamp > messageB.timeStamp;
  })
}
console.timeEnd("sort");
console.time("insert");
for(let i = 0; i < iterations; i++) {
  let idx = visibleMessages.indexOf(action.id) + 1;
  let x = [
    ...visibleMessages.slice(0, idx),
    ...messagesToShow,
    ...visibleMessages.slice(idx),
  ]
}
console.timeEnd("insert");
```

Here are the results I see in the console, when I open/close the group a handful of times :

```
sort: 372.35ms
insert: 15.86ms

sort: 368.47ms
insert: 12.63ms

sort: 354.9ms
insert: 13.65ms

sort: 338.92ms
insert: 4.58ms

sort: 337.64ms
insert: 5.9ms

sort: 325.55ms
insert: 4.23ms

sort: 323.1ms
insert: 4.24ms
```

We can see that inserting is from 20 to ~90 times faster.
Even with only 1 iteration (which is what we do in regular condition), I get: 

```
sort: 22.74ms
insert: 1.6ms

sort: 9.43ms
insert: 1.88ms

sort: 8.48ms
insert: 5.67ms

sort: 6.01ms
insert: 0.6ms

sort: 6.15ms
insert: 0.54ms

sort: 6.47ms
insert: 0.68ms

sort: 6.46ms
insert: 0.5ms

sort: 5.93ms
insert: 0.7ms
```

We can see that sorting isn't really an option if we want 60fps.
Attachment #8871818 - Flags: review?(bgrinstead)
Attachment #8871819 - Flags: review?(bgrinstead) → review?(odvarko)
Comment on attachment 8871819 [details]
Bug 1363678 - Refactor how we do the messages limit on the reducer.

https://reviewboard.mozilla.org/r/143288/#review147568

Couple of inline comments

::: devtools/client/webconsole/new-console-output/reducers/messages.js:369
(Diff revision 2)
> -  // can be associated with backend actors.
> +        // can be associated with backend actors.
> -  removedMessages = state.removedMessages.filter(msg => msg.parameters);
> +        if (message && message.parameters) {
> +          removedMessages.push(message);
> +        }
> +
> +        const index = visibleMessages.indexOf(id);

Not  sure where exactly the problem happens, but here is STR:

1) Log a two groups and then simple logs to reach the max limit (I am chaning the max to 10 when testing)
2) Step by step create additional logs and watch the  two groups disappear
3) First, title of the first group disappear. Consequently all its children, but the last child disappears together with the title of the second group.

Is this intended?

Honza

::: devtools/client/webconsole/new-console-output/reducers/messages.js:399
(Diff revision 2)
> +    record.set("messagesTableDataById",
> +      record.messagesTableDataById.withMutations(cleanUpCollection));
> +  }
> +
> +  if (record.groupsById.isSuperset(removedMessagesId)) {
> +    record.set("groupsById", record.groupsById.withMutations(cleanUpCollection));

Can `removedMessagesId` array contain group and non group messages? If yes, should we really use `isSubset` (because it would be false if non-group messages are in the array).
Attachment #8871819 - Flags: review?(odvarko)
Comment on attachment 8871819 [details]
Bug 1363678 - Refactor how we do the messages limit on the reducer.

https://reviewboard.mozilla.org/r/143288/#review147568

> Can `removedMessagesId` array contain group and non group messages? If yes, should we really use `isSubset` (because it would be false if non-group messages are in the array).

you're right, and there must be similar problem with messagesTableDataById.
I'll fix that, thanks
Comment on attachment 8871819 [details]
Bug 1363678 - Refactor how we do the messages limit on the reducer.

https://reviewboard.mozilla.org/r/143288/#review147568

> you're right, and there must be similar problem with messagesTableDataById.
> I'll fix that, thanks

Fixed by using "find"
Comment on attachment 8871819 [details]
Bug 1363678 - Refactor how we do the messages limit on the reducer.

https://reviewboard.mozilla.org/r/143288/#review147860
Comment on attachment 8871820 [details]
Bug 1363678 - Adapt tests to the new filtering logic.

https://reviewboard.mozilla.org/r/143290/#review147948

I reviewed all changes except for the group related parts which I think Honza will look at.  If we end up pulling out the filter optimizations from this patch then technically we could also remove the 'previousText' code and tests but I'd also be OK with keeping the logic in place so that we can re-add the optimizations later (up to you).
Attachment #8871820 - Flags: review?(bgrinstead) → review+
Iteration: 55.6 - May 29 → 55.7 - Jun 12
Comment on attachment 8871818 [details]
Bug 1363678 - Move the filtering logic to the reducer.

https://reviewboard.mozilla.org/r/142242/#review148216

::: devtools/client/webconsole/new-console-output/reducers/messages.js:213
(Diff revision 3)
> +      // Here we can check if non-visible messages should now be visible
> +      let messagesToShow = [...messagesById].reduce((res, [messageId, message]) => {
> +        if (
> +          !visibleMessages.includes(messageId)
> +          && shouldMessageBeVisible(message, state, filtersState)
> +        ) {
> +          res.push(messageId);
> +        }
> +        return res;
> +      }, []);
> +
> +      if (messagesToShow.length === 0) {
> +        return state;
> +      }
> +
> +      return state.set(
> +        "visibleMessages",
> +        visibleMessages.concat(messagesToShow)
> +          .sort((idA, idB) => {
> +            let messageA = messagesById.get(idA);
> +            let messageB = messagesById.get(idB);
> +            return messageA.timeStamp > messageB.timeStamp;
> +          })
> +      );

Brian your guess was right on this.
Doing a "dumb" implementation (looping through each messages to build the visibleMessage array) is faster.

Here's my test cases :

```
console.time("optimized");
{
  let messagesToShow = [...messagesById].reduce((res, [messageId, message]) => {
    if (
      !visibleMessages.includes(messageId)
      && shouldMessageBeVisible(message, state, filtersState)
    ) {
      res.push(messageId);
    }
    return res;
  }, []);

  visibleMessages.concat(messagesToShow)
    .sort((idA, idB) => {
      let messageA = messagesById.get(idA);
      let messageB = messagesById.get(idB);
      return messageA.timeStamp > messageB.timeStamp;
    });
}
console.timeEnd("optimized");
console.time("dumb");
{
  let messagesToShow = [...messagesById].reduce((res, [messageId, message]) => {
    if (shouldMessageBeVisible(message, state, filtersState)) {
      res.push(messageId);
    }
    return res;
  }, []);
}
console.timeEnd("dumb");
```

And the results I get with a store that has 1000 messages: 

```
optimized: 44.75ms
dumb: 9.17ms

optimized: 21.02ms
dumb: 8.99ms

optimized: 21.7ms
dumb: 15.89ms

optimized: 14.84ms
dumb: 4.52ms

optimized: 73.49ms
dumb: 16.52ms

optimized: 30.3ms
dumb: 12.48ms

optimized: 25.43ms
dumb: 9.67ms

optimized: 80.77ms
dumb: 20.11ms

optimized: 52.25ms
dumb: 11.25ms

optimized: 57.29ms
dumb: 6.8ms

optimized: 26.52ms
dumb: 3.6ms

optimized: 40.46ms
dumb: 6.55ms

optimized: 32.63ms
dumb: 6.54ms

optimized: 31.75ms
dumb: 9.32ms
```
Comment on attachment 8871819 [details]
Bug 1363678 - Refactor how we do the messages limit on the reducer.

https://reviewboard.mozilla.org/r/143288/#review148294

Looks good to me now, thanks Nicolas!

Honza

::: devtools/client/webconsole/new-console-output/reducers/messages.js:250
(Diff revision 4)
> - * messages.
> + * messages so they can be released.
>   */
>  function limitTopLevelMessageCount(state, record) {
> -  let tempRecord = {
> -    messagesById: record.messagesById,
> -    messagesUiById: record.messagesUiById,
> +  let topLevelCount = record.groupsById.size === 0
> +    ? record.messagesById.size
> +    : getToplevelMessageCount(record);

I metioned that at our meeting, but... I think we can count number of top level messages continuously as new messages are appended into the list (and solve the perf issue).

::: devtools/client/webconsole/new-console-output/reducers/messages.js:274
(Diff revision 4)
> +    // we exit the forEach iteration.
> +    if (cleaningGroup === false && topLevelCount <= logLimit) {
> +      return false;
> +    }
> +
> +    if (cleaningGroup === false && record.groupsById.has(id)) {

This condition would also deserve a comment
Attachment #8871819 - Flags: review?(odvarko) → review+
Comment on attachment 8871819 [details]
Bug 1363678 - Refactor how we do the messages limit on the reducer.

https://reviewboard.mozilla.org/r/143288/#review148294

> I metioned that at our meeting, but... I think we can count number of top level messages continuously as new messages are appended into the list (and solve the perf issue).

I might do it in https://bugzilla.mozilla.org/show_bug.cgi?id=1368100

> This condition would also deserve a comment

sure
Comment on attachment 8871819 [details]
Bug 1363678 - Refactor how we do the messages limit on the reducer.

https://reviewboard.mozilla.org/r/143288/#review148312
Comment on attachment 8871818 [details]
Bug 1363678 - Move the filtering logic to the reducer.

https://reviewboard.mozilla.org/r/142242/#review148376

::: devtools/client/webconsole/new-console-output/store.js:52
(Diff revision 4)
>      initialState,
>      compose(applyMiddleware(thunk), enableActorReleaser(hud), enableBatching())
>    );
>  }
>  
> +function createRootReducer() {

Is this custom reducer still needed after the filter optimization has been removed?
Attachment #8871818 - Flags: review?(bgrinstead) → review+
Comment on attachment 8871818 [details]
Bug 1363678 - Move the filtering logic to the reducer.

https://reviewboard.mozilla.org/r/142242/#review148376

> Is this custom reducer still needed after the filter optimization has been removed?

yes, this only gives us the ability to pass the filter state to the messages reducer.
We still rely on that to decide wether or not a message should be displayed
Comment on attachment 8871820 [details]
Bug 1363678 - Adapt tests to the new filtering logic.

https://reviewboard.mozilla.org/r/143290/#review148462

Looks great, just couple of inline comments.

Honza

::: devtools/client/webconsole/new-console-output/test/mochitest/browser_webconsole_console_group.js:19
(Diff revision 5)
>  add_task(function* () {
>    let toolbox = yield openNewTabAndToolbox(TEST_URI, "webconsole");
>    let hud = toolbox.getCurrentPanel().hud;
>  
>    const store = hud.ui.newConsoleOutput.getStore();
>    // Adding loggin each time the store is modified in order to check

loggin -> logging

::: devtools/client/webconsole/new-console-output/test/store/messages.test.js:163
(Diff revision 5)
> +      const messages = getAllMessagesById(getState());
> +
> +      expect(messages.count()).toBe(logLimit);
> +      expect(visibleMessages.length).toBe(logLimit);
> +      expect(visibleMessages[0].parameters[0]).toBe(`message-0`);
> +      expect(visibleMessages[logLimit - 1].parameters[0]).toBe(`message-${logLimit - 1}`);

What about adding:

const groups = getAllGroupsById(getState());
expect(groups.count()).toBe(0);

And perhaps testing the groups map size in other cases too?

::: devtools/client/webconsole/new-console-output/test/store/messages.test.js:169
(Diff revision 5)
> +    });
> +
>      it("properly limits number of groups", () => {
>        const { dispatch, getState } = setupStore([]);
>  
>        const logLimit = 1000;

What about decreasing the max limit so, the test takes less runtime?
Attachment #8871820 - Flags: review?(odvarko) → review+
(In reply to Jan Honza Odvarko [:Honza] from comment #30)
> What about decreasing the max limit so, the test takes less runtime?

Done.
I had to change how we set the limit and get it from the reducer to make this works as seamlessly as possible.
I added a patch in my review for that.
Comment on attachment 8873348 [details]
Bug 1363678 - Allow to pass a custom logLimit to configureStore.

https://reviewboard.mozilla.org/r/144794/#review148784

In commit message: Services.setIntPrefs -> Services.setIntPref
Attachment #8873348 - Flags: review?(bgrinstead) → review+
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/617099302c92
Move the filtering logic to the reducer. r=bgrins
https://hg.mozilla.org/integration/autoland/rev/e9f6b7429336
Refactor how we do the messages limit on the reducer. r=Honza
https://hg.mozilla.org/integration/autoland/rev/f481ef5c3bf0
Adapt tests to the new filtering logic. r=bgrins,Honza
https://hg.mozilla.org/integration/autoland/rev/39d218ebd0d6
Allow to pass a custom logLimit to configureStore. r=bgrins
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: