1187451 - TPS score doesn't always measure painting due to MozAfterPaint sequence mismatch

Status: RESOLVED FIXED

(Testing :: Talos, defect)

Comment 1

[Benoit Girard (:BenWa)]

Best way to see this in action is to run TPS with profiling enabled:
http://people.mozilla.org/~bgirard/cleopatra/#report=988232cbe655a2074677902813f62faaf7cb0d7d&filter=[{"type"%3A"RangeSampleFilter","start"%3A44429,"end"%3A46908},{"type"%3A"RangeSampleFilter","start"%3A46490,"end"%3A46505}]

at ~t=46500ms we're loading reddit.html but we never paint. We also get no VSync this interval.

Comment 2

[Benoit Girard (:BenWa)]

http://people.mozilla.org/~bgirard/cleopatra/#report=3b414ebdc1e5791755ffc5f450440bf4cfb49d44

Here it's chinaz and globo. I'm not entirely sure if it's caused by Vsync because 'chinaz.com' had a Vsync marker while it was loading.

Comment 3

[Benoit Girard (:BenWa)]

Had a look at this with mattwoodrow. The problem is that we listen to MozAfterPaint but we have no guarantee that the MozAfterPaint is for the current tab. In some cases we listen to a MozAfterPaint which was for a previous paint that is still pending in the event loop.

What we're going to do is switch to about:blank, let the paint settle down then we're going to use MozAfterPaint. 

This will have the side benefit of having a more fair tab switch time. In theory a test can have a noisy disadvantage cause by tearing down it's previous tab' layer tree which may be more or less costly then others. This will remove a tiny source of noise at the same time.

http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/paint_listener.js#55

Comment 4

[Benoit Girard (:BenWa)]

I should say an alternative fix would be to have some sequence numbers and/or a more useful event handler. It wouldn't solve the noise problem of tearing down the previous page and would be more difficult to implement (require platform changes) but would be more versatile. Right now I'm not planning on doing this.

Comment 5

[Benoit Girard (:BenWa)]

Attachment: WIP

This should be better but it still doesn't work. Maybe I'm still getting a bad MozAfterPaint event.

Comment 6

[Benoit Girard (:BenWa)]

I've replaced MozAfterPaint to use rAF and the results look a lot better now:
http://people.mozilla.org/~bgirard/cleopatra/#report=2e583c8b3015dab85d76915a49ee695545c6b153

Comment 7

[Benoit Girard (:BenWa)]

Attachment: patch

Please forward the review if you're not the best person to look at this.

Comment 8

[Benoit Girard (:BenWa)]

Attachment: patch

Comment 9

[Benoit Girard (:BenWa)]

url:        https://hg.mozilla.org/build/talos/rev/da09edf6d9841937f86123423c346042beb13ad3
changeset:  da09edf6d9841937f86123423c346042beb13ad3
user:       Benoit Girard <[e-mail]>
date:       Mon Jul 27 15:12:32 2015 -0400
description:
Bug 1187451 - TPS: Use rAF and waitForAllPaintsFlush instead of MozAfterPaint. r=blassey

Comment 10

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

backed out talos change:
http://hg.mozilla.org/build/talos/rev/24ecc5140689

this is because tps didn't run on try and timed out- it appears to be this change:
http://hg.mozilla.org/build/talos/rev/da09edf6d984

but backing it out has a lot of merge conflicts so we backed all of them out.

Comment 11

[Benoit Girard (:BenWa)]

Attachment: patch v2

Comment 12

[Benoit Girard (:BenWa)]

the failing push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c9f79e1096c5

Comment 13

[Benoit Girard (:BenWa)]

What's the deal with all the missing logs? Can we get that fixed?

Comment 14

