Getting message from the store in ConsoleOutput is costly

RESOLVED FIXED in Firefox 56

Status

()

Firefox
Developer Tools: Console
P1
normal
RESOLVED FIXED
6 months ago
6 months ago

People

(Reporter: nchevobbe, Assigned: nchevobbe)

Tracking

unspecified
Firefox 56
Points:
---
Bug Flags:
qe-verify -

Firefox Tracking Flags

(firefox56 fixed)

Details

(Whiteboard: [console-html])

MozReview Requests

()

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment)

(Assignee)

Description

6 months ago
Here is a profile of streaming 100 messages when the store already hit the logLimit (set to 4000 there) :

https://perfht.ml/2s7YVLI

We can see that for the whole 100 messages, it takes almost 1.5 seconds, which is quite a lot..

The reason for this is because we call this method for each message add, on all of the messages in the store.

In our test case, we do this 400000 times (100 messages added on a 4000 messages-filled store).

My guess is that it will be more efficient to retrieve the message data in the MessageContainer component, since it is updated only when needed.

We would call get getMessage function only once for each message added (in our test case, it would be 100 times instead of 400000).
(Assignee)

Comment 1

6 months ago
Here is a profile with a patch that moves the retrieval of the message into the MessageContainer component: https://perfht.ml/2s7T1dO

We went from 1.5s to 11ms, which sounds great.

Here's the test_render_perf.html test output:

WITHOUT PATCH

3 INFO took 10459.12 ms to render bulk messages (iteration 0)
4 INFO took 9525.295000000002 ms to render bulk messages (iteration 1)
5 INFO took 9481.869999999995 ms to render bulk messages (iteration 2)
6 INFO took 8976.904999999999 ms to render bulk messages (iteration 3)
7 INFO took 10059.844999999994 ms to render bulk messages (iteration 4)
8 INFO BULK: On average, it took 9700.606999999998 ms (median 8976.904999999999 ms) to render 4000 messages
9 INFO Filter toggle time (off): 537.2750000000015
10 INFO Filter toggle time (on): 7817.604999999996
11 INFO STREAMING AND PRUNING: On average, it took 181.57307142857204 ms (median 165.16250000000582 ms) for each message
12 INFO STREAMING: On average, it took 57.1974999999999 ms (median 56.0625 ms) for each message


WITH PATCH

3 INFO took 9464.98 ms to render bulk messages (iteration 0)
4 INFO took 8905.45 ms to render bulk messages (iteration 1)
5 INFO took 9329.704999999998 ms to render bulk messages (iteration 2)
6 INFO took 8067.699999999997 ms to render bulk messages (iteration 3)
7 INFO took 9071.79 ms to render bulk messages (iteration 4)
8 INFO BULK: On average, it took 8967.925 ms (median 9071.79 ms) to render 4000 messages
9 INFO Filter toggle time (off): 355.6449999999968
10 INFO Filter toggle time (on): 5946.815000000002
11 INFO STREAMING AND PRUNING: On average, it took 142.366428571429 ms (median 133.7624999999971 ms) for each message
12 INFO STREAMING: On average, it took 57.51294117646894 ms (median 56.31999999999243 ms) for each message

Those number also seam nice, but they vary a bit between each run, so I won't trust them too much.

What I constantly observe though is a gain of ~15ms for the stream and prune message add in the test.
In any case, I think that it's worth it because we avoid doing something, and the faster code is the one that isn't ran :)

I'll try to get more stable results on this, and if they appear to at least not hit performances, I think we could land this (the tests would need a bit of work though)
Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
Flags: qe-verify-
Priority: -- → P1
Whiteboard: [console-html]
(Assignee)

Comment 2

6 months ago
Some other numbers with disabling bluetooth, wifi, notifications, and having only terminal and the test running:

WITHOUT PATCH

3 INFO took 6422.51 ms to render bulk messages (iteration 0)
4 INFO took 6373.450000000001 ms to render bulk messages (iteration 1)
5 INFO took 6587.2750000000015 ms to render bulk messages (iteration 2)
6 INFO took 5572.625 ms to render bulk messages (iteration 3)
7 INFO took 5675.245000000003 ms to render bulk messages (iteration 4)
8 INFO BULK: On average, it took 6126.2210000000005 ms (median 6373.450000000001 ms) to render 4000 messages
9 INFO Filter toggle time (off): 285.31000000000495
10 INFO Filter toggle time (on): 4794.739999999998
11 INFO STREAMING AND PRUNING: On average, it took 175.84628571428578 ms (median 210.98749999999563 ms) for each message
12 INFO STREAMING: On average, it took 58.746176470588956 ms (median 58.96249999999418 ms) for each message

