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

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


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

android-nexus5

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

===== BISECT JOB RESULTS =====
Status: failed


=== Bisection aborted ===
The bisect was aborted because Bisect cannot identify a culprit: Bisect failed to reproduce the regression with enough confidence.
Please contact the the team (see below) if you believe this is in error.

===== TESTED REVISIONS =====
Revision         Mean      Std Dev  N   Good?
chromium@431667  73057166  3708911  27  good
chromium@431695  73048519  3689172  27  bad

Bisect job ran on: android_nexus5_perf_bisect
Bug ID: 671156

Test Command: src/tools/perf/run_benchmark -v --browser=android-chromium --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=browse.media.facebook.photos system_health.memory_mobile
Test Metric: memory:chrome:all_processes:reported_by_os:gpu_memory:proportional_resident_size_avg/browse_media/browse_media_facebook_photos
Relative Change: 0.01%

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/android_nexus5_perf_bisect/builds/4403
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8994115169969491328


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

| 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!

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

===== BISECT JOB RESULTS =====
Status: failed


=== Bisection aborted ===
The bisect was aborted because Bisect cannot identify a culprit: Bisect failed to reproduce the regression with enough confidence.
Please contact the the team (see below) if you believe this is in error.

===== TESTED REVISIONS =====
Revision         Mean      Std Dev  N   Good?
chromium@431667  73067482  3732895  27  good
chromium@431695  73061566  3711933  27  bad

Bisect job ran on: android_nexus5_perf_bisect
Bug ID: 671156

Test Command: src/tools/perf/run_benchmark -v --browser=android-chromium --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=browse.media.facebook.photos system_health.memory_mobile
Test Metric: memory:chrome:all_processes:reported_by_os:gpu_memory:proportional_resident_size_avg/browse_media/browse_media_facebook_photos
Relative Change: 0.01%

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/android_nexus5_perf_bisect/builds/4405
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8994100402269643120


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

| 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!

At this point I'm pretty sure that this is the same as issue 671154, and there is no regression to chase.

Still, Annie, I'm pretty baffled by these bisect results. The graph linked in #0 appears very clean, with a very clear regression, but the numbers from the bisect don't make a lot of sense, and do not reproduce the regression.

Could you look into those to see if there is anything odd going on?

+simonhatch for bisect not reproing

perezju, where in the memory dump does this metric come from?

+primiano, are the reported_by_os metrics shown in the trace view of the memory dump?

Yup those are the blue columns
as in https://storage.googleapis.com/chromium-docs.appspot.com/02eade61d57c83f8ef8227965513456555fc3324

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

Trying same thing from crbug.com/671210 where seems like same lack of repro issue (that is, removing --story-filter). If nothing comes back, we'll log a bug to investigate the lack of repro.

Re #11: On memory.top_10_mobile (as in issue 671210) the --story-filter could affect reproducibility (because stories on that benchmark are not strictly speaking independent).

However on system_health stories *are* independent, so I doubt that removing --story-filter could help much.

re #c13

Partial results are back from 2 bisects, both of which were able to reproduce the regression and also got the same values as the dashboard:
memory.top_10_mobile: https://bugs.chromium.org/p/chromium/issues/detail?id=671210#c10
system_health.memory_mobile: https://bugs.chromium.org/p/chromium/issues/detail?id=670227#c18

As well as this one which is nearly complete and seems to be reproducing the regression clearly now:
system_health.memory_mobile: https://build.chromium.org/p/tryserver.chromium.perf/builders/android_nexus5_perf_bisect/builds/4419


So far it's really looking like --story-filter changes the results. We can wait until the last one comes back, but if these are supposed to be able to be run independently maybe we should log a bug to investigate.

On the bisect side of things, maybe what we can do is provide some "next steps" advice in the output (ie. try running without the story filter?).

+nednguyen: see #14: It's looking like bisecting without --story-filter repros some memory regressions that don't repro with it.

My only three explanations at the moment:
1) gpu memory is leaked even after the browser is closed.
2) This is affected by thermal state/power state. With "--story-filter" off, the phone has to run a lot longer.
3) This regression is device specific.


