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

Issue 631808 link

Starred by 2 users

Issue metadata

Status: WontFix
Owner:
Closed: Sep 2016
Cc:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug-Regression



Sign in to add a comment

54.9% regression in startup.cold.blank_page at 407510:407544

Project Member Reported by aiolos@chromium.org, Jul 26 2016

Issue description

See attached graph.
 

Comment 1 by aiolos@chromium.org, Jul 26 2016

All graphs for this bug:
  https://chromeperf.appspot.com/group_report?bug_id=631808

Original alerts at time of bug-filing:
  https://chromeperf.appspot.com/group_report?keys=agxzfmNocm9tZXBlcmZyFAsSB0Fub21hbHkYgICghoixqAoM


Bot(s) for this bug's original alert(s):

chromium-rel-win7-gpu-ati
Project Member

Comment 3 by 42576172...@developer.gserviceaccount.com, Jul 27 2016

Cc: rdevlin....@chromium.org
Owner: rdevlin....@chromium.org

=== Auto-CCing suspected CL author rdevlin.cronin@chromium.org ===

Hi rdevlin.cronin@chromium.org, the bisect results pointed to your CL below as possibly
causing a regression. Please have a look at this info and see whether
your CL be related.


===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : [Extensions] Use compiled feature files
Author  : rdevlin.cronin
Commit description:
  
Use generated compiled feature files instead of parsing the JSON at
runtime. In local testing, this shows an order-of-magnitude performance
increase, as well as catching a number of invalid features.

BUG= 280286 

