Improve audio/video sync during underflow, reduce underflow frequency.

Improve audio/video sync during underflow, reduce underflow frequency.

The current approach doesn't account for expired frames when resuming
after underflow, which means we may resume and then immediately fail
again; these frames are also out of sync with the audio playing out.
Fixing this requires several changes to the pipeline:

- TimeSource::ConvertMediaTimestamps() will now always convert timestamps,
even when time is stopped.  When time is stopped the converted values are
based on the last known media wall clock time.

- TimeSource::ConvertMediaTimestamps() will now return the current media
wall clock time when an empty timestamps vector is given; this value is
used to figure out which video frames have been played out already.

- Introduce AudioClock::CompensateForSuspendedWrites() to ensure the audio
delay value is correctly used when return the current wall clock time.

- Introduce |was_time_moving_| to VideoRendererAlgorithm to ensure the
|last_deadline_max_| value, used by RemoveExpiredFrames, is only changed
when time is ticking; otherwise the value given to RemoveExpiredFrames is
overwritten by Render() calls and EffectiveFramesQueued() will vary.

- Modifies VideoRendererImpl::FrameReady() to remove expired frames based
on the last known media wall clock time during underflow states.

Combined these changes lead to a noticeable improvement in audio/video sync
during underflow as well as a greatly reduced number of underflow events.

BUG=498525
TEST=lots of new tests.

Committed: https://crrev.com/8a047ffa05b477e148428c787e86601d21d73ce2
Cr-Commit-Position: refs/heads/master@{#333672}

[DaleCurtis, 2015-06-03 02:23:33]

dalecurtis@chromium.org changed reviewers:
+ xhwang@chromium.org

[DaleCurtis, 2015-06-03 02:23:34]

Just for discussion right now, I think this is the right path forward, but need
to think about it some more to make sure that we're not expiring frames at the
wrong time.

Take a look and lets discuss tomorrow :)

https://codereview.chromium.org/1160853006/diff/1/media/renderers/audio_rende...
File media/renderers/audio_renderer_impl.cc (right):

https://codereview.chromium.org/1160853006/diff/1/media/renderers/audio_rende...
media/renderers/audio_renderer_impl.cc:118: // Figure out how much time has
elapsed?
Perhaps we need some AudioClock::FastForward() method to handle the elapsed time
since last Render() call (which if audio underflowed, wrote nothing and didn't
advance the clock, it's only when video underflows but audio doesn't that we
really need to handle a fast forward type).

[xhwang, 2015-06-03 22:19:47]

I skimmed the code. Is the problem that during underflow, right after we
EnqueueFrames(), we could remove them in RemoveExpiredFrames() because they
don't have valid start_time? (Correct me if I am wrong.)

If so, I'd prefer not to mess up with the clocks. Can we instead choose not to
expire frames during underflow, or don't expire frames with no start_time?

I think I am still missing the big picture. Let's chat on this.

[DaleCurtis, 2015-06-04 16:47:51]

Thinking about this more, the core issue is that we want to expire frames which
relate to audio played out on the audio device prior to playback resuming.

Since underflow is a programmatic action it can happen very fast, faster than
~20ms, which means we can't just always expire everything before
back_timestamp().

Thus far we've discussed two ways of doing this:
1 - Base future time stamps on current wall clock time.
2 - Return the current media time in wall clock time to VRI, and call instead
RemoveExpiredFrames(current_media_wall_clock_time).

Item 2 will require us to either plumb a new method or re-purpose
GetWallClockTimes(<empty_vector>) as way for getting the current media time; to
avoid extra complexity there I opted for approach 1).

In either case we'll need to convert timestamps when time is stopped; I think
the right thing to do here is require that TimeSource::GetWallClockTimes()
always convert times, but return false if time is not moving. In
VRA::RemoveExpiredFrames() and VRA::UpdateFrameStatistics we'll handle the false
case slightly differently --> we'll compute frame durations and update cadence,
but avoid running the frame selection algorithm.

WDYT?

[xhwang, 2015-06-04 20:21:05]

On 2015/06/04 16:47:51, DaleCurtis wrote:
> Thinking about this more, the core issue is that we want to expire frames
which
> relate to audio played out on the audio device prior to playback resuming.
> 
> Since underflow is a programmatic action it can happen very fast, faster than
> ~20ms, which means we can't just always expire everything before
> back_timestamp().

Can you elaborate why not? Actually can you file a bug with some more details
about the problem we are trying to solve. I think I know what the problem is but
from time to time I feel I am confused.

> Thus far we've discussed two ways of doing this:
> 1 - Base future time stamps on current wall clock time.
> 2 - Return the current media time in wall clock time to VRI, and call instead
> RemoveExpiredFrames(current_media_wall_clock_time).
> 
> Item 2 will require us to either plumb a new method or re-purpose
> GetWallClockTimes(<empty_vector>) as way for getting the current media time;
to
> avoid extra complexity there I opted for approach 1).
> 
> In either case we'll need to convert timestamps when time is stopped; I think
> the right thing to do here is require that TimeSource::GetWallClockTimes()
> always convert times, but return false if time is not moving.

