1364488 - 2.02 - 10.63% sessionrestore / sessionrestore_no_auto_restore / tabpaint / tart / tpaint / tps / ts_paint (linux64, osx-10-10, windows7-32, windows8-64) regression on push 4ee414a52ab12c40f008da99d21a93d3cf3852f6 (Thu May 11 2017)

Status: RESOLVED FIXED

(Toolkit :: Places, defect, P1)

Description

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

Talos has detected a Firefox performance regression from push 4ee414a52ab12c40f008da99d21a93d3cf3852f6. As author of one of the patches included in that push, we need your help to address this regression.

Regressions:

 11%  tabpaint summary osx-10-10 opt e10s     53.93 -> 59.66
 10%  sessionrestore_no_auto_restore windows8-64 opt 838.58 -> 921.50
 10%  sessionrestore windows8-64 opt          819.33 -> 899.50
  9%  tps summary osx-10-10 opt               48.51 -> 52.92
  9%  sessionrestore linux64 opt              803.50 -> 876.08
  8%  tps summary windows8-64 opt             45.74 -> 49.47
  8%  sessionrestore_no_auto_restore linux64 opt 831.17 -> 898.00
  8%  tps summary linux64 opt                 46.53 -> 50.22
  8%  tps summary windows7-32 opt             48.59 -> 52.36
  6%  tabpaint summary osx-10-10 opt          90.78 -> 96.63
  6%  sessionrestore windows7-32 opt          891.42 -> 946.33
  6%  ts_paint linux64 opt                    1,267.08 -> 1,345.00
  6%  sessionrestore_no_auto_restore windows7-32 opt 915.88 -> 968.58
  4%  tpaint osx-10-10 opt                    364.31 -> 378.70
  3%  tpaint linux64 opt                      264.92 -> 273.31
  3%  tpaint windows8-64 opt                  277.08 -> 285.64
  2%  tart summary windows7-32 opt            6.80 -> 6.96
  2%  tart summary windows8-64 opt            6.32 -> 6.47
  2%  tart summary windows7-32 opt e10s       7.21 -> 7.37
  2%  tart summary linux64 opt                5.87 -> 5.99

Improvements:

  3%  tp5n nonmain_normal_fileio windows7-32 opt      357,709,390.54 -> 347,997,449.75
  2%  tp5n nonmain_normal_fileio windows7-32 opt e10s 355,981,580.96 -> 347,235,010.92


You can find links to graphs and comparison views for each of the above tests at: https://treeherder.mozilla.org/perf.html#/alerts?id=6555

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 Talos jobs in a pushlog format.

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

For information on reproducing and debugging the regression, either on try or locally, see: https://wiki.mozilla.org/Buildbot/Talos/Running

*** Please let us know your plans within 3 business days, or the offending patch(es) will be backed out! ***

Our wiki page outlines the common responses and expectations: https://wiki.mozilla.org/Buildbot/Talos/RegressionBugsHandling

Comment 1

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

there are a lot of regressions here, I have been working to ensure I have all of the changes documented, I think I do but a few more data points might come in a bit later.

This is pretty widespread across tests and different OS's, likewise some larger regressions.  Pauline, I see you authored the patch in bug 1157709, can you take a look at fixing these regressions?

Comment 2

[Marco Bonardo [:mak]]

Are we confident about the regression range? It's strange that the change may have affected many of those...

I can look a this on monday, if it's a problem please backout and then we'll investigate on Try.

Comment 3

[Marco Bonardo [:mak]]

Mark, a heads-up if you're working on top of bug 1157709

Comment 4

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

I am pretty confident on the range, I did a lot of retriggers and the graphs show a clear line with only one revision in the range.

Monday sounds good to me, thanks ::mak.

Comment 5

[Marco Bonardo [:mak]]

Off the top of my head there are a few things different in the new code:
- the new query excludes tags, while this is positive, it may initiate code that was not initiated before?
- the new code is mostly JS, the previous one was Cpp. Not a big deal but this may cause a skew in time so that our query runs during one of the tab tests instead of before/after
- the query could be canceled before it could even ran, now it always runs. in general it shouldn't matter, if not by delaying by a few ms the star button state. And looks like we are also doing less IO, so... dunno if it really matters
- asyncGetBookmarkIds was not starting up the bookmarks service... could matter or not, depending on how these tests are run

Comment 6

[Marco Bonardo [:mak]]

I have a couple of ideas that I will test today on Try.

Comment 7

[Marco Bonardo [:mak]]

