Add DAMP measurement for console.log performance

RESOLVED FIXED in Firefox 46

Status

RESOLVED FIXED
3 years ago
2 months ago

People

(Reporter: bgrins, Assigned: bgrins)

Tracking

unspecified
Firefox 46
Dependency tree / graph

Firefox Tracking Flags

(firefox46 fixed)

Details

MozReview Requests

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

Attachments

(4 attachments, 1 obsolete attachment)

(Assignee)

Description

3 years ago
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.
(Assignee)

Comment 1

3 years ago
Created attachment 8707989 [details] [diff] [review]
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
(Assignee)

Updated

3 years ago
Depends on: 1239422
(Assignee)

Updated

3 years ago
Assignee: nobody → bgrinstead
Status: NEW → ASSIGNED
(Assignee)

Comment 2

3 years ago
Created attachment 8708134 [details]
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/
Attachment #8708134 - Flags: review?(nfitzgerald)
(Assignee)

Comment 3

3 years ago
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.
Attachment #8708134 - Flags: feedback?(jmaher)
Attachment #8708134 - Flags: review?(nfitzgerald)
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.
(Assignee)

Comment 5

3 years ago
(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.
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.
Attachment #8708134 - Flags: feedback?(jmaher)
(Assignee)

Comment 7

3 years ago
(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?
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.
(Assignee)

Comment 9

3 years ago
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/
Attachment #8708134 - Attachment description: MozReview Request: Bug 1239750 - Add DAMP measurement for console.log performance;r=fitzgen → MozReview Request: Bug 1239750 - Refactor DAMP openToolbox, closeToolbox, and reloadPage to mutate results state;r=fitzgen
Attachment #8708134 - Flags: review?(nfitzgerald)
(Assignee)

Comment 10

3 years ago
Created attachment 8708488 [details]
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/
Attachment #8708488 - Flags: review?(nfitzgerald)
(Assignee)

Comment 11

3 years ago
Created attachment 8708489 [details]
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/
Attachment #8708489 - Flags: review?(nfitzgerald)
(Assignee)

Comment 12

3 years ago
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.
See Also: → bug 1237368
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
Attachment #8708134 - Flags: review?(nfitzgerald) → review+
Attachment #8708488 - Flags: review?(nfitzgerald) → review+
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 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
Attachment #8708489 - Flags: review?(nfitzgerald) → review+
(Assignee)

Comment 16

3 years ago
(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"?
Flags: needinfo?(jmaher)
Created attachment 8709906 [details] [diff] [review]
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.
Flags: needinfo?(jmaher)
Attachment #8709906 - Flags: review?(bgrinstead)
(Assignee)

Comment 18

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

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

Perfect, thanks!
Attachment #8709906 - Flags: review?(bgrinstead) → review+
(Assignee)

Comment 19

3 years ago
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.
Flags: needinfo?(jmaher)
Depends on: 1241242
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.
Flags: needinfo?(jmaher)
(Assignee)

Comment 21

3 years ago
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/
Attachment #8708134 - Attachment description: MozReview Request: Bug 1239750 - Refactor DAMP openToolbox, closeToolbox, and reloadPage to mutate results state;r=fitzgen → MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen
(Assignee)

Comment 22

3 years ago
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/
Attachment #8708488 - Attachment description: MozReview Request: Bug 1239750 - Add DAMP measurement for bulk console.log performance;r=fitzgen → MozReview Request: Bug 1239750 - Add DAMP measurement for rAF performance during streaming console.log messages;r=fitzgen
(Assignee)

Updated

3 years ago
Attachment #8708489 - Attachment is obsolete: true

Comment 26

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/57cd47c177f6
https://hg.mozilla.org/mozilla-central/rev/24afa30a759c
https://hg.mozilla.org/mozilla-central/rev/63e4b33812a9
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
status-firefox46: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 46
(Assignee)

Updated

3 years ago
Blocks: 1244348

Comment 27

2 years ago
[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

Updated

2 months ago
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.