3 INFO took 6430.85 ms to render bulk messages (iteration 0)
4 INFO took 6078.505000000001 ms to render bulk messages (iteration 1)
5 INFO took 6798.870000000003 ms to render bulk messages (iteration 2)
6 INFO took 6411.225000000002 ms to render bulk messages (iteration 3)
7 INFO took 6083.579999999998 ms to render bulk messages (iteration 4)
8 INFO BULK: On average, it took 6360.606000000002 ms (median 6411.225000000002 ms) to render 4000 messages
9 INFO Filter toggle time (off): 448.9649999999965
10 INFO Filter toggle time (on): 5241.6500000000015
11 INFO STREAMING AND PRUNING: On average, it took 192.67192857142842 ms (median 207.7674999999981 ms) for each message
12 INFO STREAMING: On average, it took 60.630147058823184 ms (median 60.36499999999796 ms) for each message


WITH PATCH

3 INFO took 6003.240000000001 ms to render bulk messages (iteration 0)
4 INFO took 5654.230000000001 ms to render bulk messages (iteration 1)
5 INFO took 5698.445 ms to render bulk messages (iteration 2)
6 INFO took 6906.739999999998 ms to render bulk messages (iteration 3)
7 INFO took 5548.459999999999 ms to render bulk messages (iteration 4)
8 INFO BULK: On average, it took 5962.223 ms (median 5698.445 ms) to render 4000 messages
9 INFO Filter toggle time (off): 723.4500000000044
10 INFO Filter toggle time (on): 3743.239999999998
11 INFO STREAMING AND PRUNING: On average, it took 176.81100000000026 ms (median 184.2475000000013 ms) for each message
12 INFO STREAMING: On average, it took 66.65029411764665 ms (median 63.79750000000058 ms) for each message

3 INFO took 6548.175 ms to render bulk messages (iteration 0)
4 INFO took 5692.390000000001 ms to render bulk messages (iteration 1)
5 INFO took 5766.095000000001 ms to render bulk messages (iteration 2)
6 INFO took 6602.294999999998 ms to render bulk messages (iteration 3)
7 INFO took 6606.720000000001 ms to render bulk messages (iteration 4)
8 INFO BULK: On average, it took 6243.135 ms (median 6548.175 ms) to render 4000 messages
9 INFO Filter toggle time (off): 446.1050000000032
10 INFO Filter toggle time (on): 5332.739999999998
11 INFO STREAMING AND PRUNING: On average, it took 177.7865000000003 ms (median 191.68499999999767 ms) for each message
12 INFO STREAMING: On average, it took 64.64867647058803 ms (median 63.362500000010186 ms) for each message



This is utterly frustrating, basically nothing is going on my machine, but the numbers have a min/max difference of 1.5s for bulk log, and I get worse numbers (with and without patch) than when I run multiple things (firefox, spotify, ... ).
I wish there was a way to be sure 100% that this patch would help performances.

Updated

6 months ago
Whiteboard: [console-html] → [console-html] [triage]

Updated

6 months ago
Iteration: --- → 56.1 - Jun 26
Whiteboard: [console-html] [triage] → [console-html]
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 5

6 months ago
mozreview-review
Comment on attachment 8879187 [details]
Bug 1373568 - Retrieve message data in MessageContainer instead of in ConsoleOutput; .

https://reviewboard.mozilla.org/r/150526/#review155672

