661918 - Tp should wait for MozAfterPaint after onload

Status: RESOLVED FIXED

(Testing :: Talos, defect)

Description

[Joe Drew (not getting mail)]

Tp currently waits for onload to go to the next page. Unfortunately, this means that we don't reliably measure the time it takes to paint the page as part of Tp.

Instead of using onload, Tp should use MozAfterPaint, the same way that Ts_paint does.

Comment 1

[Shawn Wilsher :sdwilsh]

Should this be part of the tp5 roll out since we are already going to have numbers changing anyway?

Comment 2

[Dão Gottwald [:dao]]

To clarify, we still need to wait for the load event and should then wait for the following MozAfterPaint event, since we can paint before the page has finished loading, right?

Comment 3

[Timothy Nikkel (:tnikkel)]

Yes.

Comment 4

[cmtalbert]

We already made this change for the txul sets of tests. It shouldn't be too hard to add that step to a tp5 pageloads, but I would not want to block tp5 on having this.  I'd recommend that we land tp5 as soon as possible and then add the tp5-paint test afterward.

Comment 5

[alice nodelman [:alice] [:anode]]

I agree with ctalbert that this should not block the roll out of tp5.

jmaher - how hard do you think that this would be to integrate?

Comment 6

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

this shouldn't be too hard to modify pageloader, but a good deal of work to make tpx-paint and get that turned on.  My bigger concern is will we want to do this for all pageloader tests (tsvg, tdhtml, tsspider, tp4, tp5, etc...)?  If we do, do we want to keep the old tests around?

In bug 660124, there is talk of not running ts and txul anymore to save machine cycles (and that nobody really looks at these numbers).  What would be the halflife of the old pageloader tests?  

