Kicked off a bisect on the CPU time graph, which wasn't offline while the BattOrs were.

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

Started another bisect: https://chromeperf.appspot.com/buildbucket_job_status/8997832029142527200

Bisect failed: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1763
Failure reason: the build has failed.
Additional errors:
The metric was not found in the test output.
Either of the initial "good" or "bad" revisions failed to be tested or built.

Gah: it looks like this is due to a failing BattOr:

@@@STEP_LOG_LINE@Failure Output@Traceback (most recent call last):@@@
@@@STEP_LOG_LINE@Failure Output@  File "/b/c/b/mac_retina_perf_bisect/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py", line 78, in _RunStoryAndProcessErrorIfNeeded@@@
@@@STEP_LOG_LINE@Failure Output@    test.WillRunStory(state.platform)@@@
@@@STEP_LOG_LINE@Failure Output@  File "/b/c/b/mac_retina_perf_bisect/src/third_party/catapult/telemetry/telemetry/web_perf/timeline_based_measurement.py", line 282, in WillRunStory@@@
@@@STEP_LOG_LINE@Failure Output@    platform.tracing_controller.StartTracing(self._tbm_options.config)@@@
@@@STEP_LOG_LINE@Failure Output@  File "/b/c/b/mac_retina_perf_bisect/src/third_party/catapult/telemetry/telemetry/core/tracing_controller.py", line 43, in StartTracing@@@
@@@STEP_LOG_LINE@Failure Output@    self._tracing_controller_backend.StartTracing(tracing_config, timeout)@@@
@@@STEP_LOG_LINE@Failure Output@  File "/b/c/b/mac_retina_perf_bisect/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_controller_backend.py", line 91, in StartTracing@@@
@@@STEP_LOG_LINE@Failure Output@    if agent.StartAgentTracing(config, timeout):@@@
@@@STEP_LOG_LINE@Failure Output@  File "/b/c/b/mac_retina_perf_bisect/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/battor_tracing_agent.py", line 73, in StartAgentTracing@@@
@@@STEP_LOG_LINE@Failure Output@    self._battor.StartTracing()@@@
@@@STEP_LOG_LINE@Failure Output@  File "/b/c/b/mac_retina_perf_bisect/src/third_party/catapult/common/battor/battor/battor_wrapper.py", line 155, in StartTracing@@@
@@@STEP_LOG_LINE@Failure Output@    self._SendBattorCommand(self._START_TRACING_CMD)@@@
@@@STEP_LOG_LINE@Failure Output@  File "/b/c/b/mac_retina_perf_bisect/src/third_party/catapult/common/battor/battor/battor_wrapper.py", line 270, in _SendBattorCommand@@@
@@@STEP_LOG_LINE@Failure Output@    'Outputted: %s' % (cmd, status))@@@
@@@STEP_LOG_LINE@Failure Output@BattorError: BattOr did not complete command 'StartTracing' correctly.@@@
@@@STEP_LOG_LINE@Failure Output@Outputted: [1025/044818:FATAL:battor_agent_bin.cc(88)] Fatal error when communicating with the BattOr: TIMEOUT@@@

rnephew@, it looks like this BattOr is displaying all of the symptoms of having a bad SD card. Could you replace the SD card on this bisector when you're in the lab?

SDCard is switched out.

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

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

Thanks Randy!