Attachment: Bug 1364488 - Recover from a Talos regression due to recent changes to the Star button.

The main reason for these changes is to avoid initializing the bookmarks service too early,
plus a lot of micro-optimizations to reduce the code-bloat compared to the previous bogus
(but slick) async getter.

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

Comment 8

[Marco Bonardo [:mak]]

The main remaining differences from the previous code, after this patch, are:
- a bit more code. The old helper didn't really make input validation, and didn't exclude tags, both of which are not positives. This could cost some additional js execution but it is something I'd prefer not having to remove. I tried to bypass code as far as possible, but without creating technical debt.
- using the RW connection instead of the RO connection. On Try, based on my testing, the difference in Talos was always inside the noise, so hard to tell if it would make any difference. It looked like it could improve tps and tart, but at the same time it regressed nonmain_io. Additionally the change would require non conventional changes to the bookmarking API (basically a dedicated option), that is not something I'd love. Overall the results didn't look much better than the attached patch.
- clearly there can be some time shifting, so we can't go back exactly where we are, plus a bunch of stuff landed in the meanwhile (included the huge Task/async rewrite), that makes a bit hard to measure precisely the recovery.

Comment 9

[Marco Bonardo [:mak]]

Comment on attachment 8868141 [details]
Bug 1364488 - Recover from a Talos regression due to recent changes to the Star button.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/139740/diff/1-2/

Comment 10

[Marco Bonardo [:mak]]

I honestly think the tabpaint regression is bogus. First it's only on MacOS, second all the changes I tried did not cause any change in it, and I'd indeed expect that, I don't see how the Star button updating may change the time to paint the tab's content, if not due to some time shifting (that would also explain why the regression appears only on Mac, it's just now measuring at a slightly different time, the Mac thread scheduler is picky at times). It also seem to have a 6% uncertainty that makes any measurement complicate.

tart has a 2% uncertainty, as I said it's possible there is a bit more js code to run, but it doesn't appear to be easily measurable.
on tpaint I see a small improvement with the patch, but it's in the noise (2%). Whatever has an effect on tpaint should also have on ts_paint, and we're recoving the ts_paint regression.

The sessionrestore measurements will be recovered, that makes sense since the new code path was initing the bookmarks service earlier. Same for ts_paint.

The patch will surely do good, I only see improvements, but maybe won't cover 100% of the regression. It should land regardless.

Tomorrow I will still do one measurement using the patch as baseline and comparing with a full backout of bug 1157709, that should give me some insight on how the numbers look now, after the many patches that landed in the meanwhile and shifted the measurements.

Comment 11

[Marco Bonardo [:mak]]

I've done a comparison of the latest patch with a (partial) backout of bug 1157709 (the remaining part of the patch is disabled behind a pref, so it doesn't matter), as suspected tabpaint doesn't change at all, even with a backout. I call that bogus and likely unrecoverable (probably something else landed in the meanwhile that further confirmed the times shifting).

