Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8968733382489024640

This is a crbug for b/64727577

=== BISECT JOB RESULTS ===
Perf regression found but unable to narrow commit range

Build failures prevented the bisect from narrowing the range further.


Bisect Details
  Configuration: android_webview_arm64_aosp_perf_bisect
  Benchmark    : system_health.webview_startup_multiprocess
  Metric       : webview_startup_wall_time_avg/blank_about/blank_about_blank
  Change       : 5.17% | 156.028071429 -> 162.956571429

Suspected Commit Range
  4 commits in range
  https://chromium.googlesource.com/chromium/src/+log/a606d6e0020c013eee1862afcd4018338588abf7..ed9ec796e62619560c0a8ca788f3ee1dc49e7c07


Revision             Result                  N
chromium@471824      156.028 +- 20.865       14       good
chromium@471891      156.495 +- 19.1133      14       good
chromium@471892      ---                     ---      build failure
chromium@471893      ---                     ---      build failure
chromium@471894      ---                     ---      build failure
chromium@471895      162.24 +- 29.1168       14       bad
chromium@471899      167.241 +- 7.60149      6        bad
chromium@471909      162.427 +- 9.67142      9        bad
chromium@471924      162.622 +- 23.0431      14       bad
chromium@471956      162.957 +- 22.8165      14       bad

To Run This Test
  src/tools/perf/run_benchmark -v --browser=android-webview --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=blank.about.blank system_health.webview_startup_multiprocess

More information on addressing performance regressions:
  http://g.co/ChromePerformanceRegressions

Debug information about this bisect:
  https://chromeperf.appspot.com/buildbucket_job_status/8968733382489024640


For feedback, file a bug with component Speed>Bisection

I'm gonna cc the authors of 3 of the CLs (one of them is DevTools specific).

Hi hiroshige@, tsunghung@, and fdoray@, do you know if any of your the CLs in comment #3 could have regressed startup-time?