[Benoit Girard (:BenWa)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=51a2309b4ba8
https://treeherder.mozilla.org/perf.html#/comparechooser?newProject=try&newRevision=51a2309b4ba8

Comment 15

[Benoit Girard (:BenWa)]

Attachment: patch v3

I removed waitForAllPaintsFlushed because it's not clear that it was helping and it was causing complexity.

Comment 16

[Benoit Girard (:BenWa)]

url:        https://hg.mozilla.org/build/talos/rev/2d45216ff5eb9aa4a2f527d6dadb6aab083a0311
changeset:  2d45216ff5eb9aa4a2f527d6dadb6aab083a0311
user:       Benoit Girard <[e-mail]>
date:       Mon Jul 27 15:12:32 2015 -0400
description:
 Bug 1187451 - TPS: Use rAF instead of MozAfterPaint. r=blassey

Comment 17

[Benoit Girard (:BenWa)]

I was meaning to push to my local repo instead to do try runs. Just noticed the mistake. I already have re-triggers using this new repo running but I expect things to be better now:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=51a2309b4ba8

Comment 18

[Benoit Girard (:BenWa)]

Attachment: patch v4

I've tweaked how I handle the initial tab. It was getting too finicky to exclude it from the result set. This should be less finicky.

Comment 19

[Benoit Girard (:BenWa)]

Alright the latest run is green, look like v4 did the trick. I'll land the delta tomorrow since I pushed to the master talos repo by accident (pushed to default instead of try).

Comment 20

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

there is a raw log which includes the stdout/stderr from the process.  In this case we launched the browser and nothing happened.  Do let me know if there is something that should have been there.

Comment 21

[Benoit Girard (:BenWa)]

url:        https://hg.mozilla.org/build/talos/rev/c2dd2a3fe8f5d7eee2731e4f9e1682e43b806f16
changeset:  c2dd2a3fe8f5d7eee2731e4f9e1682e43b806f16
user:       Benoit Girard <[e-mail]>
date:       Fri Jul 31 14:05:13 2015 -0400
description:
Bug 1187451 - Backout patch v3 for bustage

url:        https://hg.mozilla.org/build/talos/rev/d44548b8feb996af0595c9c369b96b0ab939b8ae
changeset:  d44548b8feb996af0595c9c369b96b0ab939b8ae
user:       Benoit Girard <[e-mail]>
date:       Mon Jul 27 15:12:32 2015 -0400
description:
 Bug 1187451 - TPS: Use rAF instead of MozAfterPaint. r=blassey

Comment 22

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

this is deployed and we have some results of what has changed:
https://treeherder.allizom.org/perf.html#/compare?originalProject=mozilla-inbound&originalRevision=b2db9b75841a&newProject=mozilla-inbound&newRevision=768312f4d281&hideMinorChanges=1

I am starting to think that all OSX 10.10 results are rubbish given the fact that the majority of comparisons I see show significant changes.  As you can see there are a lot of random improvement/regressions there, in this case tps is the area of focus and you can see the change.  My understanding is this is expected and now we are measuring something a lot more realistic.

:BenWa, can you confirm that?

Comment 23

[Benoit Girard (:BenWa)]

If I'm reading this correctly the stddev for 10.10 went from 11% to 6% so things got better with this patch?

As far as I can tell what we were measuring before was not correct since we would score a page without painting it somewhat randomly.

From what I was seeing with profiling we are still off by quite a bit with this patch. I've already filed bug 1188635 to get things under control. Getting rid of the GC/CC will help a bit.

Comment 24

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

yes, the stddev went down.  I just wanted to know if I should ignore these TPS *regressions*.  It sounds like we have another round of it coming up soon.

Comment 25

[Benoit Girard (:BenWa)]

As far as I can tell these regressions are expected because we're more accurately measuring the thing that we want. In some cases we got away with randomly not measuring a subtest run properly which would explain why our previous test scores were lower and had a higher stddev.

Even if the numbers are worse, if we're more confident we're always measuring page paint and the stddev is going down I believe it's a sign that TPS is converging towards being a more useful test. Also a lower stddev means better signal to noise.

Comment 26

[Avi Halachmi (:avih)]

+1 to benwa.

It's expected because we now measure a different thing which is not necessarily comparable to the previous thing it measured. And the new thing is better, so it just resets our reference point.

Comment 27

[Benoit Girard (:BenWa)]

Patches have landed and it sounds like we're good with the numbers. Resolving.