The question is, in this case, what wall clock time should we return?

> In
> VRA::RemoveExpiredFrames() and VRA::UpdateFrameStatistics we'll handle the
false
> case slightly differently --> we'll compute frame durations and update
cadence,
> but avoid running the frame selection algorithm.
> 
> WDYT?

Currently when we expire frames, we call:

algorithm_->RemoveExpiredFrames(tick_clock_->NowTicks());

Note that we are using "Now". This totally makes sense when the time is moving.
But when the time source is not ticking, this looks odd. It seems (2)
could solve this issue, but I agree that requires a new API, something like
GetReferenceWallClockTime() or GetMediaWallClockTime().

Your proposal seems good to me though I don't fully understand the detail of
your proposal.

Actually the time source knows whether a media time is before
 or after the base media time. In GetWallClockTimes(), can we return invalid
wall clock time for media times that are before the base media time so that
we can expire them immediately. Then return valid wall clock time for media
times that are after the base media time, based on the last reference time:
we will not expire these frames. Then when we start to tick again, we'll
always update the wallclock times on all queued frames anyways.

[DaleCurtis, 2015-06-06 02:07:22]

Updated to use current media time, still needs some more tests, but is in good
enough shape to review.

[DaleCurtis, 2015-06-06 17:17:15]

Had to run last night before I could offer a summary.  There are three issues I
discovered while doing this underflow analysis, the one deadlock issue you saw
previously ( http://crbug.com/496466 ) and the following:

1) Wall clock time starts moving too early in the audio renderer, this is a
regression, previously media time wouldn't change until the first Render() call
after stoppage, currently it resumes as soon as StartTicking() or
SetPlaybackRate() is called again.  I suspect this is the root cause of
http://b/21474258

The |stop_renderering_time_| updates address this and I'm going to split them
into another smaller CL so that we might have a chance to merge them back to
M43.

2) We don't remove frames which are related to audio which are already played
out to the device during underflow, resulting in audio/video sync issues over
time and increasing the likelihood of underflow.  Fixing this requires the
AudioClock, TimeSource, and RemoveExpiredFrames changes.

I'll split these CLs on Monday.

[xhwang, 2015-06-08 19:48:24]

LG. This approach is much cleaner!

I'll do another review after you finish all the tests and rebase this on other
CLs.

https://codereview.chromium.org/1160853006/diff/60001/media/base/time_source.h
File media/base/time_source.h (right):

https://codereview.chromium.org/1160853006/diff/60001/media/base/time_source....
media/base/time_source.h:58: // time as a wall clock time.
"last media time update" and "the current media time as a wall clock time"
aren't easy to understand without looking into implementation details. Maybe we
can introduce a concept of "last wall clock time" (LWCT) or something similar,
which is the wall clock time corresponding to the last media update. Then we
could have:
1. if time is stopped, timestamps will be converted relative to the LWCT, and
2. passing in an empty |media_timestamps| will return the LWCT.

hmm, I am not super happy with the above wording either, just some idea for
improvement...

https://codereview.chromium.org/1160853006/diff/60001/media/filters/audio_clo...
File media/filters/audio_clock.cc (right):

https://codereview.chromium.org/1160853006/diff/60001/media/filters/audio_clo...
media/filters/audio_clock.cc:88: // Flush buffered frames up to to capacity and
update cached timestamps.
s/to to/to/

https://codereview.chromium.org/1160853006/diff/60001/media/renderers/video_r...
File media/renderers/video_renderer_impl.cc (right):