For 1) & 2), I think it's worthwhile to do some comparison of memory numbers of the last page got run in system_health.memory_mobile when --story-filter is on vs off.

===== BISECT JOB RESULTS =====
Status: failed


===== TESTED REVISIONS =====
Revision         Mean      Std Dev  N  Good?
chromium@431667  71569408  0.0      5  good
chromium@431681  71569408  0.0      5  good
chromium@431688  71569408  0.0      5  good
chromium@431692  71569408  0.0      5  good
chromium@431694  73397862  186231   5  bad
chromium@431695  73431450  153870   5  bad

Bisect job ran on: android_nexus5_perf_bisect
Bug ID: 671156

Test Command: src/tools/perf/run_benchmark -v --browser=android-chromium --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests system_health.memory_mobile
Test Metric: memory:chrome:all_processes:reported_by_os:gpu_memory:proportional_resident_size_avg/browse_media/browse_media_facebook_photos
Relative Change: 2.60%

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/android_nexus5_perf_bisect/builds/4419
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8993912757722430768


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

| 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!

+hjd, could this also be related to the upwards trend we saw on the "dumb bisect" on tests that were meant to be independent?

Juan or Hector, would either of you have time to look into this soon? If not, I think we may need to disable --story-filter for the system health benchmarks :(

Juan and I discussed, I'm going to try locally running a test to see if maybe we are leaking something between runs.

Thanks, Hector! Note that sometimes the results are really specific to the device and Android version. If you're able to run on a N5 flashed to KOT49H you'll have the best chance of reproing whatever is going on.

Summary of investigation so far:
Using an N5 flashed to KOT49H and restarting the phone between runs and using a recent but fixed build:

I've tried:
- Just the browse:media:facebook_photos using --story-filter pageset_repeat=4 page_repeat=1 n=3
- All of the non-loading stories pageset_repeat=4 page_repeat=1
- All of the non-loading stories pageset_repeat=1 page_repeat=4
- All of the stories pageset_repeat=3 page_repeat=3

The results for all_processes:reported_by_os:gpu_memory:proportional_resident_size_avg
are summarised here: https://screenshot.googleplex.com/Ax7kUKgoZPT.png

It looks like the very first story you run (which happens every time when using story filter) consistently
reports 1.8mb less gpu_memory:proportional_resident_size_avg than later runs.
However other than that the numbers with story-filter seem very consistent to those without.

The difference between the bisect results with and without story-filter is 1.41mb.

Normally we do story-repeat=3 so the first result being different would only shift the mean by -0.56mb so
it doesn't seem to be enough to explain the difference between with and without story-filter bisects. 

To #30: how do you define the "very first story run" here? We always close the browser & restart it between run, so it's unclear to me what that means precisely. 

Interesting result regardless, I wonder whether this is because due to the way gpu memory usage is managed.

"very first story run" is after rebooting the device

I meant that if you run tools/perf/run_benchmark run system_health.memory_mobile --pageset-repeat=x --page-repeat=y --story-filter=blah the very first story that appears on the phone screen seems to under report gpu_memory:proportional_resident_size_avg (or at least reports differently) even though we're restart the browser between each story :(

Primiano thinks maybe it is something with the driver?

Juan just mentioned that bisect runs with --page-repeat=1 so actually we hit this 'cold start' case every time when we use bisect and --story-filter.

So we looked together and here is a partial, still not conclusive, summary:
- this is NOT a flake due timing. The numbers are consistently bimodal after reboot/first run.
- there is a consistent: (i) big shift (~2 MB) both in the gl memory measured via memtrack and small shift (~100K) in the memory of the sqlite connections.

The 2nd one is the more suspicious one. The size is irrelevant, but the state of the sqlite databases should be really the same.
One theory that I have right now (hjd is checking it) is that chrome gets brought back to life by something else (e.g., Icing binding to chrome to update the bookmark and history index and sync it with Google Search), so in some cases we start with a really fresh profile and in other cases we start with a non fully fresh one.

That would explain differences in things like java-heap, sqlite and gpu (rationale for gpu: whether we have to regenerate some thumbnail or not).

- There didn't seem to be obvious evidence in logcat that Chrome was starting up in between tests.
- I extracted /data/data/org.chromium.chrome between the first and second and the second and third runs to check compare the contents of the sqlite db but couldn't immediately locate it so that needs some further investigation.  

(I'm OOO on Monday but I can continue looking on Tuesday)

Primiano, perezju and I have narrowed down the problem to the following line: [1] this line runs: "adb shell 'echo -n 3 > /proc/sys/vm/drop_caches'" at the end of each story. When that command is run (via telemetry or by hand) the next story (and only the next story) that runs reports +2 MB of GL mem as measured by memtrack. Since every story runs this command at the end this explains why we normally only observe this on the first story after rebooting.

To test I did:

* With line [1] commented out:
  - Restart phone.
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 36XX
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 36XX
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 36XX
  - Run .../adb shell ‘( echo -n 3 > /proc/sys/vm/drop_caches );echo %$?
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 55XX
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 36XX

* With line [1] as normal:
  - Restart phone.
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 36XX
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 53XX
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 54XX
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 54XX
    - while that story is running ctrl-c *once* before telemetry runs echo -n 3 > /proc/sys/vm/drop_caches
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 36XX
  - Run one story[2] and watch dumpsys meminfo GL total[3]: see 54XX

We're still thinking about why this happens...

[1]: https://cs.corp.google.com/github/catapult-project/catapult/telemetry/telemetry/internal/actions/action_runner.py?type=cs&q=p:github+f:%5Ecatapult-project+FlushEntireSystemCache&l=156
[2]: Works even with about:blank, I did .../chromium/src/tools/perf/run_benchmark run system_health.memory_mobile --story-filter=’blank:about:blank’ --pageset-repeat=1 --page-repeat=1
[3]: watch -d .../chromium/src/third_party_devil/bin/deps/linux2/x86_64/bin/adb shell dumpsys meminfo

hjd: Any update on this?

CL here: https://codereview.chromium.org/2589173004/ with lgtm. Was waiting on results of perf try jobs per comment, now they're done (see patch set #4) but I can't work out what I have to click in https://build.chromium.org/p/tryserver.chromium.perf/builders/android_nexus5_perf_bisect/builds/4494 to view the results :(

The results can be found going through the "Captured Output" logs of "Performance Test (Without Patch)", and then scrolling all the way to end until you see:

View HTML results online at https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/html-results/results-2017-01-03_07-11-30

I mentioned this is the blocking bug, we need an easier way to find the link to the final results.html :(

Unfortunately, also due to the blocking  issue 676304 , this tryjob has only a few stories and just 2 page set repeats. I've tried filtering metrics to show only "gpu_memory:proportional_resident_size", but it's unclear whether the patch is having or not the intended effect.

We could either:
- wait until  issue 676304  is resolved to run a more comprehensive try job.
- try to do some local testing to validate the change.
- land hector's CL, and see the effect it has live on perf bots.

Primiano, Annie, any thoughts?

re: #c43,#c44

Blocking on  crbug.com/670316  for the missing result link


Perf try jobs quietly broke a while ago (months? maybe longer), so although they run we don't actually parse out the info properly to display. I'm going to try fixing that this week.

Thanks Juan now I can find the link I've rerun the experiment and the results seem to be more conclusive: https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/html-results/results-2017-01-10_07-47-41

Yep, thanks! This matches a lot better what we expected to see. Let's land that CL.

Deleted: e0W5wAiML7X.png 76.6 KB

	e0W5wAiML7X.png 76.6 KB View Download

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

commit 3afb7e7da06df087b3e9fac2ae68593f75a051ed
Author: hjd <hjd@chromium.org>
Date: Thu Jan 12 17:17:54 2017

Stop bad results on first memory benchmark run

The first memory system-health story ran in a set has been reporting
memory use differently all subsequent runs. This is due to how we
flush the system caches.

Just before we measure memory we flush the system caches unfortunately
this doesn't immediately take effect, instead the next story run is
effected. Due to this the first story run has anomalous results.
This option causes us to flush caches each time before Chrome starts
so we effect even the first story - avoiding the bug.

*************** Note to Perf Sheriff ****************

Regressions across several memory metrics are
expected for system_health.memory_mobile,
system_health.memory_desktop and memory.top10_mobile
as we stop under counting memory use.

*****************************************************

BUG= chromium:671156 
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.perf:linux_perf_cq;master.tryserver.chromium.perf:mac_retina_perf_cq

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

[modify] https://crrev.com/3afb7e7da06df087b3e9fac2ae68593f75a051ed/tools/perf/benchmarks/memory.py
[modify] https://crrev.com/3afb7e7da06df087b3e9fac2ae68593f75a051ed/tools/perf/benchmarks/system_health.py

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

commit 36f123b0599822932e4c62c350448b961957c9ea
Author: xlai <xlai@chromium.org>
Date: Thu Jan 12 19:30:10 2017

Revert of Stop bad results on first memory benchmark run (patchset #8 id:140001 of https://codereview.chromium.org/2589173004/ )

Reason for revert:
Suspecting that this CL is causing many failures on benchmarks.system_health_smoke_test.SystemHealthBenchmarkSmokeTest.

Example builds:

https://build.chromium.org/p/chromium.mac/builders/Mac10.10%20Tests/builds/11962
https://build.chromium.org/p/chromium.mac/builders/Mac10.11%20Tests/builds/6323

Original issue's description:
> Stop bad results on first memory benchmark run
>
> The first memory system-health story ran in a set has been reporting
> memory use differently all subsequent runs. This is due to how we
> flush the system caches.
>
> Just before we measure memory we flush the system caches unfortunately
> this doesn't immediately take effect, instead the next story run is
> effected. Due to this the first story run has anomalous results.
> This option causes us to flush caches each time before Chrome starts
> so we effect even the first story - avoiding the bug.
>
> *************** Note to Perf Sheriff ****************
>
> Regressions across several memory metrics are
> expected for system_health.memory_mobile,
> system_health.memory_desktop and memory.top10_mobile
> as we stop under counting memory use.
>
> *****************************************************
>
> BUG= chromium:671156 
> CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.perf:linux_perf_cq;master.tryserver.chromium.perf:mac_retina_perf_cq
>
> Review-Url: https://codereview.chromium.org/2589173004
> Cr-Commit-Position: refs/heads/master@{#443273}
> Committed: https://chromium.googlesource.com/chromium/src/+/3afb7e7da06df087b3e9fac2ae68593f75a051ed

TBR=perezju@chromium.org,nednguyen@google.com,hjd@chromium.org
# Skipping CQ checks because original CL landed less than 1 days ago.
NOPRESUBMIT=true
NOTREECHECKS=true
NOTRY=true
BUG= chromium:671156 

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

[modify] https://crrev.com/36f123b0599822932e4c62c350448b961957c9ea/tools/perf/benchmarks/memory.py
[modify] https://crrev.com/36f123b0599822932e4c62c350448b961957c9ea/tools/perf/benchmarks/system_health.py

The error on the mac bots appears to be:

Failure while starting browser backend.
Traceback (most recent call last):
File "/b/s/w/ir2ny51C/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 52, in __init__
  self.platform.FlushEntireSystemCache()
File "/b/s/w/ir2ny51C/third_party/catapult/telemetry/telemetry/core/platform.py", line 179, in FlushEntireSystemCache
  return self._platform_backend.FlushEntireSystemCache()
File "/b/s/w/ir2ny51C/third_party/catapult/telemetry/telemetry/internal/platform/mac_platform_backend.py", line 180, in FlushEntireSystemCache
  p = self.LaunchApplication('purge', elevate_privilege=mavericks_or_later)
File "/b/s/w/ir2ny51C/third_party/catapult/telemetry/telemetry/internal/platform/posix_platform_backend.py", line 144, in LaunchApplication
  raise Exception(text)
Exception: Telemetry needs to run /usr/sbin/purge with elevated privileges, but the setuid bit is not set and there is no interactive terminal for a prompt. Please ask an administrator to set the setuid bit on this executable and ensure that it is owned by a user with the necessary privileges. Aborting.

Not sure why this works when we flush the system cache during the story runs? 

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

commit 212e946fe9e8ae00534fa86a4b2755bf1cf4810b
Author: catapult-deps-roller <catapult-deps-roller@chromium.org>
Date: Fri Jan 13 17:47:45 2017

Roll src/third_party/catapult/ e6b04fef1..1bcf49e0a (2 commits).

https://chromium.googlesource.com/external/github.com/catapult-project/catapult.git/+log/e6b04fef1997..1bcf49e0a7eb

$ git log e6b04fef1..1bcf49e0a --date=short --no-merges --format='%ad %ae %s'
2017-01-13 hjd [catapult] Ignore binary directories
2017-01-13 hjd [tracing] Avoid flushing system cache when not supported

BUG= 671156 

Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, see:
http://www.chromium.org/developers/tree-sheriffs/sheriff-details-chromium#TOC-Failures-due-to-DEPS-rolls

CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_optional_gpu_tests_rel
TBR=catapult-sheriff@chromium.org

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

[modify] https://crrev.com/212e946fe9e8ae00534fa86a4b2755bf1cf4810b/DEPS

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

commit 593ea0410890854382a2df7cd58400208410a89a
Author: hjd <hjd@chromium.org>
Date: Tue Jan 17 14:54:50 2017

Reland of Stop bad results on first memory benchmark run (patchset #1 id:1 of https://codereview.chromium.org/2627323002/ )

Reason for revert:
Now that the crash in telemetry Olivia stopped (thanks Olivia!) has been fixed: https://codereview.chromium.org/2623423005/ and that fix has rolled into chromium https://codereview.chromium.org/2622363009 the original patch ought to now work.

Original issue's description:
> Revert of Stop bad results on first memory benchmark run (patchset #8 id:140001 of https://codereview.chromium.org/2589173004/ )
>
> Reason for revert:
> Suspecting that this CL is causing many failures on benchmarks.system_health_smoke_test.SystemHealthBenchmarkSmokeTest.
>
> Example builds:
>
> https://build.chromium.org/p/chromium.mac/builders/Mac10.10%20Tests/builds/11962
> https://build.chromium.org/p/chromium.mac/builders/Mac10.11%20Tests/builds/6323
>
> Original issue's description:
> > Stop bad results on first memory benchmark run
> >
> > The first memory system-health story ran in a set has been reporting
> > memory use differently all subsequent runs. This is due to how we
> > flush the system caches.
> >
> > Just before we measure memory we flush the system caches unfortunately
> > this doesn't immediately take effect, instead the next story run is
> > effected. Due to this the first story run has anomalous results.
> > This option causes us to flush caches each time before Chrome starts
> > so we effect even the first story - avoiding the bug.
> >
> > *************** Note to Perf Sheriff ****************
> >
> > Regressions across several memory metrics are
> > expected for system_health.memory_mobile,
> > system_health.memory_desktop and memory.top10_mobile
> > as we stop under counting memory use.
> >
> > *****************************************************
> >
> > BUG= chromium:671156 
> > CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.perf:linux_perf_cq;master.tryserver.chromium.perf:mac_retina_perf_cq
> >
> > Review-Url: https://codereview.chromium.org/2589173004
> > Cr-Commit-Position: refs/heads/master@{#443273}
> > Committed: https://chromium.googlesource.com/chromium/src/+/3afb7e7da06df087b3e9fac2ae68593f75a051ed
>
> TBR=perezju@chromium.org,nednguyen@google.com,hjd@chromium.org
> # Skipping CQ checks because original CL landed less than 1 days ago.
> NOPRESUBMIT=true
> NOTREECHECKS=true
> NOTRY=true
> BUG= chromium:671156 
>
> Review-Url: https://codereview.chromium.org/2627323002
> Cr-Commit-Position: refs/heads/master@{#443323}
> Committed: https://chromium.googlesource.com/chromium/src/+/36f123b0599822932e4c62c350448b961957c9ea

TBR=perezju@chromium.org,nednguyen@google.com,xlai@chromium.org
# Not skipping CQ checks because original CL landed more than 1 days ago.
BUG= chromium:671156 

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

[modify] https://crrev.com/593ea0410890854382a2df7cd58400208410a89a/tools/perf/benchmarks/memory.py
[modify] https://crrev.com/593ea0410890854382a2df7cd58400208410a89a/tools/perf/benchmarks/system_health.py

Awesome!