1359065 - Message repeat shouldn't check timestamp

Status: VERIFIED FIXED

(DevTools :: Console, defect, P1)

Description

[Nicolas Chevobbe [:nchevobbe]]

STR : 

1. Open the console
2. In jsterm, add the following event listener which logs "mouse" on each mousemove :
document.addEventListener("mousemove", e => console.log("mouse"))
3. Move your cursor across the screen

ER : One "mouse" message is logged, and then the repeat icon number grows (like in the old console)

AR : One "mouse" message is logged for each event.

----

This is happening because in order to check if a message is the same as the previous one, we stringify the whole message (see http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/utils/messages.js#221-224). The problem with this approach is that messages have a `timestamp` property, which is likely to be different for each messages, even if they look alike.

We might revisit how we generate this repeatId, first because it's incorrect, and second because it is not really efficient (the transform from an Immutable.Record to a plain object is costly)

Comment 1

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Attachment: Bug 1359065 - Remove timeStamp before generating message ID;

Review commit: https://reviewboard.mozilla.org/r/134280/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/134280/

Comment 2

[Jan Honza Odvarko [:Honza] (always need-info? me)]

I have been testing how much time is spent in getRepeatId() method using peformance.now() and summing up all values for 1K messages. I am getting 30-80 ms time spent in that method for 1K messages (depending on log size).

So, I also agree that we can just keep that methods as is (at least for now).
Patch attached for review.

Honza

Comment 3

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8862354 [details]
Bug 1359065 - Remove timeStamp before generating message ID;

https://reviewboard.mozilla.org/r/134280/#review137302

Looks enough for now.
Could you edit the existing mocha tests to make sure this is fixed : 
- http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/test/utils/getRepeatId.test.js
- http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/test/store/messages.test.js#42

We should set a different timestamp on the second messages of both tests, and they should have the same repeatId

Comment 4

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Attachment: Bug 1359065 - Update tests;

Review commit: https://reviewboard.mozilla.org/r/134600/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/134600/

Comment 5

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8862354 [details]
Bug 1359065 - Remove timeStamp before generating message ID;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/134280/diff/1-2/

Comment 6

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8862733 [details]
Bug 1359065 - Update tests;

https://reviewboard.mozilla.org/r/134600/#review137588

Looks good !
I think we should run the mochitest to update http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/test/fixtures/stubs/cssMessage.js , http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/test/fixtures/stubs/evaluationResult.js and http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/test/fixtures/stubs/pageError.js since they have a repeatId which contains the timeStamp too.

::: devtools/client/webconsole/new-console-output/test/utils/getRepeatId.test.js:12
(Diff revision 1)
> -    const message1 = stubPreparedMessages.get("console.log('foobar', 'test')");
> -    const message2 = message1.set("repeat", 3);
> +    var message1 = stubPreparedMessages.get("console.log('foobar', 'test')");
> +    var message2 = message1.set("repeat", 3);
> +
> +    // Repeat ID must be the same even if the timestamp is different.
> +    message1 = message1.set("timeStamp", 1,);
> +    message2 = message2.set("timeStamp", 2,);

not: I don't think we need to set the "repeat" property here, and maybe we can improve things a bit like :

```
const baseMessage = stubPreparedMessages.get("console.log('foobar', 'test')");

// Repeat ID must be the same even if the timestamp is different.
const message1 = baseMessage.set("timeStamp", 1);
const message2 = baseMessage.set("timeStamp", 2);
```

Comment 7

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8862733 [details]
Bug 1359065 - Update tests;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/134600/diff/1-2/

Comment 8

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8862733 [details]
Bug 1359065 - Update tests;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/134600/diff/2-3/

Comment 9

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Nicolas, do you see any perf improvement if the code looks like as follows?

// Do not use 'delete'
function getRepeatId(message) {
  message = message.toJS();
  message.repeat = null;
  message.timeStamp = null;
  return JSON.stringify(message);
}


Honza

Comment 10

[Nicolas Chevobbe [:nchevobbe]]

(In reply to Jan Honza Odvarko [:Honza] from comment #9)
> Nicolas, do you see any perf improvement if the code looks like as follows?
> 
> // Do not use 'delete'
> function getRepeatId(message) {
>   message = message.toJS();
>   message.repeat = null;
>   message.timeStamp = null;
>   return JSON.stringify(message);
> }
> 
> 
> Honza

Definitely (saves ~30ms)

Comment 11

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8862354 [details]
Bug 1359065 - Remove timeStamp before generating message ID;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/134280/diff/2-3/

Comment 12

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8862733 [details]
Bug 1359065 - Update tests;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/134600/diff/3-4/

Comment 13

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #10)
> Definitely (saves ~30ms)
Great, patch updated.
Honza

Comment 14

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Attachment: Bug 1359065 - Update stubs;

Review commit: https://reviewboard.mozilla.org/r/135720/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/135720/

Comment 15

[Nicolas Chevobbe [:nchevobbe]]

Comment on attachment 8863994 [details]
Bug 1359065 - Update stubs;

https://reviewboard.mozilla.org/r/135720/#review138744

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e9e7ef4f6e99
Remove timeStamp before generating message ID; r=nchevobbe
https://hg.mozilla.org/integration/autoland/rev/66d3d14f9d9d
Update tests; r=nchevobbe
https://hg.mozilla.org/integration/autoland/rev/a63f99f00b49
Update stubs; r=nchevobbe

Comment 17

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/e9e7ef4f6e99
https://hg.mozilla.org/mozilla-central/rev/66d3d14f9d9d
https://hg.mozilla.org/mozilla-central/rev/a63f99f00b49

Comment 18

[Iulia Cristescu, QA [:JuliaC] (away, please needinfo? [e-mail])]

Managed to reproduce the initial issue on 55.0a1 (2017-05-02), using Windows 10 x64, Ubuntu 16.04 x64 and Mac OS X 10.11.6. I can confirm that 55.0a1 (2017-05-17) build is verified fixed on the above platforms.