Am I interpreting "diff" and "total" correctly in these results? For example:

  `anonymous namespace'::LoadMessageFile (code, 1.376%, 68.0ms, +67.8ms)

means that this used to take 0.2ms, and now it takes 68ms?

And similarly, this:

  extensions::InstalledLoader::LoadAllExtensions() (code, 22.32%, 1.10s, +1.00s)

means that LoadAllExtensions went from 0.10s to 1.10s?


I would be surprised if my CL resulted in even a 2x difference in LoadMessageFile, let alone a 340x difference. It looks like the extra time is being spent in creating files -- why does ReadFileToStringWithMaxSize() create files?

Is opening a file on Windows significantly slower if that file doesn't exist?

I'm just having trouble understanding how loading all extensions used to take 100ms and now takes 1100ms.

Each extension used to try to read at least one messages file.
Now, each extension will try to read at most one additional messages file.

https://cs.chromium.org/chromium/src/extensions/common/extension_l10n_util.cc?type=cs&sq=package:chromium&g=0&l=362

We can do a minor optimization here (make sure we don't insert the same locale twice, in case the preferred or default locale is also returned by GetParentLocales) but that wouldn't account for a full second.

That interpretation of the "diff" and "total" is correct.

Chances are that some of this variation in performance may be due which extensions were loaded or to ambient I/O contention. We do tend to see some performance variation in the extensions code from release to release in the UMA Sampling Profiler data. Comparing between 72.0.3584.0 and 72.0.3586.0 (the following version) for example the regression is still there, but is 24ms.

24ms is one thing, but I'm also seeing a full 1s increase (from 0.1s) in LoadAllExtensions().

Is opening a file on Windows significantly slower if that file doesn't exist?

Before my CL, each extension used to try to read at least one messages file.
Now, each extension will try to read at most one additional messages file.

https://cs.chromium.org/chromium/src/extensions/common/extension_l10n_util.cc?type=cs&sq=package:chromium&g=0&l=362

We can do a minor optimization here (make sure we don't insert the same locale twice, in case the preferred or default locale is also returned by GetParentLocales) but that wouldn't account for a full second.

I don't think opening a file should be slower if it doesn't exist.

The overall slowdown in LoadAllExtensions seems to be dominated by disk I/O, which likely indicates some combination of additional I/O while loading the extensions and additional I/O contention. That seems like a broader issue than the i18n changes.

Side note: as would be expected we also see a spike in Extensions.ExtensionServiceInitTime in the UMA data during this time: https://uma.googleplex.com/p/chrome/timeline_v2?sid=dc478122c1c38dff89cb6a639c04d634

FYI, my CL was cherry-picked into 71.0.3578.19. We should check if there is a similar regression there (once that version goes out to dev channel).

71.0.3578.10 to 71.0.3578.20 do show a similar performance regression. But the results for later 72 revisions fluctuate too much for me to draw any conclusions.

Un-assigning from myself because:

* Latest data shows most of the extensions::DefaultLocaleHandler::Validate() as a big contributing factor to the regression; that function does not use the changed code from my CL
* With my CL, Chrome is reading *up to* one additional file per extension on startup, which is WAI; I don't think that would explain a 100-200ms increase in time spent in base::PathExists()
* Does not seem to have regressed on Linux/Mac/Chrome OS
* I don't have the equipment (or knowledge, really) to debug this

Brett, any thoughts on why we're seeing these performance regressions or who this should be directed to?

Looking at Extensions.ExtensionServiceInitTime, we see that the average increases a little at the 25th percentile, but quadruples at the 95th percentile -- meaning 5% of Beta users are seeing an average 5-second increase in this metric?! [2]

There wasn't a similar change in stable channel, so it wouldn't be explained by a change in Windows itself.

[1] https://uma.googleplex.com/p/chrome/callstacks?sid=055cca01a24db2de59e332babcf8cd22
[2] https://uma.googleplex.com/p/chrome/timeline_v2?sid=075a4e8d8d4362579cfe795ad520a58e

Can we try reverting the i18n change for one canary release to test the impact that it's having?

Separately etienneb is setting up a Slow Reports trigger for this issue. This should give us traces from 99th percentile clients which should help to understand if the issue is in the extensions code proper or if that code is suffering based on other contention in the system.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/ce0ec6fc14e4b07ae2d17fddd3c329cc38c8e004

commit ce0ec6fc14e4b07ae2d17fddd3c329cc38c8e004
Author: Michael Giuffrida <michaelpg@chromium.org>
Date: Fri Nov 02 02:57:41 2018

Partial revert of "Use preferred language in extension i18n"

This is a logical revert of "Use preferred language in extension i18n"
(commit 693d01a674be72cb5ee4bf1f0c622189e7e05b37). Because of some
intervening changes causing more complicated merges, it's simpler to
just undo the side effects of the original change, leaving the changed
boilerplate intact.

Reason for revert: Testing perf regression in  crbug.com/898191 

If this exonerates the original CL, we will revert this change.
Otherwise, we will clean up the boilerplate added for the original CL.

Original change's description:
> Use preferred language in extension i18n
>
> When localizing an extension, prioritize the user's preferred language
> over the application locale.
>
> Normally, these are the same. In some cases, they differ. For example,
> the user may choose to display Chrome in "en-CA" (the intl.app_locale
> pref), but because we don't have translations for that, the actual
> UI locale is "en-GB".
>
> This CL makes extensions try to use the user's preferred locale for i18n
> ("en_CA"), falling back to the UI locale ("en_GB") if no locale
> directory is found for the preferred locale.
>
> This change also updates the "current_locale" manifest key to reflect
> the user's preferred locale, or the UI locale if intl.app_locale is
> unset.
>
> Note: Like the application locale, the preferred locale is only set at
> startup (and in certain situations in CrOS). If the user changes their
> intl.app_locale pref, they have to restart Chrome before extensions are
> re-localized, just like before.
>
> Bug: 874225
> Change-Id: I1aabe3c3680b77d6522193e764aec15a3d618d2d
> Reviewed-on: https://chromium-review.googlesource.com/c/1244666
> Commit-Queue: Michael Giuffrida <michaelpg@chromium.org>
> Reviewed-by: Scott Violet <sky@chromium.org>
> Reviewed-by: Istiaque Ahmed <lazyboy@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#600619}

Bug:  898191 
Change-Id: Iaddceb16d61ffc5572a25ed31276443ea5b5baa4
Reviewed-on: https://chromium-review.googlesource.com/c/1308765
Reviewed-by: Istiaque Ahmed <lazyboy@chromium.org>
Commit-Queue: Michael Giuffrida <michaelpg@chromium.org>
Cr-Commit-Position: refs/heads/master@{#604819}
[modify] https://crrev.com/ce0ec6fc14e4b07ae2d17fddd3c329cc38c8e004/extensions/common/extension_l10n_util.cc
[modify] https://crrev.com/ce0ec6fc14e4b07ae2d17fddd3c329cc38c8e004/extensions/common/extension_l10n_util_unittest.cc

Thanks for the revert!

We have data for this now, and it's ... odd. We're seeing a spike in Extensions.ExtensionServiceInitTime once again, very similar to what we saw originally[1]. Unfortunately we can't get a good sampling profiler diff for this because one of the functions low in the call tree happened to change signature in the same version.

The Slow Reports trigger isn't quite working as expected, but we at least have one trace where ExtensionService::Init is taking almost 4 seconds[2]. I'm not 100% sure how to understand that trace but it does look like there may be a lot of I/O happening on high-priority threads at the same time. Etienne -- could you take a look at the trace and see what you think about why ExtensionService::Init is taking 4 seconds?

I am wondering if this has something to do with SuperFetch. Perhaps changing which files get read on ExtensionService init invalidates part of its caching? This potentially would explain regressions on both commit and revert, and the drop-off in the regression over time as more and more clients files become cached.

[1] https://uma.googleplex.com/p/chrome/timeline_v2?sid=3fc9c422a10bbb47899fb8a729c60417
[2] http://crash/b09df533419b9dac#6

From this slow-reports: e293deee24452ddc 
There is a 3.9 seconds LoadAllExtensions.

The attached trace is symbolized, and you can look to the sampling profiler.

Deleted: trace-e293deee24452ddc.gz 1.4 MB

trace-e293deee24452ddc.gz 1.4 MB Download

Deleted: extension1.png 71.0 KB

	extension1.png 71.0 KB View Download

From this slow-report: b09df533419b9dac

Deleted: extension2.png 82.1 KB

	extension2.png 82.1 KB View Download

Deleted: trace-b09df533419b9dac.gz 1.5 MB

trace-b09df533419b9dac.gz 1.5 MB Download

To evaluate the SuperFetch hypothesis, I took a look at how Extensions.ExtensionServiceInitTime varies by version for the same clients. If this issue is due to invalidating the SuperFetch cache I would expect that individual clients would see poor performance on the first run of 72.0.3585.0 and but later runs of that version (and later versions up to 72.0.3600.0 where the revert happened) would have 'normal' performance.

The data I looked at, for versions between 72.0.3580.0 and 72.0.3586.1, was consistent with this expectation: generally individual clients saw a regression in a single run in 72.0.3585.0 that did not persist beyond that version. Since this appears to be a transient issue on a per-client basis (whether due to SuperFetch or not), I don't think there's anything to be done to address the regression.

I will revert the revert to restore the original behavior.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/df2c70fcdb46d29057b48084c2571f9373ba4eff

commit df2c70fcdb46d29057b48084c2571f9373ba4eff
Author: Mike Wittman <wittman@chromium.org>
Date: Tue Nov 13 20:12:03 2018

Revert "Partial revert of "Use preferred language in extension i18n""

This reverts commit ce0ec6fc14e4b07ae2d17fddd3c329cc38c8e004.

Reason for revert: While the perf regression may have been caused by the original CL, it was transient. 

Original change's description:
> Partial revert of "Use preferred language in extension i18n"
> 
> This is a logical revert of "Use preferred language in extension i18n"
> (commit 693d01a674be72cb5ee4bf1f0c622189e7e05b37). Because of some
> intervening changes causing more complicated merges, it's simpler to
> just undo the side effects of the original change, leaving the changed
> boilerplate intact.
> 
> Reason for revert: Testing perf regression in  crbug.com/898191 
> 
> If this exonerates the original CL, we will revert this change.
> Otherwise, we will clean up the boilerplate added for the original CL.
> 
> Original change's description:
> > Use preferred language in extension i18n
> >
> > When localizing an extension, prioritize the user's preferred language
> > over the application locale.
> >
> > Normally, these are the same. In some cases, they differ. For example,
> > the user may choose to display Chrome in "en-CA" (the intl.app_locale
> > pref), but because we don't have translations for that, the actual
> > UI locale is "en-GB".
> >
> > This CL makes extensions try to use the user's preferred locale for i18n
> > ("en_CA"), falling back to the UI locale ("en_GB") if no locale
> > directory is found for the preferred locale.
> >
> > This change also updates the "current_locale" manifest key to reflect
> > the user's preferred locale, or the UI locale if intl.app_locale is
> > unset.
> >
> > Note: Like the application locale, the preferred locale is only set at
> > startup (and in certain situations in CrOS). If the user changes their
> > intl.app_locale pref, they have to restart Chrome before extensions are
> > re-localized, just like before.
> >
> > Bug: 874225
> > Change-Id: I1aabe3c3680b77d6522193e764aec15a3d618d2d
> > Reviewed-on: https://chromium-review.googlesource.com/c/1244666
> > Commit-Queue: Michael Giuffrida <michaelpg@chromium.org>
> > Reviewed-by: Scott Violet <sky@chromium.org>
> > Reviewed-by: Istiaque Ahmed <lazyboy@chromium.org>
> > Cr-Commit-Position: refs/heads/master@{#600619}
> 
> Bug:  898191 
> Change-Id: Iaddceb16d61ffc5572a25ed31276443ea5b5baa4
> Reviewed-on: https://chromium-review.googlesource.com/c/1308765
> Reviewed-by: Istiaque Ahmed <lazyboy@chromium.org>
> Commit-Queue: Michael Giuffrida <michaelpg@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#604819}

TBR=lazyboy@chromium.org,michaelpg@chromium.org

# Not skipping CQ checks because original CL landed > 1 day ago.

Bug:  898191 
Change-Id: Iead107f46039f01b5d5b97b36d1b8fb242f0aee3
Reviewed-on: https://chromium-review.googlesource.com/c/1334194
Reviewed-by: Mike Wittman <wittman@chromium.org>
Reviewed-by: Michael Giuffrida <michaelpg@chromium.org>
Commit-Queue: Mike Wittman <wittman@chromium.org>
Cr-Commit-Position: refs/heads/master@{#607719}
[modify] https://crrev.com/df2c70fcdb46d29057b48084c2571f9373ba4eff/extensions/common/extension_l10n_util.cc
[modify] https://crrev.com/df2c70fcdb46d29057b48084c2571f9373ba4eff/extensions/common/extension_l10n_util_unittest.cc

WontFix per comment 16.