Trace with sampled events

Deleted: trace-f18e92565431800f.json.gz 199 KB

trace-f18e92565431800f.json.gz 199 KB Download

+benwells I am not sure if this is caused by search permission service or general content settings initialization.

Removing myself from the owner of this bug and assigning to a content settings owner.

I'm assuming this ins't search permission service specific but general content settings initialization.

Is this a new bug? AFAIK neither search permission or content settings have changed significantly recently.

We have recently started collecting stack samples from users and it shows up often as one of the reasons for janks at startup.

OK that makes sense. +permissions team lead.

Maybe the init that is causing the jank could be delayed somewhat.

Looking at the stack trace, this is simply reading content settings from the preferences. All of this happens on the UI thread, and needs to be done at the profile initialization, since content settings need to be available when pages are loaded.

We've always been aware that content settings are not stored in an efficient format, but we believed it wasn't a high-priority problem in practice as users didn't have a lot of them. Maybe that has changed now.

Passing to engedy@ to figure out our options.

@Siddhartha, do we have any more reports to corroborate this?

According to UMA, the vast majority of users seem to have <100 total content setting exceptions stored. Storage of content settings might be inefficient, but not so terribly so that it would take 1-2 seconds to parse all exceptions unless there were tens/hundreds of thousands of them.

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

commit 8db4ea0900e4fe47450c2a1e710641b109acfbc1
Author: Siddhartha S <ssid@chromium.org>
Date: Mon Oct 15 19:40:33 2018

Add trace event in HostContentSettingsMap constructor

Helps to show the impact of settings parsing in startup.

BUG=890129

Change-Id: Ia92ebd734600a9114b7cffaf1296d7ada2d1c4f5
Reviewed-on: https://chromium-review.googlesource.com/c/1260142
Reviewed-by: Balazs Engedy <engedy@chromium.org>
Reviewed-by: Martin Šrámek <msramek@chromium.org>
Commit-Queue: Siddhartha S <ssid@chromium.org>
Cr-Commit-Position: refs/heads/master@{#599713}
[modify] https://crrev.com/8db4ea0900e4fe47450c2a1e710641b109acfbc1/components/content_settings/core/browser/host_content_settings_map.cc

Some stats from the recent dev version:
Out of 1600 reports collected with randomized trigger,
we got 200 reports with duration(HostContentSettingsMap ctor) > 100 ms.
This also affect the message loop start time at startup. So, 100ms is a significant portion.

Some example reports where HostContentSettingsMap::HostContentSettingsMap took too long:
https://crash.corp.google.com/browse?q=reportid=%27aadcd7185ae5f484%27#6  - 1s
https://crash.corp.google.com/browse?q=reportid=%278d1cf87a9d9a953f%27#6  - 600ms
https://crash.corp.google.com/browse?q=reportid=%27c4dd6094cb1ae6e3%27#6  - 1.2s
https://crash.corp.google.com/browse?q=reportid=%27164cf1edba9e2d51%27#6  - 300ms

If you think we need better stats about it, I can add an UMA across the function.

Thanks, that's really good data, and indeed concerning. Is there any way to somehow correlate these reports with the number of content settings these users have (we already have UMA for that if that helps).

The easiest way to get that information is by adding it to a TRAC_EVENT1(..., "count", count) and get back the results in the slow traces.

I am unsure what is the right metric to record here to understand the problem better. There are 2 different reasons causing jank here:
1. Reading lot of data from disk. Maybe we could simply compress all the data and store it to disk.
2. Parsing and creating data structs like strings, map. To fix this we need entirely different model to store the data. 

I am unsure what else could be the problems here. As etienne mentioned we can add any kind of data we need in trace events and get back more info. I could help with how to add such events, but not very familiar with the code to make changes myself.

What is the next step here?

Thank you both for the guidance. I prepared crrev.com/c/1326150.

The problem is a combination of two factors:

 1.) We are storing an enormously large number of media engagement scores in the form of content setting exceptions. For example, on my personal Android device I observed almost 700 exceptions, amounting to >90% of all content setting exceptions stored across all content setting types. UMA histogram data confirms that this observation is not an outlier, media engagement exceptions account for the majority of content setting exceptions.

This factor could be remedied by either a.) expiring media engagement scores much more aggressively, b.) if we really need to retain all the data, then migrating media engagement scores to custom, more performant content setting provider implementation.


 2.) Reading content setting exceptions is not particularly efficient. ContentSettingsPattern::Builder::Canonicalize copies strings multiple times, and performs canonicalization of hostnames. After talking to msramek@, we could probably take a leap of faith here and just assume that the hosts stored in prefs are always canonicalized. (In the worst case, the pattern will just have no effect.)

We should do this optimization regardless of the decision on (1). We could write a unit test that parses a couple thousand patterns from a test corpus, do some optimizations (e.g. omitting canonicalization, string copies) and see if it has a significant performance impact, especially on older Android phones (where the current jank reports are coming from).