::: devtools/client/webconsole/new-console-output/components/message-container.js
(Diff revision 2)
>  
>    shouldComponentUpdate(nextProps, nextState) {
>      const repeatChanged = this.props.repeat !== nextProps.repeat;
>      const openChanged = this.props.open !== nextProps.open;
>      const tableDataChanged = this.props.tableData !== nextProps.tableData;
> -    const responseChanged = this.props.message.response !== nextProps.message.response;

Are we going to miss any updates when message.response or message.totalTime changes?  Or is this somehow covered in the networkMessageUpdateChanged condition?

::: devtools/client/webconsole/new-console-output/components/message-container.js:68
(Diff revision 2)
>  
>    render() {
> -    const { message } = this.props;
> +    const message = this.props.getMessage();
>  
>      let MessageComponent = getMessageComponent(message);
> -    return MessageComponent(this.props);
> +    return MessageComponent(Object.assign({message, indent: message.indent}, this.props));

Doesn't need to be done in this bug, but I don't see why `indent` is needed as a separate prop.  All of the message types seem to just pass along the value into the message Message component (which has a default value of 0).  Seems they could grab it off of the message object and still pass it into Message.
Attachment #8879187 - Flags: review?(bgrinstead)
(Assignee)

Comment 6

6 months ago
mozreview-review-reply
Comment on attachment 8879187 [details]
Bug 1373568 - Retrieve message data in MessageContainer instead of in ConsoleOutput; .

https://reviewboard.mozilla.org/r/150526/#review155672

> Are we going to miss any updates when message.response or message.totalTime changes?  Or is this somehow covered in the networkMessageUpdateChanged condition?

Yes, those updates were moved to `networkMessageUpdateChanged`, and so we don't need those lines anymore. 
I should have removed them when I did the `networkMessageUpdateChanged` patch.

> Doesn't need to be done in this bug, but I don't see why `indent` is needed as a separate prop.  All of the message types seem to just pass along the value into the message Message component (which has a default value of 0).  Seems they could grab it off of the message object and still pass it into Message.

Yeah I agree, I think this is due to how we handled it before (it was computed in ConsoleOutput).
I'll file a bug to change that.
(Assignee)

Comment 7

6 months ago
> Doesn't need to be done in this bug, but I don't see why `indent` is needed as a separate prop.  All of the message types seem to just pass along the value into the message Message component (which has a default value of 0).  Seems they could grab it off of the message object and still pass it into Message.

Filed Bug 1374680 for this

Comment 8

6 months ago
mozreview-review
Comment on attachment 8879187 [details]
Bug 1373568 - Retrieve message data in MessageContainer instead of in ConsoleOutput; .

https://reviewboard.mozilla.org/r/150526/#review155682

::: devtools/client/webconsole/new-console-output/selectors/messages.js:33
(Diff revision 2)
>  function getCurrentGroup(state) {
>    return state.messages.currentGroup;
>  }
>  
>  function getVisibleMessages(state) {
> -  return state.messages.visibleMessages.map(id => getMessage(state, id));
> +  return state.messages.visibleMessages;

Would this give us a similar perf boost:

```
let allMessages = getAllMessagesById(state);
return state.messages.visibleMessages.map(id => allMessages.get(id));
```

IOW, is it the mulitple calls to getAllMessagesById that is slow, the multiple calls to .get(id), or both?
(Assignee)

Comment 9

6 months ago
The bottleneck here is really the `Immutable.OrderedMap.get` call.
So if I understand your proposal, we would end up calling it the same number of time: for each visible message in the store on each render, which in our stream and prune test case would be 4000 * 100. When with the patch we only call it once per message addition/update (100 times for the stream and prune test case).
(Assignee)

Comment 10

6 months ago
if you look at https://perf-html.io/public/da1ce767f76d6b2a55dd2f2d207b0108fcb51d76/calltree/?implementation=js&range=64.3764_92.8717&search=getMessage&thread=0 , getMessages takes almost 1500ms, in which Immutable.get is 1000ms, getAllMessagesById 200ms, and getMessage itself 250ms

Comment 11

6 months ago
mozreview-review
Comment on attachment 8879187 [details]
Bug 1373568 - Retrieve message data in MessageContainer instead of in ConsoleOutput; .

https://reviewboard.mozilla.org/r/150526/#review155688
Attachment #8879187 - Flags: review+

Comment 12

6 months ago
We're sorry, Autoland could not rebase your commits for you automatically. Please manually rebase your commits and try again.

hg error in cmd: hg rebase -s 0ea63131f099 -d 21c963bcc2ce: rebasing 402939:0ea63131f099 "Bug 1373568 - Retrieve message data in MessageContainer instead of in ConsoleOutput; r=bgrins." (tip)
merging devtools/client/webconsole/new-console-output/components/message-container.js
warning: conflicts while merging devtools/client/webconsole/new-console-output/components/message-container.js! (edit, then use 'hg resolve --mark')
unresolved conflicts (see hg resolve, then hg rebase --continue)
Comment hidden (mozreview-request)

Comment 14

6 months ago
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/74d375a6430c
Retrieve message data in MessageContainer instead of in ConsoleOutput; r=bgrins.

Comment 15

6 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/74d375a6430c
Status: ASSIGNED → RESOLVED
Last Resolved: 6 months ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 56
You need to log in before you can comment on or make changes to this bug.