The interesting part is that the backup shows a tart improvement and _MAYBE_ (it's completely in the noise) a win7 tps improvement. Out of the 2 the only one that looks real is tart, considered the tps improvement is only on win7 and very noisy.

So basically, what's left here is a 2% tart regression. It's likely the input validation code is a tiny bit more expensive than having no validation at all, plus the work may happen at a different time (maybe before it wasn't counter while now run a bit later). My previous attempt that introduced a dedicated API with limited input checking and using a concurrent connection had similar results, but I'd prefer to avoid adding further specialized APIs for uncertain benefits, yet. I'll try to do some further profiling and see if I find anything more to save.

Overall with the patch the situation is not that horrible.

Comment 12

[Marco Bonardo [:mak]]

by doing a further analysis of my tests on Try, the only thing that seems to affect tart is the way we query.
Rethinking about that, using withConnectionWrapper is indeed more expensive than promiseDBConnection, because it has to do a lot more boilerplate to setup a shutdown blocker. I'll try to add an option to fetch to run a concurrent query and see if that will help with tart.

Comment 13

[Mark Banner (:standard8)]

Comment on attachment 8868141 [details]
Bug 1364488 - Recover from a Talos regression due to recent changes to the Star button.

https://reviewboard.mozilla.org/r/139740/#review143496

Looks good to me r+

Comment 14

[Marco Bonardo [:mak]]

note: we could lose the nonmain_normal_fileio improvement. I think the improvement was not "real", probably talos was just stopping the measurement before some of the queries ran (it's all async). Going back to a concurrent connection seems to move back those reads inside the analyzed bracket, it all makes sense. Nothing serious imo, the query is identical, the amount of data is identical, it's clearly just a measurement bracket problem.

Comment 15

[Marco Bonardo [:mak]]

Attachment: Bug 1364488 - Allow fetch to use a concurrent connection.

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

Comment 16

[Marco Bonardo [:mak]]

Here is the results: https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=eba684ff8635&newProject=try&newRevision=94e409d6faa2&framework=1&showOnlyImportant=0

MacOS is late to the party yet, not enough builders.

Comment 17

[Mark Banner (:standard8)]

Comment on attachment 8868718 [details]
Bug 1364488 - Allow fetch to use a concurrent connection.

https://reviewboard.mozilla.org/r/140306/#review143984

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fd205946fab5
Recover from a Talos regression due to recent changes to the Star button. r=standard8
https://hg.mozilla.org/integration/autoland/rev/2e57846b3e57
Allow fetch to use a concurrent connection. r=standard8

Comment 19

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/fd205946fab5
https://hg.mozilla.org/mozilla-central/rev/2e57846b3e57

Comment 20

[Ionuț Goldan [:igoldan]]

== Change summary for alert #6705 (as of May 18 2017 10:11 UTC) ==

Improvements:

  8%  sessionrestore linux64 opt e10s     890.75 -> 823.67
  7%  sessionrestore_no_auto_restore linux64 opt e10s917.17 -> 852.33
  6%  ts_paint linux64 opt e10s           1,378.25 -> 1,297.83

Regressions:

  4%  tp5n nonmain_normal_fileio windows7-32 pgo e10s     351,769,723.68 -> 365,594,567.33
  4%  tp5n nonmain_normal_fileio windows7-32 opt e10s     349,913,796.67 -> 362,338,972.42

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

Comment 21

[Marco Bonardo [:mak]]

(In reply to Ionuț Goldan [:igoldan], Performance Sheriffing from comment #20)
> == Change summary for alert #6705 (as of May 18 2017 10:11 UTC) ==
> Regressions:
> 
>   4%  tp5n nonmain_normal_fileio windows7-32 pgo e10s     351,769,723.68 ->
> 365,594,567.33
>   4%  tp5n nonmain_normal_fileio windows7-32 opt e10s     349,913,796.67 ->
> 362,338,972.42

As expected we can ignore the regressions, it's just work that is moving in and out of the measurement bracket.

Actually there are also small improvements to the other tests that the automatic system considered noise:
tps on osx, tart on all the platforms, tabpaint on osx... and others, unfortunately there are so many changes to perf lately that all the measurements are extremely noisy.
But according to my measurement in comment 11 we cannot gains anything more here, we are almost on par with a backout of the originating bug. So I'm confident we addressed the regression.

Comment 22

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

as a note, there are some AWSY regressions from this:
== Change summary for alert #6721 (as of May 18 2017 11:00 UTC) ==

Regressions:

  4%  Resident Memory summary windows10-64-vm opt      598,656,483.20 -> 620,803,795.46
  4%  Explicit Memory summary windows7-32-vm opt       110,790,401.14 -> 114,859,446.92
  2%  Resident Memory summary windows7-32-vm opt       381,373,167.74 -> 389,169,545.44

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

possibly related to the nonmain_normal_fileio

Comment 23

[Marco Bonardo [:mak]]

Was there an improvement previously when bug 1157709 landed?
The nonmain_normal_fileio thing is just bogus, as I said in comment 14. There's nothing serious here that can increase or decrease memory usage by a measurable amount.

Comment 24

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

you can see some AWSY improvements https://bugzilla.mozilla.org/show_bug.cgi?id=1157709#c29:
Improvements:

  4%  Explicit Memory summary windows7-32-vm opt      114,176,080.01 -> 109,609,005.84
  4%  Resident Memory summary windows7-32-vm opt      400,773,773.31 -> 385,822,445.00
  4%  Explicit Memory summary linux32 opt             115,980,741.01 -> 111,711,691.77
  4%  Explicit Memory summary linux64 opt             154,589,146.31 -> 149,081,308.47
  3%  Resident Memory summary windows10-64-vm opt     613,099,121.73 -> 592,227,480.40
  3%  Explicit Memory summary windows10-64-vm opt     149,483,483.78 -> 145,119,607.05
  2%  Heap Unclassified summary windows10-64-vm opt   42,192,367.33 -> 41,268,304.13

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


so if this is related to changing some of bug 1157709, then possibly that is an easy explanation for the awsy data.