New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 651848 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Closed: Feb 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: All
Pri: 2
Type: Bug



Sign in to add a comment

Optimize Chrome startup based on data from UMA Sampling Profiler

Project Member Reported by asvitk...@chromium.org, Sep 30 2016

Issue description

Optimize Chrome startup based on data from UMA Sampling Profiler.

While looking at the data from a regression, I noticed a few low hanging fruits we can optimize that will improve start up time.

Will use this bug to track these small improvements. Planning to land a few for M55.
 
Planning to land the set of CLs all together early next week, just to see how much they move the needle. (Each one individually is a pretty small gain, but together it should be a reasonable improvement.)
And one more: https://codereview.chromium.org/2383893002/

Will land them all on the same day (hopefully today if I can get all the lgtms) so we can see the combined effect in canary. :)
Project Member

Comment 6 by bugdroid1@chromium.org, Oct 3 2016

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

commit b62d7d9eec9d9d49d7d2d50bc3fb08f1a4d1880e
Author: asvitkine <asvitkine@chromium.org>
Date: Mon Oct 03 21:15:03 2016

Optimize ShouldLaunchIncognito() since its on the startup path.

Sampling profiler data shows this takes 10ms on the startup path,
mainly due to querying parental controls. Since we only need to
check parental controls if the incognito flag was specified on
the command line, the code is refactored to only query them in
that case.

BUG= 651848 