Looking back up at the bisect that failed, it appears that it's the BattOr bisect and not the CPU time bisect. The BattOrs were offline when this regression happened, so narrowing down the revision range of the culprit isn't really possible with their data. However, the cpu_time metric was online then, so we can use that to identify the revision range. This graph (https://chromeperf.appspot.com/report?sid=8f9feb67447e8b0c8dcb998826375ed7e4fa2e710fe326cb84d6124260846059) suggests that the revision is clearly visible for the YouTube story in battor.power_cases for both the cpu_time_percentage_avg metrics and the idle:power_avg metrics. The cpu_time_percentage_avg metric suggests that the culprit is between 425753 and 426756.

I'm going to kick off bisects using both the CPU time metric and the power metric just to see what happens: I want to make sure that they find the same culprit.

Bisect failed: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1780
Failure reason: the build has failed.
Additional errors:
The metric was not found in the test output.
Either of the initial "good" or "bad" revisions failed to be tested or built.

Bisect failed: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1779
Failure reason: the build has failed.
Additional errors:
The metric was not found in the test output.
Either of the initial "good" or "bad" revisions failed to be tested or built.

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

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

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


===== TESTED REVISIONS =====
Revision         Mean     Std Dev  N  Good?
chromium@426756  44.0268  1.18358  5  bad

Bisect job ran on: mac_retina_perf_bisect
Bug ID: 658840

Test Command: src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=youtube battor.power_cases
Test Metric: idle:power_avg/https___www.youtube.com_watch?v_3KANI2dpXLw?autoplay_1
Relative Change: None
Score: 0

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1782
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8997159303725899680


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

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

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

Hi chcunningham@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 : AudioRendererImpl: Don't advance time when rendering stops.
Author  : chcunningham
Commit description:
  
This is a quick work-around for the bug below. AudioRendererImpl was
recently improved to estimate time's advancing along the last rendered
audio buffer between Render() calls. This means the clock is capable of
still advancing a bit after OnBufferingStateChange indicates we've run
out of data. While tehcnically correct, the clocks advancing causes
blink to emit 'timeupdate' events with time advancing after emitting
'waiting' indicating that no data is buffered. This change stops the
clock once the render has underflowed.

Longterm, blink should be improved to gaurd against emitting timeupdate
after waiting. This larger change will be done separately to give it
time to bake. https://codereview.chromium.org/2425463002/

BUG=648710

Review-Url: https://codereview.chromium.org/2423903003
Cr-Commit-Position: refs/heads/master@{#425871}
Commit  : 9409db28cd7402d4bad8022afbd2b3719de72d08
Date    : Tue Oct 18 02:52:22 2016


===== TESTED REVISIONS =====
Revision         Mean      Std Dev     N  Good?
chromium@425753  0.38178   0.010476    5  good
chromium@425816  0.384519  0.00708323  5  good
chromium@425848  0.390471  0.00582243  5  good
chromium@425864  0.388641  0.010221    5  good
chromium@425868  0.386066  0.00563752  5  good
chromium@425870  0.382842  0.0071985   5  good
chromium@425871  0.423561  0.00692994  5  bad    <--
chromium@425872  0.423982  0.00409352  5  bad
chromium@425879  0.429715  0.00756735  5  bad
chromium@426004  0.418721  0.00610292  5  bad
chromium@426255  0.413556  0.00863387  5  bad
chromium@426756  0.414428  0.00468104  5  bad

Bisect job ran on: mac_retina_perf_bisect
Bug ID: 658840

Test Command: src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=youtube battor.power_cases
Test Metric: cpu_time_percentage_avg/https___www.youtube.com_watch?v_3KANI2dpXLw?autoplay_1
Relative Change: 8.55%
Score: 99.9

Buildbot stdio: http://build.chromium.org/p/tryserver.chromium.perf/builders/mac_retina_perf_bisect/builds/1781
Job details: https://chromeperf.appspot.com/buildbucket_job_status/8997159365394589824


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

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

:D this is surprising. The change referenced adds a handful of comparisons to a fairly hot path. I don't think these could really regress this metric, but fortunately we get to find out because this CL is about to be reverted (replaced by: https://codereview.chromium.org/2425463002/).

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

commit a7f938399ef9a6d7c2f804848ac815bc4ba3e48a
Author: chcunningham <chcunningham@chromium.org>
Date: Thu Nov 03 17:43:11 2016

Improve HTMLMediaElement::currentTime()

This CL introduces "current/official playback position" concepts
from the spec. currentTime will return official playback position
and will not advance while scripts are running. I've also removed
old notions of cached time that were increasingly difficult to
maintain.

This change also prevents the advancing of currentTime (and
associated timeupdate events) while 'waiting' for more data. The
underlying media pipeline may slightly advance the clock after
signalling underflow, but we should conceal this in blink to avoid
sending a mixed signal about the state of playback. This was
previously accomplished in audio_renderer_impl.cc, but can now be
moved to blink with the currentTime cleanup.

TEST=blink layout tests, especially media/video-play-stall.html
BUG=648710, 658840 

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

[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/media/renderers/audio_renderer_impl.cc
[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/media/renderers/audio_renderer_impl.h
[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/media/renderers/audio_renderer_impl_unittest.cc
[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/third_party/WebKit/LayoutTests/http/tests/media/video-buffered-range-contains-currentTime.html
[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/third_party/WebKit/LayoutTests/http/tests/media/video-seek-to-middle.html
[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/third_party/WebKit/Source/core/html/HTMLMediaElement.cpp
[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/third_party/WebKit/Source/core/html/HTMLMediaElement.h
[modify] https://crrev.com/a7f938399ef9a6d7c2f804848ac815bc4ba3e48a/third_party/WebKit/Source/modules/mediasource/SourceBuffer.cpp

The suspected CL is now reverted by the new CL in comment #17. Lets see if the graphs come back down.

The Mac builder used to supply the binaries for our Mac perf tests is slighty behind: I'm going to make a note to myself to swing back around and take a look at this early next week.

Hi Chris,

It doesn't appear that the CL made any appreciable difference :-/

https://chromeperf.appspot.com/report?sid=3a155acd089afdf47bb3b405052fec6b48d7b50c9c6291fe97949180ee4213b7&start_rev=421483&end_rev=430930&rev=426756

I agree. I think my CL was likely not responsible. The later CL completely reverts the original. It adds some new logic to HTMLMediaElement, but this is very light performance wise. 

I'm closing this as WontFix after doing some manual tracing.

I synced to the last known good CL, 704feb5, recorded a power trace while watching a YouTube video, and saw that we were consuming about 14.5W on average to watch the video.

Then I synced to the known bad CL, b6ce161, did the same, and saw that we were still consuming between 14.5W and 15.5W on average to watch the video.

I suspect that this "regression" has more to do with the metrics that we were using at the time than the performance of Chrome. At this time, we were reporting idle:power_avg as the average of the average powers for each idle period in the trace. This means that, if there were a .001s idle interval where we consumed 1000W and a 10s idle interval where we consumed 1W, the idle:power_avg metric would report as (1W + 1000W) / 2 ~~ 500W, instead of the much lower true idle:power_avg of 1.09W. This was changed in https://codereview.chromium.org/2441883002, which was submitted after this regression.

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

=== BISECT JOB RESULTS ===
NO Perf regression found, tests failed to produce values

Bisect Details
  Configuration: mac_retina_perf_bisect
  Benchmark    : battor.power_cases
  Metric       : idle:power_avg/https___www.youtube.com_watch?v_3KANI2dpXLw?autoplay_1

Revision             Result                  N
chromium@426756      19.8607 +- 1.70735      21      bad

To Run This Test
  src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests --story-filter=youtube battor.power_cases

Debug Info
  https://chromeperf.appspot.com/buildbucket_job_status/8982667494842573872

Is this bisect wrong?
  https://chromeperf.appspot.com/bad_bisect?try_job_id=4959488266731520


| 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 Speed>Bisection.  Thank you!