(my guess would be fdoray@'s CL but I have no experience with perf regressions)

I just reviewed my CL, and I don't think my CL would affect the startup-time.

Thanks tsunghung@

I'm trying to reproduce this but can't right now because the webview_startup_multiprocess was removed in
https://chromium-review.googlesource.com/c/chromium/src/+/514044

Torne/Juan, do I need to sync to somewhere just before that CL to rerun this benchmark? (and should I then build some specific target to make it work, or is it enough that the source tree is synced?)

Re #6, to run the benchmark it should be enough to sync the tree to any point before that CL. It shouldn't matter that much which version of WebView (and the webview shell) which you build and install on the device.

Note that a similar jump was seen on system_health.webview_startup (the regular version of the benchmark) which should still be found on ToT.

https://chromeperf.appspot.com/report?sid=4707ab3edabbf28b0f6c907022d3b67652426dc47548ebbd1bfcb9f602fcc8eb&start_rev=470890&end_rev=473611

I'm not sure how to proceed here, when I run this locally I get conflicting results (sometimes the WebViews built from commits before the regression show worse performance than after the regression, sometimes the ones before and after the regression show the same performance..).

Might it be useful to rerun the bisect, or do you think the issue "build failure" would just happen again?


If we have direct access to the bisect bots we could maybe just use those to checkout some specific version like commit 471824, and then cherry-pick each of the four CLs to see which one is the cause? (in case my local setup somehow differs from that of the bisect bots').

Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8967849960451448512

I started a new bisect, but I'm not very hopeful. On your local testing, try adding something like --pageset-repeat 15 to each commit tested. This should help average out the noise. On #3 the bisect bot also appears to have seen some noise, but a clear signal when averaging over many runs.

I started out with pageset-repeat 20, then raised it to 100 for a couple of runs and still got non-consistent results so idk.. (maybe I messed up somewhere ;))

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

Hi fgorski@chromium.org, the bisect results pointed to your CL, please take a look at the
results.


=== BISECT JOB RESULTS ===
Perf regression found with culprit

Suspected Commit
  Author : fgorski
  Commit : 7c52dcabdaefff4b583999c786afbefa907564fb
  Date   : Mon May 15 22:15:20 2017
  Subject: [Android] Adding scheduling through GcmNetworkManager

Bisect Details
  Configuration: android_webview_arm64_aosp_perf_bisect
  Benchmark    : system_health.webview_startup_multiprocess
  Metric       : webview_startup_cpu_time_avg/blank_about/blank_about_blank
  Change       : 4.38% | 134.884857143 -> 140.786214286

Revision             Result                  N
chromium@471824      134.885 +- 16.1116      14      good
chromium@471890      134.293 +- 8.31518      9       good
chromium@471907      133.146 +- 15.0065      14      good
chromium@471915      134.016 +- 9.82626      14      good
chromium@471917      134.041 +- 15.496       14      good
chromium@471918      135.325 +- 8.12672      9       good
chromium@471919      139.797 +- 10.2797      14      bad       <--
chromium@471923      139.322 +- 11.4767      9       bad
chromium@471956      140.786 +- 16.9443      14      bad

To Run This Test
  src/tools/perf/run_benchmark -v --browser=android-webview --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=blank.about.blank system_health.webview_startup_multiprocess

More information on addressing performance regressions:
  http://g.co/ChromePerformanceRegressions

Debug information about this bisect:
  https://chromeperf.appspot.com/buildbucket_job_status/8967849960451448512


For feedback, file a bug with component Speed>Bisection

So the bisects in #13 and #3 point to completely different CL ranges. Yaaay.

How am I supposed to understand #14?
My change was adding functionality that is not even likely to be triggered by the test.

Could someone explain what this test is measuring and how?
Would hot vs. cold start affect results?

Taking this over to investigate noisy metric :(

Extracted raw numbers from both bisects to investigate. The bisect in #3 (build 1677) is quite puzzling, the output posted does not seem to match what actually happened during the bisect. Filed  issue 768384  to investigate.

The second bisect, on webview_startup_cpu_time_avg, is however clearer and---even if there is some noise---it *does* appear to reproduce an actual jump at r471919.

+fgorski, assigning back to you to investigate.

Note, from #8 this was also detected in system_health.webview_startup; so you could try running that benchmark with/without your change and see if that makes a difference.

Re #15: This test is measuring startup time for webview, basically starting webview on about:blank from _cold_ (cleared profile, etc.) and measuring how long that takes. +yolandyan might remember some more of the details.

I would appreciate if someone could validate my presumptions here:

If I understand correctly, this benchmark was run on this bot:
https://build.chromium.org/p/tryserver.chromium.perf/builders/android_webview_arm64_aosp_perf_bisect/builds/1700

Which tells me here:
https://luci-logdog.appspot.com/v/?s=chrome%2Fbb%2Ftryserver.chromium.perf%2Fandroid_webview_arm64_aosp_perf_bisect%2F1700%2F%2B%2Frecipes%2Fsteps%2Fdevice_status%2F0%2Fstdout

that device was running Android M:
I    1.449s Main  020232abc2931127
I    1.449s Main    USB status: online
I    1.449s Main    ADB status: device
I    1.449s Main    Blacklisted: False
I    1.449s Main    Device type: bullhead
I    1.449s Main    OS build: MOB30K
I    1.449s Main    OS build fingerprint: Android/aosp_bullhead/bullhead:6.0.1/MOB30K/2787339:userdebug/test-keys

Which means that most of the added code was not triggered (specifically the GcmNetworkManager code).

If there was any code run, it would be related to newly added capability to write scheduled task to preferences, which I think I can move to AsyncTask and defer from this work.

yes, it's M. bullhead is a nexus 5x in case that's useful

also it's an aosp build, so presumably there is no play store or play services, so no GcmNetworkManager

Lack of GcmNetworkManager does not affect this code as it is never triggered, we only use it on builds before M, that have Play Services of course, where the comment fully applies.

Give this is M, if there is any task scheduled/canceled at the time Android Webview is starting (doubtful on a clean install), it would be using JobScheduler, which is code existing in prior revision.

The only change made to that code path here, is adding a write to SharedPreferences, when schedule/cancel is called. Even in that case we are already doing a sane thing: calling apply().

https://developer.android.com/reference/android/content/SharedPreferences.Editor.html#apply%28%29

I don't see how this code would be affecting webview startup/rendering at this point.

doing a write in the background thread doesn't mean it won't affect things on critical threads

but we are all just guestimating here. perf bots has traces, right? can we compare before and after traces?

I think we might be actually making a first access to shared preferences, and that might be a bit slow.

Looking further

Regarding #24. I don't know how to do that. I'd appreciate pointers.

And thanks for help provided to this point.

from the link in the first comment of this bug, you can hover and click on individual runs on the graph, and in the pop up, there is a "View trace from this run" link

I started looking at traces with limited epiphanies so far.

The only code in my patch that would have a chance of affecting anything is using Shared Preferences.
I can validate that in 2 ways:
* Move it to async task
* Tentatively remove it just to run performance traces.
(Reverting the whole patch is not really an option and does not make much sense at this point).

I am trying to find what piece of code would trigger schedule on Chrome startup, as that would be the reason to even go that far.

android webview start up, not chrome, but the src/content and below parts are shared I guess

Either my code gets triggered and causes trouble, or it could not have possibly do it, right?

Alternative is that the binary is bigger and stuff takes longer to load?

I'll add tracing to my code and check it shows in traces for this test.

Question: If I add traces using org.chromium.base.TraceEvent. Is there a way to run this test so that they were captured (if of course the code path gets triggered?)

Or would I have to do it using android.os.Trace?

I have a patch that captures traces for the methods that were modified added in the offending change:
https://chromium-review.googlesource.com/c/chromium/src/+/687966

It uses TraceEvent right now, but can be adjusted if that will not work for webview tests.

org.chromium.base.TraceEvent or TRACE_EVENT* in native code should work fine

I'm not sure if there are the equivalent perf trybot on cq though. Maybe someone else cc-ed here knows?

Not sure if I understand the request in #33, maybe the info in https://chromium.googlesource.com/chromium/src/+/master/docs/speed/addressing_performance_regressions.md#debugging-regressions helps?

+ned, +simon as they know better the trybot services, and could help answer specific questions about it.

So I'm a bit unclear what's being asked here, taking a stab at summarizing starting with boliu's comment in #c24. Regression here, not sure if fgorski's code is even running in the test, suggestion is to use perf try bots with a patch that adds trace events?

If this is right, then you can try a perf-try bot: https://chromium.googlesource.com/chromium/src/+/master/docs/speed/perf_trybots.md

Basically, patch in your changes, git cl upload, then use run_benchmark to send a job to a perf try bot. It should look roughly like this:

./tools/perf/run_benchmark trybot android-webview-arm64-aosp --output-format=html --upload-results --also-run-disabled-tests --story-filter=blank.about.blank system_health.webview_startup_multiprocess

That will send a job to https://build.chromium.org/p/tryserver.chromium.perf/builders/android_webview_arm64_aosp_perf_bisect, and you'll be able to follow it's progress and get the trace links (sorry this is a little broken and doesn't show up on the waterfall now, so you'll need to look in the logs). Feel free to ping me if need any help.

Thanks. That is what I was looking for I think.

I started this: system_health.webview_startup as it was complaining that there is no benchmark for *_multiprocess

I'll wait for traces from that run and see if I get anything insightful. 

A few questions:

1. My run has finished, but I don't know how to get to the tracing:
https://build.chromium.org/p/tryserver.chromium.perf/builders/android_webview_arm64_aosp_perf_bisect/builds/1716

2. As I mentioned in #36 I was not running exactly the same benchmark, as command line tools told me it does not exist.


The latest data I can find for system_health.webview_startup_multiprocess benchmark is from 05/23/17.

3. Is this benchmark still around?

Please advice

Sorry about the difficulties, unfortunately there have been a few recent benchmark changes that are making this a bit more difficult to diagnose.

- system_health.webview_startup_multiprocess was indeed removed, but note (as I mentioned in #8) that this regression was *also* registered on system_health.webview_startup; so hopefully that one will work too.

- from the tryjob, the links to traces can be found on the "Captured Output" links (one for each WITH/WITHOUT patch), usually near the end of the log.

- there is also an "HTML Results" link under the "Results" step, with values for the metrics measured.

- sadly your run has no traces nor results :( this is because "blank:about:blank" was at some point renamed to "load:chrome:blank"; and the --story-filter option you passed is filtering out all of the stories.

Pleas run your tryjob again, just exclude the --story-filter option which is not really needed in this situation.

Again sorry this is all currently a bit broken, gladly speed-ops team is working hard on a new tryjob system which will make all of this a lot more seamless.

Rerunning:

./tools/perf/run_benchmark trybot android-webview-arm64-aosp --output-format=html --upload-results --also-run-disabled-tests system_health.webview_startup

Thanks for all the guidance. This has been very educational so far, even though I don't have any tangible results yet.

1. It seems that the test run into execution errors.

2. It does not seem like I have any logs in Java category.

I wonder if I am holding it wrong or the problem could be attributed to something else than: my code ran and affected the other code.

Rerunning the test either way, to see if I can get it running without failures.

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

commit 406f48bc3462a9d05d6ae7e15ba2abb0fc4cf09f
Author: Filip Gorski <fgorski@chromium.org>
Date: Thu Jan 18 21:46:04 2018

[BTS] Adding tracing to investigate performance issues

This patch adds tracking to:
* BackgroundTaskSchedulerImpl
* BackgroundTaskSchedulerPrefs

In order to understand how much time we spend in these routines and
find a link to performance issue on webview startup.

Bug: 763955
Change-Id: I92e9614dec572211fa31d61d8ab6dfcad96bc829
Reviewed-on: https://chromium-review.googlesource.com/687966
Reviewed-by: Tommy Nyquist <nyquist@chromium.org>
Commit-Queue: Filip Gorski <fgorski@chromium.org>
Cr-Commit-Position: refs/heads/master@{#530282}
[modify] https://crrev.com/406f48bc3462a9d05d6ae7e15ba2abb0fc4cf09f/components/background_task_scheduler/android/java/src/org/chromium/components/background_task_scheduler/BackgroundTaskSchedulerImpl.java
[modify] https://crrev.com/406f48bc3462a9d05d6ae7e15ba2abb0fc4cf09f/components/background_task_scheduler/android/java/src/org/chromium/components/background_task_scheduler/BackgroundTaskSchedulerPrefs.java