Review-Url: https://codereview.chromium.org/2382023003
Cr-Commit-Position: refs/heads/master@{#422532}

[modify] https://crrev.com/b62d7d9eec9d9d49d7d2d50bc3fb08f1a4d1880e/chrome/browser/prefs/incognito_mode_prefs.cc
[modify] https://crrev.com/b62d7d9eec9d9d49d7d2d50bc3fb08f1a4d1880e/chrome/browser/prefs/incognito_mode_prefs.h

Project Member

Comment 7 by bugdroid1@chromium.org, Oct 3 2016

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

commit 5424cce0cb1592d7e5c025417861a1a540bd7569
Author: asvitkine <asvitkine@chromium.org>
Date: Mon Oct 03 21:54:41 2016

Optimize startup time of notification code by removing unused code.

Generating the icon via GetAvatarIcon() can be expensive - according
to UMA sampling profiler it takes ~35ms mean time from a recent
Windows dev release. Turns out, it's not even used - so this CL
simply removes it.

Additionally, removes a unit test that stayed around after the code
it was testing was removed because it wasn't referenced in any
BUILD file: ui/message_center/cocoa/settings_controller_unittest.mm

BUG= 651848 

Review-Url: https://codereview.chromium.org/2383893002
Cr-Commit-Position: refs/heads/master@{#422550}

[modify] https://crrev.com/5424cce0cb1592d7e5c025417861a1a540bd7569/chrome/browser/notifications/message_center_settings_controller.cc
[delete] https://crrev.com/6971ec6d658d06cace0a6d873608127a99367aee/ui/message_center/cocoa/settings_controller_unittest.mm
[modify] https://crrev.com/5424cce0cb1592d7e5c025417861a1a540bd7569/ui/message_center/fake_notifier_settings_provider.cc
[modify] https://crrev.com/5424cce0cb1592d7e5c025417861a1a540bd7569/ui/message_center/notifier_settings.cc
[modify] https://crrev.com/5424cce0cb1592d7e5c025417861a1a540bd7569/ui/message_center/notifier_settings.h

Project Member

Comment 8 by bugdroid1@chromium.org, Oct 3 2016

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

commit 49cf5df2724445f3160b4fdf13a187295abe14fb
Author: asvitkine <asvitkine@chromium.org>
Date: Mon Oct 03 22:25:05 2016

Optimize some code in RenderTextHarfbuzz.

This was showing up in the UMA callstacks profiler as taking
significant time on start up. Turns out, creating and Init'ing
the BreakIterator does some icu initialization which is expensive,
e.g. ~50ms at the mean from dev UMA users.

However, we only ever need the BreakIterator if there's a grapheme
run of over 2 characters - which might be uncommon for many users.
So this change makes that initialization lazy - only done when we
actually need it.

BUG= 651848 

Review-Url: https://codereview.chromium.org/2379033004
Cr-Commit-Position: refs/heads/master@{#422564}

[modify] https://crrev.com/49cf5df2724445f3160b4fdf13a187295abe14fb/ui/gfx/render_text_harfbuzz.cc
[modify] https://crrev.com/49cf5df2724445f3160b4fdf13a187295abe14fb/ui/gfx/render_text_harfbuzz.h
[modify] https://crrev.com/49cf5df2724445f3160b4fdf13a187295abe14fb/ui/gfx/render_text_unittest.cc

Project Member

Comment 9 by bugdroid1@chromium.org, Oct 3 2016

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

commit 4417714b419462d698d03a790293818c6cecd81f
Author: asvitkine <asvitkine@chromium.org>
Date: Mon Oct 03 22:52:08 2016

Move GetNewTabCSS() caching off the startup path.

This function appears to take about a mean of 35ms during
startup according to UMA sampling profiler data. Also, the
current NTP doesn't need this CSS - since this is related to
the old local NTP, which currently only powers chrome://apps.

This also saves memory used by the generated CSS until the
first time it's used. The downside is there will be a delay
when loading this css - but given this codepath is only used
by chrome://apps page, this seems like a reasonable trade-off.

Note: The CSS will still be cached after the first request, since
NTPResourceCache caches it and we fetch it from there.

No intended functional changes. Expecting to see a 35ms
startup improvement in UMA when this lands.

BUG= 651848 

Review-Url: https://codereview.chromium.org/2381093002
Cr-Commit-Position: refs/heads/master@{#422578}

[modify] https://crrev.com/4417714b419462d698d03a790293818c6cecd81f/chrome/browser/ui/webui/theme_source.cc
[modify] https://crrev.com/4417714b419462d698d03a790293818c6cecd81f/chrome/browser/ui/webui/theme_source.h
[modify] https://crrev.com/4417714b419462d698d03a790293818c6cecd81f/chrome/browser/ui/webui/theme_source_unittest.cc

We now have data for 2880 which has the fixes.

Results:

https://codereview.chromium.org/2383893002
-> GetAvatarIcon goes from 35ms to essentially 0

https://codereview.chromium.org/2379033004
-> BreakIterator::Init goes from 52ms to 18ms

https://codereview.chromium.org/2382023003
-> ShouldLaunchIncognito goes from ~8ms to essentially 0

https://codereview.chromium.org/2381093002
-> ThemeSource goes from ~35ms to essentially 0

All of the above were inspected by comparing 55.0.2877.0 canary and 55.0.2880.4 canaries on callstacks dashboard.
(And specifically, by typing the above function names into the search field and seeing aggregated time used by time from the very bottom.)

Comment 12 Deleted

I tried to look at UMA histograms to see if the effect is clear there and I didn't see a lot of effect in NonEmptyPaint2 - possibly the metric is too noisy?

So I tried to get something more precise - e.g. Startup.BrowserMainRunnerImplInitializeLongTime. In this case, no real effect at 50th percentile, but see clear wins at 75th and 95th percentiles:

https://uma.googleplex.com/p/chrome/timeline_v2/?sid=cd79d5974014960b90e03568122d8541

This is just looking at first day of a canary, since we don't have the data yet. So for first day, 75% goes from 2.3s to 2.175s and 95% goes from 11s to 10.5s.

Still very limited data though, so I'd like to keep monitoring this to see if this trend continues after a few days.
Cc: wittman@chromium.org gab@chromium.org
I wanted to go back to see if I can tease out the effect of my optimizations.

I looked at 55.0.2877.0 canary and 55.0.2880.4 canaries to match my analysis in comment 10.

To focus on one specific change, I picked the ThemeSource optimization and I filtered both callstacks by ComponentLoader::LoadAll - of which ThemeSource was a large chunk before my optimization.

SamplingProfiler shows that in 2877 this took 79.4ms mean and in 2880 it became 40.2ms:
https://uma.googleplex.com/callstacks?sid=a9deab27efa68621b1ca51286ccb7dae
https://uma.googleplex.com/callstacks?sid=442344082c15172e348bf483d8a78cc5

Looks great! But - I picked ComponentLoader::LoadAll for a reason - because there's a histogram (Extensions.LoadAllComponentTime) track this same interval - so this lets us compare sampling profiler data vs. what we see via histograms. And we do see an effect there:

https://uma.googleplex.com/timeline_v2/?sid=38b8c4dba64bfdeae64c530c99a8cbcb

Looks like a 10ms saving at the 50th percentile and a 200ms (!) saving at the 95th percentile. Actually, more impressive than I expected! (Since this was just one of the four optimizations I landed.)

Also, demonstrates that we really want to have percentiles in sampling profiler data. Otherwise, hard to see the effect of optimizations without also having such histograms.
Re: the above, we also see the effect in 50th and 75th percentiles of Extensions.ExtensionServiceInitTime:

https://uma.googleplex.com/timeline_v2/?sid=6863ea0ad735853b3f53cdb693d8e79d

(95th percentile is unfortunately noisy)

Comment 16 by gab@chromium.org, Nov 15 2016

Cool :), also appears to be visible in Profile.OnLocaleReadyTime and Profile.ProfileImplDoFinalInit which are part of the same stack, but it's lost in noise in Startup.BrowserMessageLoopStartTime.
Great, glad to see this help move the needle on startup performance. I've seen other cases of slowness due to high-percentile clients (e.g.  issue 632126 ), so adding percentile support to the tool will definitely be useful.
Status: Fixed (was: Started)
Closing per the optimizations done earlier. We can file new bugs for any additional work.

Sign in to add a comment