If it turns out that performance can not be substantially improved, then we will have to either a.) rethink storage for content settings, b.) at least migrate site engagement scores to a custom provider (site engagement is the second largest client of content settings in terms of number of exceptions stored).


For now, I have added a trace event to double-check that jank reports are indeed coming from users who have exceptions in the low thousands.

Becca, Mounir, could you please comment on whether (1./a) would be feasible?

+ site engagement folks as well. There is a similar, slightly less frequently observed jank recorded in  issue 900022 .

:-)

I do not think 1) a) is feasible since MEI is expired with history automatically and to make it expire sooner would work against what MEI is trying to do.

I think the right solution here is to fix the storage, especially if site engagement has the same problems.

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

commit 5d8eed38bec9b93351d1e3cd65f981380acf6e3c
Author: Balazs Engedy <engedy@chromium.org>
Date: Fri Nov 09 10:28:57 2018

Document ContentSettings.Exceptions.media-engagement.

Add the missing histogram suffix `media-engagement` to histograms.xml.
This is the content setting type with by far the largest number of
exceptions, yet missing from the dashboards.

Bug: 890129
Change-Id: Iaca89cf7b28db59a9d3c9baf3f810e765a8308a7
Reviewed-on: https://chromium-review.googlesource.com/c/1326147
Reviewed-by: Jesse Doherty <jwd@chromium.org>
Commit-Queue: Balazs Engedy <engedy@chromium.org>
Cr-Commit-Position: refs/heads/master@{#606785}
[modify] https://crrev.com/5d8eed38bec9b93351d1e3cd65f981380acf6e3c/tools/metrics/histograms/histograms.xml

Just to make sure that we are allocating resources efficiently.

The overwhelming majority (90%) of media engagement entries I am seeing locally are all zeroes apart from visit counts.

Are we certain that no simple alternatives exist to deduce these visit counts without storing these entries; so that implementing an entirely new storage mechanism is the best way forward?

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

commit 5bbf1ecccfbf00d7f286621551ac4fbf6289cd54
Author: Balazs Engedy <engedy@chromium.org>
Date: Fri Nov 09 21:42:07 2018

Trace the content_settings::PrefProvider constructor.

Add a TRACE_EVENT to track how long it takes to initialize
content_settings::PrefProvider, and record the number of exceptions parsed.

Bug: 890129
Change-Id: Ic70783bc9c69f4ce0fdb84e5406701b59bbcbd10
Reviewed-on: https://chromium-review.googlesource.com/c/1326150
Reviewed-by: oysteine <oysteine@chromium.org>
Reviewed-by: Martin Šrámek <msramek@chromium.org>
Reviewed-by: ssid <ssid@chromium.org>
Commit-Queue: Balazs Engedy <engedy@chromium.org>
Cr-Commit-Position: refs/heads/master@{#606976}
[modify] https://crrev.com/5bbf1ecccfbf00d7f286621551ac4fbf6289cd54/chrome/common/trace_event_args_whitelist.cc
[modify] https://crrev.com/5bbf1ecccfbf00d7f286621551ac4fbf6289cd54/components/content_settings/core/browser/content_settings_pref_provider.cc

Note: PrefProvider::PrefProvider does not account for the full duration of the HostContentSettingsMap::HostContentSettingsMap constructor. But it is a significant portion.

The following are stats about the "PrefProvider::PrefProvider" events observed in current dev.

report ID		duration ms	number of exceptions parsed.
f2ef3b650bb2c6ac	324.814		1285
be87f16007c0f7b1	290.621		1497
cd53cc2914209ddc	275.974		298
2c16f698d8ee69b5	274.696		748
e39eb15003ab13e2	273.282		1321
d69ce1ca7964eb1d	233.267		664
8ba0edbad7847b63	232.265		1211

Can we try to debug the issue mentioned in comment #23?

I am removing the first bug tag, since a rough estimate of 10% of users face 100ms delays because of content settings.

Data from media-engagement UMA shows:

95th percentile has 500 exceptions.
99th percentile has >1000 exceptions (falls in overflow bucket).

https://uma.googleplex.com/p/chrome/histograms/?endDate=20181110&dayCount=7&histograms=ContentSettings.Exceptions.media-engagement&fixupData=true&showMax=true&analysis=0.25%200.5%200.75%200.95%200.99%200.995&filters=platform%2Ceq%2CA%2Cchannel%2Ceq%2C2%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial

Assigning to Becca to verify if the zero values are needed, and investigate different storage.

The zero values are still kind of important because they tell us that the site is not a media site.

Assigning back to @engedy.

It looks like the 0 engagement scores are important for the media engagement use case. Expiring the stored metrics sooner is not a viable option.

I am still unclear how much work would be involved in migrating the storage for engagement scores. Can you investigate if it's possible to support the use case of large number of entries in the settings? Can you provide alternative settings storage media/site engagement scores can use if content settings cannot support more performant api.

Is there any way to store the engagement scores to a different file so that reading *any other* settings type does not cause parsing through all the engagement exceptions? Currently reading media scores are not causing the jank, it is reading search provider settings (which happens to read at startup) causes janks.

On a related note, would it be possible to update the histogram range to make sure we have more accurate metrics about number of entries we are storing.

Tommy observed that almost all stack traces we got has CompareDomainNames() in them. Specifically these:

base::SplitStringPiece(base::BasicStringPiece<std::__ndk1::basic_string<char, std::__ndk1::char_traits<char>, std::__ndk1::allocator<char> > >, base::BasicStringPiece<std::__ndk1::basic_string<char, std::__ndk1::char_traits<char>, std::__ndk1::allocator<char> > >, base::WhitespaceHandling, base::SplitResult)

(anonymous namespace)::CompareDomainNames(std::__ndk1::basic_string<char, std::__ndk1::char_traits<char>, std::__ndk1::allocator<char> > const&, std::__ndk1::basic_string<char, std::__ndk1::char_traits<char>, std::__ndk1::allocator<char> > const&)

ContentSettingsPattern::Compare(ContentSettingsPattern const&) const

ContentSettingsPattern::operator<(ContentSettingsPattern const&) const

content_settings::OriginIdentifierValueMap::PatternPair::operator<(content_settings::OriginIdentifierValueMap::PatternPair const&) const

content_settings::OriginIdentifierValueMap::SetValue(ContentSettingsPattern const&, ContentSettingsPattern const&, ContentSettingsType, std::__ndk1::basic_string<char, std::__ndk1::char_traits<char>, std::__ndk1::allocator<char> > const&, base::Time, base::Value*)

content_settings::ContentSettingsPref::ReadContentSettingsFromPref()

The NextAction date has arrived: 2018-12-18

friendly ping

So based on some quick profiling, the lowest hanging fruit is indeed CompareDomainNames, which amounts for ~61% of the total CPU time inside ReadContentSettingsFromPref(). First I'm preparing a CL to optimize that without chaning any functionality.

Deleted: ReadContentSettingsFromPref.svg 201 KB

ReadContentSettingsFromPref.svg 201 KB Download

This is now the profiling result with CompareDomainNames optimized (its cost is now nearly negligible).

Deleted: CompareDomainNames.svg 182 KB

CompareDomainNames.svg 182 KB Download

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

commit 830237cfbc77cb5e6ace760d83fda8a08bb8d6c4
Author: Balazs Engedy <engedy@chromium.org>
Date: Mon Jan 21 14:11:32 2019

Optimize content_settings::IsSubDomainOrEqual.

Slightly optimize performance of IsSubDomainOrEqual(a,b). The previous
implementation performed an rfind() for |b| in |a|, which is cheap if
|a| is indeed the subdomain of |b|, but expensive if not. The new
implementation just checks if |b| is a suffix of |a|.

This CL also increases test coverage for this function.

Bug: 890129
Change-Id: I7a8f71a146616a8c35fd3b1660f57e8f26a32828
Reviewed-on: https://chromium-review.googlesource.com/c/1424940
Commit-Queue: Balazs Engedy <engedy@chromium.org>
Reviewed-by: Martin Šrámek <msramek@chromium.org>
Cr-Commit-Position: refs/heads/master@{#624577}
[modify] https://crrev.com/830237cfbc77cb5e6ace760d83fda8a08bb8d6c4/components/content_settings/core/common/content_settings_pattern.cc
[modify] https://crrev.com/830237cfbc77cb5e6ace760d83fda8a08bb8d6c4/components/content_settings/core/common/content_settings_pattern_unittest.cc

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

commit 1a3d49cd425744c33f9e7cbc96213537fc65e885
Author: Balazs Engedy <engedy@chromium.org>
Date: Tue Jan 22 17:52:24 2019

Optimize performance of content_settings::CompareDomainNames.

This CL reduces CPU time by a factor of 5-10x based on local testing
on practical inputs. Turns out, constructing the output vector, and
trimming strings had been really expensive previously (see profiling
data on the bug).

As the function used to account for about 60% of the total CPU time
spent in ReadContentSettingsFromPref(), this operation is now about
2x faster on start-up on both mobile and desktop platforms.

Bug: 890129
Change-Id: I8d589d3746bb4762180a824b3f18d3c4353f9bf4
Reviewed-on: https://chromium-review.googlesource.com/c/1421922
Reviewed-by: Martin Šrámek <msramek@chromium.org>
Reviewed-by: ssid <ssid@chromium.org>
Commit-Queue: Balazs Engedy <engedy@chromium.org>
Cr-Commit-Position: refs/heads/master@{#624824}
[modify] https://crrev.com/1a3d49cd425744c33f9e7cbc96213537fc65e885/components/content_settings/core/common/content_settings_pattern.cc