https://codereview.chromium.org/1160853006/diff/60001/media/renderers/video_r...
media/renderers/video_renderer_impl.cc:515: if (was_background_rendering_ ||
nit: now read this again, shouldn't this be |is_background_rendering_|?

[DaleCurtis, 2015-06-09 01:09:16]

Patchset #5 (id:80001) has been deleted

[DaleCurtis, 2015-06-09 01:14:45]

Patchset #5 (id:100001) has been deleted

[DaleCurtis, 2015-06-09 02:17:40]

Okay cleaned up and added tests for everything.  I'm still running the numbers
locally, but I think the stop rendering time fix has the biggest impact on
underflow frequency, the rest of these changes mostly just improve the a/v sync
-- which is nice, but less than I expected, so I need to double check the
numbers tomorrow.

https://codereview.chromium.org/1160853006/diff/60001/media/base/time_source.h
File media/base/time_source.h (right):

https://codereview.chromium.org/1160853006/diff/60001/media/base/time_source....
media/base/time_source.h:58: // time as a wall clock time.
On 2015/06/08 19:48:24, xhwang wrote:
> "last media time update" and "the current media time as a wall clock time"
> aren't easy to understand without looking into implementation details. Maybe
we
> can introduce a concept of "last wall clock time" (LWCT) or something similar,
> which is the wall clock time corresponding to the last media update. Then we
> could have:
> 1. if time is stopped, timestamps will be converted relative to the LWCT, and
> 2. passing in an empty |media_timestamps| will return the LWCT.
> 
> hmm, I am not super happy with the above wording either, just some idea for
> improvement...

Actually I think we can just drop most of this text as it's an implementation
detail.  It's natural to assume that whether time is moving or not, timestamps
will be converted relative to the last known value.  I've left the API change,
but deleted additional helper text.

https://codereview.chromium.org/1160853006/diff/60001/media/filters/audio_clo...
File media/filters/audio_clock.cc (right):

https://codereview.chromium.org/1160853006/diff/60001/media/filters/audio_clo...
media/filters/audio_clock.cc:88: // Flush buffered frames up to to capacity and
update cached timestamps.
On 2015/06/08 19:48:24, xhwang wrote:
> s/to to/to/

Done.

https://codereview.chromium.org/1160853006/diff/60001/media/renderers/video_r...
File media/renderers/video_renderer_impl.cc (right):

https://codereview.chromium.org/1160853006/diff/60001/media/renderers/video_r...
media/renderers/video_renderer_impl.cc:515: if (was_background_rendering_ ||
On 2015/06/08 19:48:24, xhwang wrote:
> nit: now read this again, shouldn't this be |is_background_rendering_|?

We don't have an |is_background_rendering_| only |was_background_rendering_|
since it happens on another thread.

[xhwang, 2015-06-09 22:26:00]

lgtm, I only have a few nits.

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
File media/filters/video_renderer_algorithm.cc (right):

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
media/filters/video_renderer_algorithm.cc:75: was_time_moving_ =
UpdateFrameStatistics();
Can we set was_time_moving_ in UpdateFrameStatistics() directly? It's a bit odd
that we ignore the return value in l.249, where we could have known a better
value for was_time_moving_.

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
media/filters/video_renderer_algorithm.cc:77: if (!was_time_moving_ ||
!have_known_duration) {
I found it easier to read to have:

if (!(was_time_moving_ && have_known_duration))

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
File media/filters/video_renderer_algorithm.h (right):

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
media/filters/video_renderer_algorithm.h:122: void time_stopped() {
was_time_moving_ = false; }
It's easy to misread this as was_time_stopped()...Use a verb to make it clear?
e.g. StopTime() or NotifyTimeStopped().

[DaleCurtis, 2015-06-09 22:52:49]

Thanks for review!

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
File media/filters/video_renderer_algorithm.cc (right):

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
media/filters/video_renderer_algorithm.cc:75: was_time_moving_ =
UpdateFrameStatistics();
On 2015/06/09 22:26:00, xhwang wrote:
> Can we set was_time_moving_ in UpdateFrameStatistics() directly? It's a bit
odd
> that we ignore the return value in l.249, where we could have known a better
> value for was_time_moving_.

Done. Removed the return value from UpdateFrameStatistics() too.

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
media/filters/video_renderer_algorithm.cc:77: if (!was_time_moving_ ||
!have_known_duration) {
On 2015/06/09 22:26:00, xhwang wrote:
> I found it easier to read to have:
> 
> if (!(was_time_moving_ && have_known_duration))

Done.

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
File media/filters/video_renderer_algorithm.h (right):

https://codereview.chromium.org/1160853006/diff/120001/media/filters/video_re...
media/filters/video_renderer_algorithm.h:122: void time_stopped() {
was_time_moving_ = false; }
On 2015/06/09 22:26:00, xhwang wrote:
> It's easy to misread this as was_time_stopped()...Use a verb to make it clear?
> e.g. StopTime() or NotifyTimeStopped().

Used set_time_stopped().

[DaleCurtis, 2015-06-09 22:52:58]

The CQ bit was checked by dalecurtis@chromium.org

[DaleCurtis, 2015-06-09 22:52:58]

The patchset sent to the CQ was uploaded after l-g-t-m from xhwang@chromium.org
Link to the patchset: https://codereview.chromium.org/1160853006/#ps140001
(title: "Comments.")

[commit-bot: I haz the power, 2015-06-09 22:56:00]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1160853006/140001

[commit-bot: I haz the power, 2015-06-10 00:31:32]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2015-06-10 00:31:33]

Try jobs failed on following builders:
  linux_android_rel_ng on tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_android_r...)

[DaleCurtis, 2015-06-10 00:32:22]

The CQ bit was checked by dalecurtis@chromium.org

[commit-bot: I haz the power, 2015-06-10 00:38:19]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1160853006/140001

[commit-bot: I haz the power, 2015-06-10 03:18:06]

Committed patchset #6 (id:140001)

[commit-bot: I haz the power, 2015-06-10 03:18:56]

Patchset 6 (id:??) landed as
https://crrev.com/8a047ffa05b477e148428c787e86601d21d73ce2
Cr-Commit-Position: refs/heads/master@{#333672}