It looks like MediaEngagementService::RecordStoredScoresToHistogram() is taking all the time here. I will see if this can be moved to a background thread.

Windows' fault tolerant heap stack logging added another 40ms to the time taken for this code in 65.0.3292.0[1], so I took a deeper look into what's going on.

Most of the time taken is in content_settings::Rule creation and destruction, particularly the cloning and destruction of the of the base::Value iterating over each Rule. It looks like we're doing a ton of Rule creation and deletion.

The code is effectively implementing a double nested loop:

for each engagement origin:
  for each content settings rule:
    create a copy of the rule
    check if the rule matches
    destroy the rule

Presumably this has gotten progressively slower over time because the number of engagement origins has been continuously increasing as users do more browsing.

Can we either invert the loop ordering so that we're not creating and destroying each Rule for every origin, or avoid the Rule creation and destruction entirely? This probably should be done regardless of whether the execution gets moved to a background thread.

Looking at the numbers, the increase in execution time of this code is causing startup to regress by an additional *14ms per-week* on average. And the time is not uniformly distributed among users -- in 65.0.3292.0 canary the average execution time is now 125ms but users spend 300ms in this function at the 90th percentile and 2.1 seconds at the 99th percentile.


[1] https://uma.googleplex.com/p/chrome/callstacks?sid=592b1a6c02d58d8b5c5b54e195a4c93d

Pending CL out to fix: https://chromium-review.googlesource.com/c/chromium/src/+/808484

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

commit e505f9db8ab902f50b16368498198f8f74a8d13c
Author: Becca Hughes <beccahughes@chromium.org>
Date: Mon Dec 18 14:29:44 2017

Media Engagement: Move record scores histo to task runner

RecordStoredScoresToHistogram() is currently taking around 53.5ms when
MediaEngagementService is constructed. This uses a task runner to record
the scores asynchronously without blocking startup.

BUG= 791779 

Change-Id: I8302eea6ab50411471572edb0b12f78f2986f144
Reviewed-on: https://chromium-review.googlesource.com/808484
Commit-Queue: Becca Hughes <beccahughes@chromium.org>
Reviewed-by: Mounir Lamouri <mlamouri@chromium.org>
Cr-Commit-Position: refs/heads/master@{#524703}
[modify] https://crrev.com/e505f9db8ab902f50b16368498198f8f74a8d13c/chrome/browser/media/media_engagement_score.cc
[modify] https://crrev.com/e505f9db8ab902f50b16368498198f8f74a8d13c/chrome/browser/media/media_engagement_score.h
[modify] https://crrev.com/e505f9db8ab902f50b16368498198f8f74a8d13c/chrome/browser/media/media_engagement_service.cc
[modify] https://crrev.com/e505f9db8ab902f50b16368498198f8f74a8d13c/chrome/browser/media/media_engagement_service.h
[modify] https://crrev.com/e505f9db8ab902f50b16368498198f8f74a8d13c/chrome/browser/media/media_engagement_service_unittest.cc

Following up, we see a 102ms improvement in startup with this change: https://uma.googleplex.com/p/chrome/callstacks?sid=6fb0365e87b53e625597a32cccf777f3

... which is most pronounced in message loop warm start: https://uma.googleplex.com/timeline_v2?sid=35b8f23359f988c461f63fa330dc9aed

Bulk adding Performance-Browser label for bugs identified with the UMA Sampling Profiler.