Review-Url: https://codereview.chromium.org/2165023003
Cr-Commit-Position: refs/heads/master@{#407511}
Commit  : 5c684983bc51d5a377fcc34dcdaa9363e9a9d7d3
Date    : Mon Jul 25 18:06:31 2016


===== TESTED REVISIONS =====
Revision         Mean     Std Dev  N  Good?
chromium@407509  820.52   93.5654  5  good
chromium@407510  868.28   47.6377  5  good
chromium@407511  1342.96  50.587   5  bad    <--
chromium@407512  1383.16  118.563  5  bad
chromium@407514  1357.68  60.0373  5  bad
chromium@407519  1329.68  75.8696  5  bad
chromium@407528  1322.88  62.1716  5  bad
chromium@407544  1451.64  50.3665  5  bad

Bisect job ran on: winx64ati_perf_bisect
Bug ID: 631808

Test Command: src/tools/perf/run_benchmark -v --browser=release_x64 --output-format=chartjson --upload-results --also-run-disabled-tests startup.cold.blank_page
Test Metric: open_tabs_time/open_tabs_time
Relative Change: 76.92%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/winx64ati_perf_bisect/builds/1455
Job details: https://chromeperf.appspot.com/buildbucket_job_status/9006038687964710000


Not what you expected? We'll investigate and get back to you!
  https://chromeperf.appspot.com/bad_bisect?try_job_id=5854151007797248

| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with component Tests>AutoBisect.  Thank you!
Cc: -rdevlin....@chromium.org asargent@chromium.org
Hmm.  This is very surprising to me.  This should have only affected extension system initialization time, and local testing and early metrics show it doing exactly that.

Is there a way to run this test locally with a custom build of chrome?  I tried following the instructions at https://www.chromium.org/developers/telemetry/run_locally, but using the commandline
$ tools/perf/run_benchmark startup.cold.blank_page --browser=exact --browser-executable=out/gnr/chrome
gives the error
BrowserFinderException: No browser found.

Available browsers:
canary
debug
reference
system
Another thing to look into is how this test measures things - does it measure as far as the parsing of the json features files that your CL introduced, or just the time to get to the beginning of main in a renderer process? If it wasn't counting the JSON parsing time then it would just see the impact of the additional code added to the binary (not surprising that this could cause some increase to the time to load code pages off disk, etc.) but miss a net performance win. 


Project Member

Comment 7 by 42576172...@developer.gserviceaccount.com, Jul 29 2016

Cc: michae...@chromium.org
Owner: michae...@chromium.org

=== Auto-CCing suspected CL author michaelpg@chromium.org ===

Hi michaelpg@chromium.org, the bisect results pointed to your CL below as possibly
causing a regression. Please have a look at this info and see whether
your CL be related.


===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : AnimationGroup for groups of transitions in Settings
Author  : michaelpg
Commit description:
  
Adds settings.animation.AnimationGroup for playing a Promise-based set of
animation(s). Used in https://crrev.com/2106013002 to create standalone
transitions rather than scattering animation code throughout other classes.

BUG= 589681 
R=dbeam@chromium.org
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.linux:closure_compilation

Review-Url: https://codereview.chromium.org/2171373003
Cr-Commit-Position: refs/heads/master@{#407510}
Commit  : 48e079d573d6385fab6ad7110475a2b9da913bab
Date    : Mon Jul 25 18:00:39 2016


===== TESTED REVISIONS =====
Revision         Mean     Std Dev  N  Good?
chromium@407400  684.075  134.956  8  good
chromium@407474  661.48   40.4689  5  good
chromium@407509  630.8    54.4604  5  good
chromium@407510  735.36   8.68953  5  bad    <--
chromium@407511  820.12   51.2817  5  bad
chromium@407512  929.0    84.4383  5  bad
chromium@407514  851.72   67.8064  5  bad
chromium@407519  916.12   34.1258  5  bad
chromium@407528  962.0    85.3468  5  bad
chromium@407544  962.825  39.7728  8  bad

Bisect job ran on: win_perf_bisect
Bug ID: 631808

Test Command: src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --also-run-disabled-tests startup.cold.blank_page
Test Metric: open_tabs_time/open_tabs_time
Relative Change: 34.25%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/win_perf_bisect/builds/6745
Job details: https://chromeperf.appspot.com/buildbucket_job_status/9005877311732243984


Not what you expected? We'll investigate and get back to you!
  https://chromeperf.appspot.com/bad_bisect?try_job_id=5051634783092736

| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with component Tests>AutoBisect.  Thank you!
Cc: rdevlin....@chromium.org
Unless this perf test opens the settings pages, I find #7 hard to believe.  Is there a performance sheriff cc'd that can help us triage this?
Project Member

Comment 10 by 42576172...@developer.gserviceaccount.com, Jul 30 2016


===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : [Extensions] Use compiled feature files
Author  : rdevlin.cronin
Commit description:
  
Use generated compiled feature files instead of parsing the JSON at
runtime. In local testing, this shows an order-of-magnitude performance
increase, as well as catching a number of invalid features.

BUG= 280286 

Review-Url: https://codereview.chromium.org/2165023003
Cr-Commit-Position: refs/heads/master@{#407511}
Commit  : 5c684983bc51d5a377fcc34dcdaa9363e9a9d7d3
Date    : Mon Jul 25 18:06:31 2016


===== TESTED REVISIONS =====
Revision         Mean     Std Dev  N  Good?
chromium@407505  762.4    50.7159  5  good
chromium@407509  876.64   53.0201  5  good
chromium@407510  768.92   35.9604  5  good
chromium@407511  1532.08  79.437   5  bad    <--
chromium@407512  1323.32  45.1567  5  bad
chromium@407520  1445.56  114.157  5  bad
chromium@407537  1122.0   120.646  5  bad

Bisect job ran on: winx64nvidia_perf_bisect
Bug ID: 631808

Test Command: src/tools/perf/run_benchmark -v --browser=release_x64 --output-format=chartjson --upload-results --also-run-disabled-tests startup.cold.blank_page
Test Metric: open_tabs_time/open_tabs_time
Relative Change: 47.17%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/winx64nvidia_perf_bisect/builds/1751
Job details: https://chromeperf.appspot.com/buildbucket_job_status/9005787937186544208


Not what you expected? We'll investigate and get back to you!
  https://chromeperf.appspot.com/bad_bisect?try_job_id=5246767898034176

| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with component Tests>AutoBisect.  Thank you!
Cc: alexclarke@chromium.org
explicitly cc'ing perf sheriff alexclarke.
That's a pretty noisy graph.  Lets try a wide bisect with a lot of iterations and see what it finds.

===== BISECT JOB RESULTS =====
Status: completed


===== SUSPECTED CL(s) =====
Subject : [Extensions] Use compiled feature files
Author  : rdevlin.cronin
Commit description:
  
Use generated compiled feature files instead of parsing the JSON at
runtime. In local testing, this shows an order-of-magnitude performance
increase, as well as catching a number of invalid features.

BUG= 280286 

Review-Url: https://codereview.chromium.org/2165023003
Cr-Commit-Position: refs/heads/master@{#407511}
Commit  : 5c684983bc51d5a377fcc34dcdaa9363e9a9d7d3
Date    : Mon Jul 25 18:06:31 2016


===== TESTED REVISIONS =====
Revision         Mean     Std Dev  N  Good?
chromium@407300  874.56   67.815   5  good
chromium@407450  927.84   152.922  5  good
chromium@407488  945.44   83.9704  5  good
chromium@407507  981.675  74.8489  8  good
chromium@407510  964.96   75.7124  5  good
chromium@407511  1416.84  118.282  5  bad    <--
chromium@407512  1227.1   98.0606  8  bad
chromium@407516  1235.48  44.1494  5  bad
chromium@407525  1435.76  179.789  5  bad
chromium@407600  1193.36  54.4556  5  bad

Bisect job ran on: winx64intel_perf_bisect
Bug ID: 631808

Test Command: src/tools/perf/run_benchmark -v --browser=release_x64 --output-format=chartjson --upload-results --also-run-disabled-tests startup.cold.blank_page
Test Metric: open_tabs_time/open_tabs_time
Relative Change: 36.45%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/winx64intel_perf_bisect/builds/1076
Job details: https://chromeperf.appspot.com/buildbucket_job_status/9005513810570908912


Not what you expected? We'll investigate and get back to you!
  https://chromeperf.appspot.com/bad_bisect?try_job_id=5902950518489088

| O O | Visit http://www.chromium.org/developers/speed-infra/perf-bug-faq
|  X  | for more information addressing perf regression bugs. For feedback,
| / \ | file a bug with component Tests>AutoBisect.  Thank you!
Owner: rdevlin....@chromium.org
The bisects look pretty certain this was "[Extensions] Use compiled feature files". Assigning to rdevlin.cronin@ to take a look. You should be able run the benchmark locally with the following command (listed in bisect output): 

re: #4, you might need to pass "--chromium-output-directory=out/gnr/" to get the tool to find the browser executable.

Please take a look or do a speculative revert to see if the performance recovers.
Cc: rmcilroy@chromium.org
$ tools/perf/run_benchmark startup.cold.blank_page --browser=exact --browser-executable=out/gnr/chrome --chromium-output-directory=out/gnr/

yields error:
AssertionError: Please add  to desktop_browser_finder.FindAllBrowserTypes
Locals:
  browser_directory : 'C:\\chromium\\crg\\src\\out/gnr/'
  browser_type      : ''
  executable        : 'C:\\chromium\\crg\\src\\out/gnr/chrome.exe'
  finder_options    : [('android_blacklist_file', None), ('browser_executable', 'out/gnr/chrome'), ('browser_options', [('_browser_startup_timeout', 60), ('_extra_browser_args', set([])), ('browser_type', 'exact'), ('browser_user_agent_type', None), ('clear_sytem_cache_for_browser_and_profile_on_start', False), ('disable_background_networking', True), ('disable_component_extensions_with_background_pages', True), ('disable_default_apps', True), ('dont_override_profile', False), ('extensions_to_load', []), ('extra_wpr_args', [] ... iler', None), ('remote_platform_options', <telemetry.internal.platform.remote_platform_options.AndroidPlatformOptions object at 0x0000000004366D68>), ('reset_results', None), ('results_label', None), ('run_disabled_tests', False), ('show_stdout', None), ('story_filter', None), ('story_filter_exclude', None), ('story_label_filter', None), ('story_label_filter_exclude', None), ('suppress_gtest_report', False), ('upload_bucket', 'output'), ('upload_results', None), ('use_live_sites', None), ('verbosity', 0)] (truncated)
  flash_path        : None
  is_content_shell  : False
  is_local_build    : True
  target_os         : 'win32'

Any ideas?

Additionally, the *only* part of the code that this should have affected is captured by Extensions.FeatureProviderStaticInitTime, which still shows a massive drop [1] (good).

I also still can't find any guidance on what, exactly, this test is measuring.  Is that information anywhere?

[1] https://uma.googleplex.com/p/chrome/timeline_v2/?sid=4f5d4815a80737cf22f2e371e0ba109b
Cc: -michae...@chromium.org
This is measuring the UMA metric Startup.BrowserOpenTabs, which is documented as "Time taken to open the initial tab or to restore tabs from previous session."

Here it is added to your chart; it's hard to tell if there is a slight bump or not, but definitely not the same change we're seeing on the perfbots:
https://uma.googleplex.com/p/chrome/timeline_v2/?sid=5ea2b8acb49b71bfaaad1e44af081573
@18 Thanks for the details!  Looking at the graph, I don't really see any regression - it looks like it's all very well within the normal bounds of the graph.  Any idea why the perf bots would be saying different?  And/or advice on what to do with this bug?
I kicked off some perf try jobs to get traces from the bots to see what is going on. I had time to copy out the times and trace URIs, but not to actually dig into the traces. Will look more tomorrow.

Nvidia GPU:
https://uberchromegw.corp.google.com/i/tryserver.chromium.perf/builders/winx64nvidia_perf_bisect/builds/1802
407510:
Times: [765.000000,981.000000,714.000000,1006.000000,740.000000]
Traces:
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_0-2016-08-10_16-17-2752612.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_1-2016-08-10_16-17-2886470.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_2-2016-08-10_16-17-299952.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_3-2016-08-10_16-17-3126943.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_4-2016-08-10_16-17-3227277.zip

407511:
Times: [2197.000000,1381.000000,1190.000000,1489.000000,1115.000000]
Traces:
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_0-2016-08-10_15-57-2441291.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_1-2016-08-10_15-57-2543566.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_2-2016-08-10_15-57-2644676.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_3-2016-08-10_15-57-2744087.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_4-2016-08-10_15-57-2875781.zip

ATI GPU:
https://build.chromium.org/p/tryserver.chromium.perf/builders/winx64ati_perf_bisect/builds/1500
407509:
Times: [752.000000,860.000000,760.000000,960.000000,660.000000]
Traces:
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_0-2016-08-10_16-13-0143898.zip https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_1-2016-08-10_16-13-029841.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_2-2016-08-10_16-13-0344346.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_3-2016-08-10_16-13-0437409.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_4-2016-08-10_16-13-0554684.zip

407544:
Times: [1600.000000,1269.000000,1116.000000,1167.000000,1050.000000]
Traces:
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_0-2016-08-10_15-52-1892253.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_1-2016-08-10_15-52-1982609.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_2-2016-08-10_15-52-2020287.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_3-2016-08-10_15-52-218891.zip
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/profiler-file-id_4-2016-08-10_15-52-2266696.zip

Intel GPU still running: https://build.chromium.org/p/tryserver.chromium.perf/builders/winx64intel_perf_bisect/builds/1102
Perf sheriff ping: reminder to follow up on possible performance issues
Cc: sullivan@chromium.org
sullivan@, given the UMA (still) doesn't show any regression, do you think it's safe to close this bug?
Status: WontFix (was: Assigned)
Marking as WontFix, since UMA hasn't shown a significant move. 

Sign in to add a comment