1375848 - 65.49 - 131.4% tp5n nonmain_startup_fileio (windows7-32) regression on push 8b34a8ccdb17 (Thu Jun 22 2017)

Status: RESOLVED WONTFIX

(Core :: Preferences: Backend, defect)

Description

[Ionuț Goldan [:igoldan]]

Talos has detected a Firefox performance regression from push:

https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?changeset=b7ab577515658d9acbc974e3a200f872aa93d20e

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

Regressions:

131%  tp5n nonmain_startup_fileio windows7-32 opt e10s     51,887.83 -> 120,070.00
 65%  tp5n nonmain_startup_fileio windows7-32 pgo e10s     70,577.54 -> 116,800.67


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

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

[Ionuț Goldan [:igoldan]]

Above comment was pregenerated. The actual regression came from this push:

https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=0298f22db7a5a127c26c1de3b23dcfa303a64c28&tochange=8b34a8ccdb17604b9bce0f228f8cab9710224331

Comment 2

[:Gijs (he/him)]

I guess this is related to saving prefs off a timer. If we dirty prefs on startup (which is likely) that would explain us saving and thereby increasing file io. Perhaps the batching needs to be more aggressive (ie longer delays), especially if we're guaranteed to write on (non-crash) shutdown?

Comment 3

[Ionuț Goldan [:igoldan]]

This is the backout:

== Change summary for alert #7496 (as of June 23 2017 03:48 UTC) ==

Improvements:

 58%  tp5n nonmain_startup_fileio windows7-32 opt e10s     107,744.04 -> 45,573.42

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

Comment 4

[Ionuț Goldan [:igoldan]]

:Gijs Could you name the precise bug, out of the 4, so we know we're on the same page?

Comment 5

[:Gijs (he/him)]

bug 981818.

Comment 6

[Milan Sreckovic [:milan] (needinfo for best results)]

One thing we can consider is having the "save on dirty" only start after the startup sequence has been completed, instead of right away.

Comment 7

[Benjamin Smedberg]

I'm surprised that we'd be firing an idle event before startup is finished, but I guess it could be if there are periods during startup where the main thread is blocked on I/O.

igoldan, The https://wiki.mozilla.org/Buildbot/Talos/Tests page doesn't have any documentation for this metric, which is disappointing. Could you help fix that? Was there an equivalent reduction in main-thread I/O from this? Or do we even measure main thread I/O similarly? 

The original patch got backed out; I'll think about this before relanding.

Comment 8

[Ionuț Goldan [:igoldan]]

:bsmedberg This is indeed one of the high priorities right now, as the performance wiki either remained out of date or lacking proper descriptions.

Comment 9

[Benjamin Smedberg]

This stopped happening because the bug was backed out, but it's not fixed.

Comment 11

[Benjamin Smedberg]

From the relanding: 
1357%  tp5n nonmain_startup_fileio windows7-32 opt e10s     4,586.42 -> 66,802.58
724%  tp5n nonmain_startup_fileio windows7-32 pgo e10s     8,473.96 -> 69,822.67

This is still surprising given the forced delays and coalescing in the patch which I have tested work correctly. However, without evidence of any other performance losses during startup I'd like to keep this in, and I'll follow up with some logging to figure out which prefs are being set that would cause all these extra writes.

Ionut can you verify that none of the other startup performance metrics regressed?

Comment 12

[Ionuț Goldan [:igoldan]]

If they were any, they would have fired so far. But I double checked them, to see any hint of other startup regressions.
Nothing bad showed up, so besides tp5n, everything is ok.

Comment 13

[Benjamin Smedberg]

ok, I'm going to call this WONTFIX because there is an increase and we've decided to accept it