1239750 - Add DAMP measurement for console.log performance

Status: RESOLVED FIXED

(DevTools :: Framework, defect)

Description

[Brian Grinstead [:bgrins]]

We should track how fast console.log messages come through in DAMP.  Two main things I can think of to measure here:

1) Run `for (var i = 0; i < 100; i++) { console.log(i); }` and then wait for all 100 messages to appear
2) Send 100 messages, once every Nms and then see how long it takes each to come through and take an average

These hit two very different performance paths.  The first is slow because of building / pruning / appending messages and the second is slow because of layout thrashing / keeping output scrolled to bottom.

I'm not sure which would be better to add (or if we should track both).  I have a work in progress for the first one.

Comment 1

[Brian Grinstead [:bgrins]]

Attachment: damp-console-WIP.patch

Work in progress.. handles case 1 but with only 10 messages because that's already slow enough :(.  Need to check and see if it's slow partly because of the RDP overhead of doing jsterm.execute by using a frame script instead to trigger the logs

Comment 2

[Brian Grinstead [:bgrins]]

Attachment: MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen

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

Comment 3

[Brian Grinstead [:bgrins]]

Comment on attachment 8708134 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen

Joel, this patch adds a new `console.bulklog` measurement to track the time between calling console.log 10 times and the messages appearing on the screen.  Spoiler alert: it's pretty slow (although still quicker than a lot of the existing measurements).

I can't remember if you have to do any special magic to make a try push with a new measurement work.  But here's a normal one: https://treeherder.mozilla.org/#/jobs?repo=try&revision=83b56e102a18.

Comment 4

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Comment on attachment 8708134 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen

https://reviewboard.mozilla.org/r/30985/#review27807

LGTM, but the `if (name)` stuff seriously confuses me. Would like answers for that before stamping an r+

