1381432 - 2.79% remote-nytimes (android-4-2-armv7-api15) on push 12cfb7c5610f (Sat Jul 8 2017)

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect)

Description

[Ionuț Goldan [:igoldan]]

We have detected an Autophone regression from push:

https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=66528bf3d70ddd5a43a9017605dd4942ed09d122&tochange=12cfb7c5610f5f6ddccfa71f2dcbe44916dffcc9

As author of one of the patches included in that push, we need your help to address this regression.

Regressions:

  3%  remote-nytimes summary android-4-2-armv7-api15 opt      3,842.29 -> 3,949.51

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

On the page above you can see an alert for each affected platform as well as a link to a graph showing the history of scores for this test. There is also a link to a treeherder page showing the jobs in a pushlog format.

To learn more about the regressing test(s), please see: https://wiki.mozilla.org/EngineeringProductivity/Autophone

Comment 1

[Georg Fritzsche [:gfritzsche]]

I don't see how bug 1358907 could affect page load times (unless measuring shutdown would be somehow part of that test).
Andrew, can you think of something?

Comment 2

[Bob Clary [:bc] (inactive)]

This appears to be Nexus 4 / Android 4.2 only and only for the cached remote nytimes (i.e. second visit to the page). You can see this clearly in phonedash:

http://phonedash.mozilla.org/#/2017-07-07/2017-07-10/binning=repo-phonetype-phoneid-test_name-cached_label-metric&rejected=norejected&errorbars=noerrorbars&errorbartype=standarderror&valuetype=median&remote-nytimes=on&throbberstart=on&throbberstop=on&second=on&autoland=on&mozilla-central=on&mozilla-inbound=on&nexus-4=on&nexus-4-8=on&nexus-4-9=on

The regression can be seen moving from autoland to inbound and central which leads credence that this is a real effect.

Comment 3

[Alessio Placitelli [:Dexter]]

(In reply to Bob Clary [:bc:] from comment #2)
> This appears to be Nexus 4 / Android 4.2 only and only for the cached remote
> nytimes (i.e. second visit to the page).

We've seen a gain in startup performances. So I wonder if the loss we're seeing on the 2nd visit is due to the addon database load being triggered by something: that would explain why the regression is happening "late", I guess.

Comment 4

[Kris Maglione [:kmag]]

(In reply to Alessio Placitelli [:Dexter] from comment #3)
> We've seen a gain in startup performances. So I wonder if the loss we're
> seeing on the 2nd visit is due to the addon database load being triggered by
> something: that would explain why the regression is happening "late", I
> guess.

That seems likely. We moved from loading the add-ons DB immediately at startup to loading it after sessionrestore, which means it happens later, and is likely to happen during page load tests.

We really need to update that code to use idle slices, but that's probably a ways off.

Comment 5

[Andrew Swan [:aswan]]

I think :Dexter and :kmag have it right in comment 3 and comment 4.

Comment 6

[Ionuț Goldan [:igoldan]]

I see bug 1379831 resolved this regression with even a noticeable improvement. I guess it's correct to close this bug as FIXED, right?

Comment 7

[Kris Maglione [:kmag]]

That's quite surprising... That change should only affect shutdown. Unless we're either including shutdown time in the test, or corrupting the add-on database in the previous session and having to rebuild it, or something along those lines.

Anyway, I guess we have to call this fixed, but that might be worth looking into.

Comment 8

[Ionuț Goldan [:igoldan]]

(In reply to Kris Maglione [:kmag] from comment #7)
> That's quite surprising... That change should only affect shutdown. Unless
> we're either including shutdown time in the test, or corrupting the add-on
> database in the previous session and having to rebuild it, or something
> along those lines.
> 
> Anyway, I guess we have to call this fixed, but that might be worth looking
> into.

Bob, can you bring more details about the remote-nytimes test?

Comment 9

[Bob Clary [:bc] (inactive)]

It is just like the other blank and twitter tests in terms of measuring data.

We get our data points from zerdatime in logcat.

1. Application start which matches Gecko.*zerdatime (\d+) - .*application start
2. page load start|page load stop which matches Gecko.*zerdatime (\d+) - page load (start|stop)
3. We adjust the page load start|stop by subtracting the application start to produce the time to start loading and finish loading the page. These are called the Throbber start|stop values. The difference page load stop - page load start is called the throbber time.

The test files are a static copy of the nytimes which was created *years* ago. The current version is available internally at https://mana.mozilla.org/wiki/display/ateam/Autophone but can't be distributed due to copyright issues.

There are several ways to "regress". If you decrease the page load start but leave page load stop alone, the throbber time will increase. If you increase both page load start and page load stop by the same amount, the throbber time will stay the same.

For example, for this checkin:

throbber time is fairly constant.

first visit: http://phonedash.mozilla.org/#/2017-07-07/2017-07-11/binning=repo-phonetype-phoneid-test_name-cached_label-metric&rejected=norejected&errorbars=noerrorbars&errorbartype=standarderror&valuetype=median&geckoview-e10s-nytimes=on&geckoview-nytimes=on&remote-blank=on&remote-nytimes=on&remote-twitter=on&throbbertime=on&first=on&second=on&autoland=on&mozilla-inbound=on&nexus-4=on&nexus-4-9=on

second visit: http://phonedash.mozilla.org/#/2017-07-07/2017-07-11/binning=repo-phonetype-phoneid-test_name-cached_label-metric&rejected=norejected&errorbars=noerrorbars&errorbartype=standarderror&valuetype=median&geckoview-e10s-nytimes=on&geckoview-nytimes=on&remote-blank=on&remote-nytimes=on&remote-twitter=on&throbbertime=on&second=on&autoland=on&mozilla-inbound=on&nexus-4=on&nexus-4-9=on

first visit throbber start (page load start) is also pretty constant:
http://phonedash.mozilla.org/#/2017-07-07/2017-07-11/binning=repo-phonetype-phoneid-test_name-cached_label-metric&rejected=norejected&errorbars=noerrorbars&errorbartype=standarderror&valuetype=median&geckoview-e10s-nytimes=on&geckoview-nytimes=on&remote-blank=on&remote-nytimes=on&remote-twitter=on&throbberstart=on&throbberstop=on&first=on&autoland=on&mozilla-inbound=on&nexus-4=on&nexus-4-9=on

but second visit throbber start and stop regressed:
http://phonedash.mozilla.org/#/2017-07-07/2017-07-11/binning=repo-phonetype-phoneid-test_name-cached_label-metric&rejected=norejected&errorbars=noerrorbars&errorbartype=standarderror&valuetype=median&geckoview-e10s-nytimes=on&geckoview-nytimes=on&remote-blank=on&remote-nytimes=on&remote-twitter=on&throbberstart=on&throbberstop=on&second=on&autoland=on&mozilla-inbound=on&nexus-4=on&nexus-4-9=on

Perhaps kmag is right that the first visit corrupted the addons which required a rebuild, or something else is interfering with the loading of the cached pages from storage or interfering with the cache in some other way.

Hope that helps.