fwiw, it is a PITA to add another test to talos (https://elvis314.wordpress.com/2011/04/21/some-notes-about-adding-new-tests-to-talos/) and I would advocate for a clean switch where we just change pageloader, but not the test names!

Comment 7

[Dão Gottwald [:dao]]

I can't think of a reason not to make a complete switch.

Comment 8

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

Attachment: support waiting for mozafterpaint in pageloader (1.0)

this patch is a first run at getting pageloader to support MozAfterPaint events.  This works for regular and test_does_own_timing scenarios.  I haven't tested in remote (e10s) yet and suspect there will be a handful of changes required for that.  

With this if you add a '-tpmozafterpaint' to the commandline it will use mozafterpaint.

this patch is from the http://hg.mozilla.org/build/pageloader repository.

Any feedback on this patch or how it should work would be appreciated.

Comment 9

[Dão Gottwald [:dao]]

Why are you adding the listener on the browser window rather than the content window?

Comment 10

[Timothy Nikkel (:tnikkel)]

Comment on attachment 538039 [details] [diff] [review]
support waiting for mozafterpaint in pageloader (1.0)

So if I'm reading this patch correctly it waits until it receives a load event and an after paint event before recording the time. I think it should wait until we get the load event, do a setTimeout (because we dispatch the load event before we unsuppress painting in DocumentViewerImpl::LoadComplete), then check if isMozAfterPaintPending on nsIDOMWindowUtils is true, and if it is wait until we get an after paint event. I think it is quite likely that we'll get after paint events before the load event (painting of just the page background or partial page), so we'd just be timing the load event in this case again. But I think we we want to time painting the complete page.

Comment 11

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

:dao-
probably lack of understanding of what is going on.  I initially tried the content window and I never received the events.  Could have been something else going wrong.  

:tn-
yes, you are reading the patch correctly.  so should we just be measuring MozAfterPaint and ignore Load?  Currently in tpaint and ts_paint, we just measure on receiving the MozAfterPaint event.  From the sounds of it we should receive that event and then check for isMozAfterPaintPending.

Comment 12

[Timothy Nikkel (:tnikkel)]

(In reply to comment #11)
> :tn-
> yes, you are reading the patch correctly.  so should we just be measuring
> MozAfterPaint and ignore Load?  Currently in tpaint and ts_paint, we just
> measure on receiving the MozAfterPaint event.  From the sounds of it we
> should receive that event and then check for isMozAfterPaintPending.

Good point about the tpaint and ts_paint tests. When we changed to the *paint tests we did that because we were previously measuring the load event and that fired before we had painted anything whatsoever to the screen (at least on Windows). So changing to measure the after paint event effectively meant we were waiting for the load event as well since after paint was coming after the load event. For startup tests I think it is valid to measure when the first paint happens (the first time the users sees your app). I think it is also valid for startup tests to measure when the first paint of the completely loaded chrome happens. I think one could argue for either setup.

But I think page load tests are different. I think we want to measure the time it takes to load the page completely and paint the complete page. So we wouldn't be ignoring load, we would still wait for load, then do a setTimeout, and then check if there are any paints waiting to happen, if so we wait until they happen, otherwise we are done.

Comment 13

[Dão Gottwald [:dao]]

(In reply to comment #12)
> (In reply to comment #11)
> > :tn-
> > yes, you are reading the patch correctly.  so should we just be measuring
> > MozAfterPaint and ignore Load?  Currently in tpaint and ts_paint, we just
> > measure on receiving the MozAfterPaint event.  From the sounds of it we
> > should receive that event and then check for isMozAfterPaintPending.
> 
> Good point about the tpaint and ts_paint tests. When we changed to the
> *paint tests we did that because we were previously measuring the load event
> and that fired before we had painted anything whatsoever to the screen (at
> least on Windows). So changing to measure the after paint event effectively
> meant we were waiting for the load event as well since after paint was
> coming after the load event. For startup tests I think it is valid to
> measure when the first paint happens (the first time the users sees your
> app). I think it is also valid for startup tests to measure when the first
> paint of the completely loaded chrome happens. I think one could argue for
> either setup.

Measuring the time it takes until the application window gets painted is fairly useless, since the application isn't actually ready at that point (neither does it load a page nor can you interact with it). So I hope we're not measuring that. ts_paint should really measure the time it takes for /content/ to be painted, pretty much like a hypothetical tp5_paint should behave.

Comment 14

[Timothy Nikkel (:tnikkel)]

(In reply to comment #13)
> Measuring the time it takes until the application window gets painted is
> fairly useless, since the application isn't actually ready at that point
> (neither does it load a page nor can you interact with it). So I hope we're
> not measuring that. ts_paint should really measure the time it takes for
> /content/ to be painted, pretty much like a hypothetical tp5_paint should
> behave.

I took a look and it looks like tpaint and tspaint are measuring the first paint that a content document gets. But this does not imply that anything is loaded or can be interacted with.

Comment 15

[Timothy Nikkel (:tnikkel)]

I only meant my comments to be about the relationship between the load event and after paint events and how we should measure on those two dimensions.

Comment 16

[Shawn Wilsher :sdwilsh]

Any progress here?

Comment 17

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

I haven't looked at this bug in a couple months.  From the comments above, it is unclear what I need to test/measure and if the ts_paint and tpaint tests are what we want.  I can easily update my patch if there is decision around what we are measuring.  

Basically tell me what to listen for and when to take the timestamp and I will update the patch, test, and checkin :)

Comment 18

[Timothy Nikkel (:tnikkel)]

I think what we want is comment 10, no one has disagreed with it.

Comment 19

[Shawn Wilsher :sdwilsh]

(In reply to Joel Maher (:jmaher) from comment #17)
> I haven't looked at this bug in a couple months.  From the comments above,
> it is unclear what I need to test/measure and if the ts_paint and tpaint
> tests are what we want.  I can easily update my patch if there is decision
> around what we are measuring.  
Yes, we want to do this.  Comment 10 looks good to me (at the very least, it's a big improvement over what we do now).

Comment 20

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

Attachment: support waiting for mozafterpaint in pageloader (2.0)

this patch passes on talos staging, but I am concerned we need to modify the tests themselves.  The tdhtml and tsspider tests record the time from inside the test file which is basically onload:
http://hg.mozilla.org/build/talos/file/ba94d2a40f17/page_load_test/dhtml/colorfade.html#l41

So while the harness will wait for load, then wait for paint, we are still reporting the time from the file we are loading in the browser window.

Any thoughts on this?

Comment 21

[alice nodelman [:alice] [:anode]]

Is this an issue in tdhtml/tsspider only?  Sounds like we need a full review of all tests that use the pageloader (fun!) and then we can determine if those tests need to be bulk updated.

Comment 22

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

Attachment: patch to create _paint tests for use with --mozAfterPaint flag (1.0)

this is created and needs to be tested on the staging server before calling it final

Comment 23

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

Comment on attachment 558561 [details] [diff] [review]
patch to create _paint tests for use with --mozAfterPaint flag (1.0)

we should get this reviewed so we can get this deployed on graphs-staging.

Comment 24

[alice nodelman [:alice] [:anode]]

Comment on attachment 558561 [details] [diff] [review]
patch to create _paint tests for use with --mozAfterPaint flag (1.0)

Applied to graphs-stage.  To add to production graphs db a separate IT bug will need to be filed.

Comment 25

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

Attachment: patch to create _paint tests for use with --mozAfterPaint flag (1.1)

modified to remove dromaeo*_paint and svg*_paint from possible test names.  These tests do their own timing based off Javascript inside the test cases.  If we decide that we want to modify these tests in the future the framework in pageloader and talos will work just fine.

Carrying over the r+ as per IRC conversation with :anode and testing on graphs-staging.

Comment 26

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

Attachment: buildbot-config for adding mozafterpaint flag (1.0)

buildbot-config patch to add --mozAfterPaint for tp tests that measuring timing based on the 'load' event.  This works in staging, but I am not sure about the different branches, it should be turned on for branches ts_paint and tpaint are turned on for.

Comment 27

[alice nodelman [:alice] [:anode]]

Comment on attachment 558812 [details] [diff] [review]
buildbot-config for adding mozafterpaint flag (1.0)

This looks like you are activating the test for all branches.  If it is limited to a handful of branches then it will have to be set up differently then being the default.

Comment 28

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

Attachment: pageloder modifications to support MozAfterPaint (3.0)

updated patch to support 4 scenarios:
1) regular time recording where pageloader does all the metrics
2) test does own timing where the test records time and reports it to pageloader
3) e10s + #1
4) e10s + #2

These scenarios all follow this pattern:
* wait for 'load' event
* if mozafterpaint occurred, then record time
* else wait for mozafterpaint
* we receive mozafterpaint, record time

this works for svg and dromaeo tests, but those tests are designed to record from inside the test mostly based off javascript.  We can tackle that problem later.

Comment 29

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

Attachment: talos patch to allow timing for mozafterpaint for pageloader tests (1.0)

this is the last patch in the series of 4 to make this work.  Other than a few PerfConfigurator.py changes the bulk of this patch is changing the calls inside the tests to tpRecordTime to use a second parameter 'startTime'.

Comment 30

[alice nodelman [:alice] [:anode]]

Comment on attachment 558815 [details] [diff] [review]
talos patch to allow timing for mozafterpaint for pageloader tests (1.0)

The bulk changes look fine.

The PerfConfigurator changes look somewhat brittle (as you say in the patch itself #HACK) but we can live with that for now.

Comment 31

[Timothy Nikkel (:tnikkel)]

Comment on attachment 558813 [details] [diff] [review]
pageloder modifications to support MozAfterPaint (3.0)

The non-e10s case looks good. In the e10s case it looks like we check isMozAfterPaintPending in the load handler itself without doing a setTimeout in between. Is that correct? I think we should check it after a setTimeout the same as the non-e10s case.

Comment 32

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

Attachment: buildbot-config for adding mozafterpaint flag (2.0)

updated patch to have old versions of the talos suites.  This also turns off the --mozAfterPaint stuff for 1.9.2, but leaves both on for all.  This can be easily adjusted depending on how we want to do side by side baseline comparisons.

Comment 33

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

Attachment: pageloder modifications to support MozAfterPaint (3.1)

minor update to pageloader.  This addresses the setTimeout in the e10s scenario.  Also I made sure to remove all eventListeners before closing the browser.

Comment 34

[Timothy Nikkel (:tnikkel)]

Comment on attachment 559255 [details] [diff] [review]
pageloder modifications to support MozAfterPaint (3.1)

This looks fine to me, but someone familiar with the pageloader should review too.

Comment 35

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

Attachment: buildbot-config for adding mozafterpaint flag (2.1)

ok, quick change of plans here on the rollout.  We will leave the original tests as they have been on all branches and for mozilla-central we will turn on the newer mozafterpaint tests.  These will run side by side for 1 week, then we will turn off the old tests and leave the new mozafterpaint tests running.  Next we will move the side by side to the next branch (unless there are any planned migrations that we can piggy back on such as a m-c->m-a merge) and continue on until all branches have this deployed.  This will save resources and should take a few weeks to get rolled out.

Comment 36

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Comment on attachment 559255 [details] [diff] [review]
pageloder modifications to support MozAfterPaint (3.1)

Looks fine, but don't call the flag/variable MozAfterPaint; call it 'useMozAfterPaint' or something.  Otherwise it's quite confusing to have it named the same as the event (and the initial caps don't match any other variable in the file etc.)

Comment 37

[Armen [:armenzg]]

Attachment: [checked in] buildbot-config for adding mozafterpaint flag (2.2)

As I was reviewing the patch I modified it to add some comments, put the old suites at the end and remove OLD_BRANCH_ mentions in mozilla-central.

Comment 38

[Armen [:armenzg]]

Comment on attachment 559510 [details] [diff] [review]
[checked in] buildbot-config for adding mozafterpaint flag (2.2)

Hi catlee. I have r+ed this patch but I would like to have your input on this.

This patch makes all branches to load old_chrome, old_chrome_mac, old_nochrome and old_tp (there are some more for 1.9.2).
Then it adds chrome, chrome_mac, nochrome and tp with the newer --mozAfterPaint flag which makes them report separately from the sibling suites.

Once we do the switch over for all branches the "old_" suites will go away from SUITES (except for some sort of hack for 1.9.2 or something).

It passes ./test-masters.sh and I have asked jmaher to get a diff of dump-master.py [1]

https://wiki.mozilla.org/ReleaseEngineering:TestingTechniques#builder_list.py_.2F_dump_master.py

Comment 39

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

landed talos patch:
http://hg.mozilla.org/build/talos/rev/a676cec0840e

landed pageloader patch:
http://hg.mozilla.org/build/pageloader/rev/0b38ce037298

Comment 40

[[e-mail] (:bhearsum)]

Comment on attachment 559510 [details] [diff] [review]
[checked in] buildbot-config for adding mozafterpaint flag (2.2)

rubberstamping this because we need it for the downtime

Comment 41

[[e-mail] (:bhearsum)]

successfully landed in the downtime

Comment 42

[Armen [:armenzg]]

Is this bug done?

Comment 43

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

This bug is done when we have rolled out tp+mozafterpaint to all branches.  I think next week when we turn off the side by side staging on the last branch we should be able to call this done.