::: testing/talos/talos/tests/devtools/addon/content/damp.js:50
(Diff revision 1)
> +        if (name) {

Why would we ever *not* have a name? Wouldn't that be a bug? If not, then this comment is a bit of a tautology, since it is super clear we won't record the results if there is not a name, however it gives zero insight into *why* we don't want to record results in this case or what scenario we do not have a name. This is the situation I find myself in now.

::: testing/talos/talos/tests/devtools/addon/content/damp.js:120
(Diff revision 1)
> +    let TOTAL_MESSAGES = 10;

Is 10 really that slow? I'd have hoped/expected a slowdown would not be noticable until ~100 at least :(

::: testing/talos/talos/tests/devtools/addon/content/damp.js:132
(Diff revision 1)
> +            // Wait for the console to redraw

Nice catch.

Comment 5

[Brian Grinstead [:bgrins]]

(In reply to Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8] from comment #4)
> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:50
> (Diff revision 1)
> > +        if (name) {
> 
> Why would we ever *not* have a name? Wouldn't that be a bug? If not, then
> this comment is a bit of a tautology, since it is super clear we won't
> record the results if there is not a name, however it gives zero insight
> into *why* we don't want to record results in this case or what scenario we
> do not have a name. This is the situation I find myself in now. 

In this patch I'm doing it on line 123.  The thing is that helper method is doing work for the original test cases (tool open / close /reloads) so they pass in a name and results get recorded.  For this case we don't want to log the open time, only the console.bulklog time.

I think the better thing to do would be to resolve the promise with that stopReloadTimestamp - startReloadTimestamp and then let the individual tool reload tests manually push onto this._results.

> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:120
> (Diff revision 1)
> > +    let TOTAL_MESSAGES = 10;
> 
> Is 10 really that slow? I'd have hoped/expected a slowdown would not be
> noticable until ~100 at least :(

Locally 10 takes around 100ms - not sure how much of that is frame script overhead.  One thing is that we only try to push messages to the screen every 20ms.  I did notice if I took `content` out of the log it is around 30% faster b/c it's not rendering the object grips.

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

https://reviewboard.mozilla.org/r/30985/#review27855

no red flags here.  As we are still using graph server, we will need to add test names to the damp test, if you can give me a list of the new test names, they can be added similar to what was done in bug 1153886.  I don't mind doing it or reviewing it.

::: testing/talos/talos/tests/devtools/addon/content/damp.js:137
(Diff revision 1)
> +      webconsole.hud.ui.on("new-messages", receiveMessages);

any concerns with us not receiving messages and then we don't turn this off?  It will only affect damp as we reload the test for additional cycles.

Comment 7

[Brian Grinstead [:bgrins]]

(In reply to Joel Maher (:jmaher) from comment #6)
> ::: testing/talos/talos/tests/devtools/addon/content/damp.js:137
> (Diff revision 1)
> > +      webconsole.hud.ui.on("new-messages", receiveMessages);
> 
> any concerns with us not receiving messages and then we don't turn this off?
> It will only affect damp as we reload the test for additional cycles.

I don't expect that would happen (we have lots of mochitests to ensure this behavior) but if it did then the promise would never resolve and _consoleLogTest would hang indefinitely.  I'm assuming talos tests have a max timeout?  What is the timeout.. and is it for an entire DAMP run or per-cycle?

Comment 8

[Joel Maher ( :jmaher ) (UTC -8)]

Talos has internal timeouts for no output and depending on the test different timeouts per cycle.  I would say 5 minutes with no activity in stdout/stderr will result in a forced timeout from the talos harness.  Every time we cycle a page, we generate stdout data.

Comment 9

[Brian Grinstead [:bgrins]]

Comment on attachment 8708134 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen

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

Comment 10

[Brian Grinstead [:bgrins]]

Attachment: MozReview Request: Bug 1239750 - Add DAMP measurement for rAF performance during streaming console.log messages;r=fitzgen

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

Comment 11

[Brian Grinstead [:bgrins]]

Attachment: MozReview Request: Bug 1239750 - Add DAMP measurement for rAF performance during streaming console.log messages;r=fitzgen

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

Comment 12

[Brian Grinstead [:bgrins]]

Thanks for the review Nick!  I've cleaned up the weirdness with `name` and openToolbox, closeToolbox, reloadPage in the first part.  Then moved the original test into part 2.  And finally added part 3, which records rAF performance based on the test case in Bug 1237368.

Comment 13

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Comment on attachment 8708134 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen

https://reviewboard.mozilla.org/r/30985/#review27883

Comment 14

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Comment on attachment 8708488 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for rAF performance during streaming console.log messages;r=fitzgen

https://reviewboard.mozilla.org/r/31065/#review27887

Comment 15

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Comment on attachment 8708489 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for rAF performance during streaming console.log messages;r=fitzgen

https://reviewboard.mozilla.org/r/31067/#review27889

Comment 16

[Brian Grinstead [:bgrins]]

(In reply to Joel Maher (:jmaher) from comment #6)
> https://reviewboard.mozilla.org/r/30985/#review27855
> 
> no red flags here.  As we are still using graph server, we will need to add
> test names to the damp test, if you can give me a list of the new test
> names, they can be added similar to what was done in bug 1153886.  I don't
> mind doing it or reviewing it.

OK, the code is ready to go.  When you get a chance, can you please add two new definitions to the graph server - "console.bulklog" and "console.streamlog"?

Comment 17

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: add media pages to graph server

old fashioned review style here- please confirm these pages are correct and I will coordinate to get them deployed to the graph server.

Comment 18

[Brian Grinstead [:bgrins]]

Comment on attachment 8709906 [details] [diff] [review]
add media pages to graph server

Review of attachment 8709906 [details] [diff] [review]:
-----------------------------------------------------------------

Perfect, thanks!

Comment 19

[Brian Grinstead [:bgrins]]

Joel, how long do you think it will take to get these deployed to graph server?  I'd love to get the DAMP changes landed before I push Bug 1237368 so I can get a sense for how much that improves these measurements.

Comment 20

[Joel Maher ( :jmaher ) (UTC -8)]

landed the damp change in the repo:
https://hg.mozilla.org/graphs/rev/4ba602b14dc8

filed bug 1241242 to deploy- let me ping and see if that can be done soon.

Comment 21

[Brian Grinstead [:bgrins]]

Comment on attachment 8708134 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen

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

Comment 22

[Brian Grinstead [:bgrins]]

Comment on attachment 8708488 [details]
MozReview Request: Bug 1239750 - Add DAMP measurement for rAF performance during streaming console.log messages;r=fitzgen

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

Comment 23

[Brian Grinstead [:bgrins]]

Updated try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=921188357c4c

Comment 24

[Brian Grinstead [:bgrins]]

Another try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=cf84f4cf9b50

Comment 25

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/57cd47c177f6
https://hg.mozilla.org/integration/fx-team/rev/24afa30a759c
https://hg.mozilla.org/integration/fx-team/rev/63e4b33812a9

Comment 26

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

https://hg.mozilla.org/mozilla-central/rev/57cd47c177f6
https://hg.mozilla.org/mozilla-central/rev/24afa30a759c
https://hg.mozilla.org/mozilla-central/rev/63e4b33812a9

Comment 27

[Mayur Patil]

[bugday-20160323]

Status: RESOLVED,FIXED -> UNVERIFIED

Comments:
STR: Not clear.
Developer specific testing

Component: 
Name			Firefox
Version			46.0b9
Build ID		20160322075646
Update Channel          beta
User Agent		Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
OS			Windows 7 SP1 x86_64

Expected Results: 
Developer specific testing

Actual Results: 
As expected