Talos pageloader changes to support 'time to first non-blank paint' measurement for tp6

RESOLVED FIXED in Firefox 56

Status

RESOLVED FIXED
a year ago
a year ago

People

(Reporter: rwood, Assigned: rwood)

Tracking

Version 3
mozilla56
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox56 fixed)

Details

(Whiteboard: [PI:July])

Attachments

(1 attachment)

(Assignee)

Description

a year ago
For the new talos quantum-pageload test, have the test use the 'time to first non-blank paint' event/perf marker.
(Assignee)

Updated

a year ago
Summary: Have quantum-pageload talos test measure 'time to first non-blank paint' → Talos pageloader changes to support 'time to first non-blank paint' measurement
Depends on: 1210906
(Assignee)

Updated

a year ago
Depends on: 1377251
(Assignee)

Updated

a year ago
Assignee: nobody → rwood
Status: NEW → ASSIGNED
Can we use timeToNonBlankPaint here instead of the MozAfterPaint?
Flags: needinfo?(rwood)
(Assignee)

Comment 6

a year ago
(In reply to Zibi Braniecki [:gandalf][:zibi] from comment #5)
> Can we use timeToNonBlankPaint here instead of the MozAfterPaint?

Yes that is the goal. Right now I'm just trying to see if I can actually retrieve the value, and apparently it is almost guaranteed a timeToNonBlankPaint value will exist by the time the MozAfterPaint event is received.
Flags: needinfo?(rwood)
See Also: → bug 1381988
In bug 1377251 comment 24, bsmedberg suggests listening for the 'onload' event and then reading the timeToNonBlankPaint property, which should (!) have been set by onload time.
(Assignee)

Updated

a year ago
Summary: Talos pageloader changes to support 'time to first non-blank paint' measurement → Talos pageloader changes to support 'time to first non-blank paint' measurement for tp6
Comment hidden (mozreview-request)

Comment 9

a year ago
mozreview-review
Comment on attachment 8888468 [details]
Bug 1363845 - Talos pageloader changes to support 'time to first non-blank paint' measurement for tp6;

https://reviewboard.mozilla.org/r/159414/#review164772

pretty close- a few bits of cleanup and the big question- does this work on try server?

::: testing/talos/talos/pageloader/chrome/pageloader.js:271
(Diff revision 1)
> -        if (gUseE10S) {
> -          let contentScript = "data:,function _contentLoadHandler(e) { " +
> +        let contentScript = "data:,function _contentLoadHandler(e) { " +
> -            "  if (e.originalTarget.defaultView == content) { " +
> +          "  if (e.originalTarget.defaultView == content) { " +
> -            "    content.wrappedJSObject.tpRecordTime = function(t, s, n) { sendAsyncMessage('PageLoader:RecordTime', { time: t, startTime: s, testName: n }); }; ";
> +          "    content.wrappedJSObject.tpRecordTime = function(t, s, n) { sendAsyncMessage('PageLoader:RecordTime', { time: t, startTime: s, testName: n }); }; ";
> -          if (useMozAfterPaint) {
> +        if (useFNBPaint) {
> +          dumpLine("Using fnbpaint");

this dumpline isn't useful for production

::: testing/talos/talos/pageloader/chrome/pageloader.js:273
(Diff revision 1)
> -            "  if (e.originalTarget.defaultView == content) { " +
> +          "  if (e.originalTarget.defaultView == content) { " +
> -            "    content.wrappedJSObject.tpRecordTime = function(t, s, n) { sendAsyncMessage('PageLoader:RecordTime', { time: t, startTime: s, testName: n }); }; ";
> +          "    content.wrappedJSObject.tpRecordTime = function(t, s, n) { sendAsyncMessage('PageLoader:RecordTime', { time: t, startTime: s, testName: n }); }; ";
> -          if (useMozAfterPaint) {
> +        if (useFNBPaint) {
> +          dumpLine("Using fnbpaint");
> +          contentScript += "" +
> +          "var retryCounter = 0; " +

can you make this: gRetryCounter?

::: testing/talos/talos/pageloader/chrome/pageloader.js:280
(Diff revision 1)
> +          "  x = content.window.performance.timing.timeToNonBlankPaint; " +
> +          "  if (typeof x == 'undefined') { " +
> +          "    sendAsyncMessage('PageLoader:FNBPaintError', {}); " +
> +          "  } " +
> +          "  if (x > 0) { " +
> +          "    dump('fnbpaint value is: ' + x + '\\n'); " +

the dump statements in here are not useful for production

::: testing/talos/talos/pageloader/chrome/pageloader.js:688
(Diff revision 1)
> +    // NOTE: window.performance.timing.timeToNonBlankPaint is currently a duration
> +    // value (ms) but may be changed to a timestamp value; see Bug 1377251
> +    var time = fnbpaint;
> +  } else {
> -  var end_time = Date.now();
> +    var end_time = Date.now();
> -  var time = (end_time - start_time);
> +    var time = (end_time - start_time);

if we are expecting fnbpaint and we don't get it, will we end up using the old fashioned time instead?

::: testing/talos/talos/pageloader/chrome/pageloader.js:829
(Diff revision 1)
>  
> -    if (gUseE10S) {
> -      let mm = content.selectedBrowser.messageManager;
> +    let mm = content.selectedBrowser.messageManager;
> -      mm.removeMessageListener("PageLoader:LoadEvent", ContentListener);
> +    mm.removeMessageListener("PageLoader:LoadEvent", ContentListener);
> -      mm.removeMessageListener("PageLoader:RecordTime", ContentListener);
> +    mm.removeMessageListener("PageLoader:RecordTime", ContentListener);
> +    mm.removeMessageListener("PageLoader:FNBPaintError", ContentListener);

mozafterpaint is on content, but fnbpaint is on mm; is that intentional?

should we also put fnbpaint behind if(useFNBPaint) ?
Attachment #8888468 - Flags: review?(jmaher) → review-
(Assignee)

Comment 10

a year ago
mozreview-review-reply
Comment on attachment 8888468 [details]
Bug 1363845 - Talos pageloader changes to support 'time to first non-blank paint' measurement for tp6;

https://reviewboard.mozilla.org/r/159414/#review164772

> the dump statements in here are not useful for production

I need this for now to run on try, since quantum-pageload only runs on windows and I am developing on osx. I am testing locally but with tsvg_static. Will def remove this before landing though!

> if we are expecting fnbpaint and we don't get it, will we end up using the old fashioned time instead?

Nope, if we are expecting fnbpaint and don't get it, pageloader (and bubbling up to talos) will error out before this point.

> mozafterpaint is on content, but fnbpaint is on mm; is that intentional?
> 
> should we also put fnbpaint behind if(useFNBPaint) ?

It's my lack of understanding of this, I thought that's how you had to send messages from content to chrome, via the mm. Not sure how to proceed here then.
(Assignee)

Comment 12

a year ago
A bunch of debug statements in pageloader, to help trace the code path with quantum-pageload:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9454e750645b97eb4023cfe51cad20652decdd15
(Assignee)

Comment 13

a year ago
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=9454e750645b97eb4023cfe51cad20652decdd15

Interesting, so this try run has fnbpaint enabled for tp6 as well as tsvg_static. The debug statements do show up on tsvg_static on OSX and show it capturing first non-blank paint successfully. However for some reason on the other platforms the debug statements aren't showing up so I can't verify it is capturing successfully there.

So next step, I'll put some temporary debug code in the pageloader content script, so that when fnbpaint is actually grabbed it will error out of talos, that way I can be certain fnbpaint is being captured successfully on the other platforms.
(Assignee)

Comment 15

a year ago
Hmm, so capturing fnbpaint in talos is only working on OSX but not the other platforms for some reason, even though the -fnbpaint flag is passed into talos on all.
(Assignee)

Comment 16

a year ago
Comment on attachment 8888468 [details]
Bug 1363845 - Talos pageloader changes to support 'time to first non-blank paint' measurement for tp6;

Big rebase, creating new attachment/review
Attachment #8888468 - Attachment is obsolete: true
(Assignee)

Comment 17

a year ago
Got it working after rebasing and signing pageloader add-on. Successfully grabbed time to fnbpaint in talos on all platforms. This try push is talos deliberately crashing out of tsvg_static and tp6 after grabbing the fnbpaint value.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1e56d06278258583d9c75143f2f50f6197656277&selectedJob=117113123

Note:  window.performance.timing.timeToNonBlankPaint was just changed from a duration value to a timestamp an hour ago, so I'll update accordingly:

https://bugzilla.mozilla.org/show_bug.cgi?id=1377251#c33
Comment hidden (mozreview-request)

Comment 19

a year ago
mozreview-review
Comment on attachment 8888468 [details]
Bug 1363845 - Talos pageloader changes to support 'time to first non-blank paint' measurement for tp6;

https://reviewboard.mozilla.org/r/159414/#review166280

this looks much nicer!
Attachment #8888468 - Flags: review?(jmaher) → review+
Comment hidden (mozreview-request)

Comment 22

a year ago
Pushed by rwood@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8d22078682e4
Talos pageloader changes to support 'time to first non-blank paint' measurement for tp6; r=jmaher
results are in:
== Change summary for alert #8268 (as of July 25 2017 19:22 UTC) ==

Improvements:

 73%  quantum_pageload_amazon summary windows7-32 opt e10s stylo     2,768.33 -> 736.17
 73%  quantum_pageload_amazon summary windows10-64 opt e10s stylo    2,441.42 -> 666.54
 69%  quantum_pageload_facebook summary windows7-32 opt e10s stylo   1,346.96 -> 411.50
 68%  quantum_pageload_facebook summary windows10-64 opt e10s stylo  1,305.12 -> 416.17
 67%  quantum_pageload_youtube summary windows7-32 opt e10s stylo    1,465.04 -> 478.08
 60%  quantum_pageload_youtube summary windows10-64 opt e10s stylo   1,389.48 -> 553.75
 53%  quantum_pageload_google summary windows7-32 opt e10s stylo     1,137.21 -> 528.88
 53%  quantum_pageload_google summary windows10-64 opt e10s stylo    1,142.17 -> 535.83

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=8268

:bsmedberg- are there any concerns with this change in values from the mozafterpaint->time to first non blank paint ?
Flags: needinfo?(benjamin)
Whiteboard: [PI:July]

Comment 24

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/8d22078682e4
Status: ASSIGNED → RESOLVED
Last Resolved: a year ago
status-firefox56: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56

Comment 25

a year ago
I don't know enough about mozafterpaint to say for certain, although 2,768.33 -> 736.17 looks like we're measuring pretty different things: mstange can you give this a sanity-check?

Are we sure that this is measuring first *nonblank* paint and not the first *blank* paint?
Flags: needinfo?(benjamin) → needinfo?(mstange)
(Assignee)

Comment 26

a year ago
Previously tp6 was just waiting for load then grabbing Date.now() and using that for the end_date, to calculate the duration (we weren't using mozafterpaint for tp6). Now at the time of load instead of just grabbing Date.now(), we're waiting for 'window.performance.timing.timeToNonBlankPaint' to have a value (there right away most times) and grabbing that to use for the 'end_date' value, which is significantly less than Date.now().

Comment 27

a year ago
Ah then this data makes perfect sense and is reasonable.
Flags: needinfo?(mstange)
so are we still sure this is measuring the first nonblank paint?  I imagine the overhead in getting the execution to pageloader and querying date.now() is accounting for a good portion of the time.  Just seeing 2000ms vs 600ms is a bit daunting.

:bsmedberg, does this match up with what we see in manual video analysis?
Flags: needinfo?(benjamin)

Comment 29

a year ago
This is in the range of the live-site video recording. Examples:
 google search is 24 frames ~= 400ms.
 amazon homepage is 41 frames ~= 680ms

Video recording with mitmproxy is not yet stable enough to compare.

What does "overhead in getting the execution to pageloader and querying date.now" mean?
Flags: needinfo?(benjamin)
by overhead, I am referring to the time it takes to switch context then call the date.now() api wherein the case of window.performance..., this is set by the browser and doesn't change, it might be a few milliseconds, or maybe a few hundred, I doubt it is too much.

Comment 31

a year ago
You're talking about recording the time the framework *starts* navigation? if you're using Date.now(), I'd strongly suggest switching to window.performance.now() for your start-navigation metric. It returns a monotonic DOMHighResTimeStamp which should be more comparable.
(Assignee)

Comment 32

a year ago
(In reply to Benjamin Smedberg [:bsmedberg] from comment #31)
> You're talking about recording the time the framework *starts* navigation?
> if you're using Date.now(), I'd strongly suggest switching to
> window.performance.now() for your start-navigation metric. It returns a
> monotonic DOMHighResTimeStamp which should be more comparable.

Just FYI, Bug 1380676 - Fix instances of using Date.now() under testing/talos
You need to log in before you can comment on or make changes to this bug.