1432268 - tp6 google is not actually measuring hero element

Status: RESOLVED FIXED

(Testing :: Talos, defect)

Description

[Robert Wood [:rwood]]

Hero element support for talos tp6 (google page only) landed in Bug 1418368. However I just noticed that it's not actually turned on, because:

In test.py for google tp6 [1] 'tphero = True', as required, however in the QuantumPageloadTest base class [2], 'fnbpaint = True' also.

And in the pageloader code [3] it looks for fnbpaint first - and if that's set it uses that and ignores the others (since currently pageloader only supports one type of measurement per pageload). So currently tp6 google is still measuring based on fnbpaint and not the hero element.

Solution is to add 'fnbpaint = False' in test.py for tp6 google.

[1] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/test.py#884

[2] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/test.py#265

[3] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#239

Comment 1

[Robert Wood [:rwood]]

Attachment: Bug 1432268 - Turn on hero element measurement for tp6 google;

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

Comment 2

[Robert Wood [:rwood]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=7289aa584855d3317efc45e11bce39fb05ab4d21

Comment 3

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

Comment on attachment 8944508 [details]
Bug 1432268 - Turn on hero element measurement for tp6 google;

https://reviewboard.mozilla.org/r/214690/#review220330

so simple!

Comment 4

[Robert Wood [:rwood]]

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #3)
...
> so simple!

heh aren't those the ones that always don't work? ;) tp6 google hero is giving negative numbers:

11:46:06     INFO -  PID 17032 | |0;/#hl=en&q=barack+obama;-1516650330774.36;-1516650332666.74;-1516650334375.5;-1516650335777.16;-1516650337194.1;-1516650338510.84;-1516650339994.74;-1516650341336.6;-1516650342741.86;-1516650344042.32;-1516650345308.36;-1516650346761.38;-1516650348083.58;-1516650349571.54;-1516650350899.96;-1516650352404.1;-1516650353778.4;-1516650355266.16;-1516650356620.1;-1516650358038.18;-1516650359458.36;-1516650360758.6;-1516650362158.66;-1516650363482.84;-1516650364864.86

So the subtest results aren't being dumped to perfherder (and tp6_google doesn't show in the job details).

:tarek, can you take a look please? We must have missed this earlier by not setting 'fnbpaint=False'.

Comment 5

[Robert Wood [:rwood]]

Hmm possibly somewhere in this code block...

https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#665

Comment 6

[Robert Wood [:rwood]]

Getting closer, lg_hero.js is recording the pageloader load event, it sends back the PageLoader:LoadEvent, which is received successfully in plLoadHanlderMessage [1]. When I dump out the message.json.time there, there is a positive value (i.e. 989). This value (paint_time) is then being passed into _loadHandler(paint_time)... it must be our start time value...

[1] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#647

Comment 7

[Robert Wood [:rwood]]

Found the problem. We're using two different time formats.

Our start_time is valid, it's a Date.now() [1]

However lg_hero.js sends us a 'content.window.performance.now()' [2]

And for our duration is end_time (performance.now) minus start time (Date.now) [3]. Which for example is 797.46 - 1516656901611, so the duration is -1516656900813.54.

[1] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#627

[2] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#627

[3] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#627

:tarek, can we change lg_hero.js to return Date.now() in the Pageloader:LoadEvent, instead of performance.now(), is that valid? Changing our talos start_time to a performance.now() doesn't seem like a good solution as that would require a refactor for all the tests.

Comment 8

[Robert Wood [:rwood]]

Sorry, correcting the links for Comment 7

[1] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#331

[2] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/lh_hero.js#13

[3] https://searchfox.org/mozilla-central/rev/b7e3ec2468d42fa59d86c03ec7afeb209813f1d4/testing/talos/talos/pageloader/chrome/pageloader.js#627

Comment 9

[Robert Wood [:rwood]]

Having lh_hero.js use Date.now() instead of performance.now() fixes the issue, results from a local run with 2 pagecycles:

{
  "framework": {
    "name": "talos"
  },
  "suites": [
    {
      "alertThreshold": 2.0,
      "extraOptions": [
        "e10s"
      ],
      "lowerIsBetter": true,
      "name": "tp6_google",
      "subtests": [
        {
          "alertThreshold": 2.0,
          "lowerIsBetter": true,
          "name": "",
          "replicates": [
            1805.0,
            1135.0
          ],
          "unit": "ms",
          "value": 1470.0
        }
      ]
    }
  ]
}

Comment 10

[Robert Wood [:rwood]]

Attachment: Bug 1432268 - Fix tp6 hero element time measurement;

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

Comment 11

[Robert Wood [:rwood]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=008dd0215a1508630b186980e02d60de79421995

Comment 12

[Tarek Ziadé (:tarek)]

oh really cool, thanks for the fix!

Comment 13

[Tarek Ziadé (:tarek)]

Comment on attachment 8944546 [details]
Bug 1432268 - Fix tp6 hero element time measurement;

https://reviewboard.mozilla.org/r/214714/#review220434

Thanks!

Comment 14

[Robert Wood [:rwood]]

Thanks Tarek. So looking at the try run, tp6 google with hero element is more than 2x the time than tp6 google without hero (and just using first non-blank paint). 

Some run examples (OSX):

tp6_google hero element: 916, 955, 904, 922, 1015
tpg_google first non-blank paint: 417, 428.5, 441, 477, 412

Just want to confirm, this is expected correct? Since hero element waits for that specific element to load (which is an image) however fnbpaint we hit alot earlier.

I believe this is as expected. Tarek, please confirm?

Should we go ahead and land this and accept this new baseline?

Comment 15

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

I am fine landing it- we are changing the test so new numbers are not an issue.

Comment 16

[Tarek Ziadé (:tarek)]

+1 thanks

Comment 17

[Robert Wood [:rwood]]

Thanks guys! Landing

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6bd4c1224daa
Turn on hero element measurement for tp6 google; r=jmaher
https://hg.mozilla.org/integration/autoland/rev/37fb46976e18
Fix tp6 hero element time measurement; r=tarek

Comment 19

[Robert Wood [:rwood]]

Hey Ionut, just FYI this is going to cause a large perf regression in tp6_google - it is expected and we are going to accept the new baseline.

Comment 20

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/6bd4c1224daa
https://hg.mozilla.org/mozilla-central/rev/37fb46976e18

Comment 21

[Ionuț Goldan [:igoldan]]

(In reply to Robert Wood [:rwood] from comment #19)
> Hey Ionut, just FYI this is going to cause a large perf regression in
> tp6_google - it is expected and we are going to accept the new baseline.

Thanks for the notice, Robert! Here are the results to that:

== Change summary for alert #11264 (as of Wed, 24 Jan 2018 12:27:49 GMT) ==

Regressions:

124%  tp6_google osx-10-10 opt e10s     439.85 -> 986.29
117%  tp6_google_heavy osx-10-10 opt e10s434.83 -> 942.42
116%  tp6_google osx-10-10 opt 1_thread e10s448.77 -> 968.31
101%  tp6_google windows10-64 opt e10s  405.08 -> 815.00
 96%  tp6_google linux64 opt e10s       465.81 -> 913.50
 95%  tp6_google windows7-32 opt e10s   428.38 -> 834.83

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