Fix an issue that audio and video may ran out of sync

Fix an issue that audio and video may ran out of sync

this is cloned from https://codereview.chromium.org/215783002/, it fixes some flaky unit test.

This CL fixes 3 issues:
1. In ProcessPendingEvents(), if there is a non-seek pending event, UpdateTimestamps() will not get called. This is probably the number 1 contributor to losing sync issue.
2. MSP use its internal clock to estmate the current presentation time. However, hardware may consume data at a different rate. Passing the current frame position from AudioTrack to MSP so we get a better estimation of the current time.
3. When config change comes, We don't need to reset the clock if audio decoder is not recreated.

BUG=351722
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=264744

[qinmin, 2014-04-15 17:33:00]

Matt, would you please take another look at this CL. 
Patch 1 is cloned from the previous codereview, patch 2 is the diff.

The flakiness is caused by that AudioTrack buffers certain amount of data before
it starts to render them.
Because we don't produce enough frames at the begining, the head_position in
PlayOutputBuffer() is always 0 for the first couple frames.
As a result, AudioDecoderJob always reports the current time as 0 to MSP. 
And this causes the flakiness as the current time is not progressing.
This patch solves that issue by decoding more data until we reach a point that
the AudioTrack starts to report non-0 head position.
When that point is reached, AudioTrack should continuously output data when ever
decoded samples are sent to it.

[wolenetz, 2014-04-15 20:40:21]

https://codereview.chromium.org/239363003/diff/20001/media/base/android/media...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/20001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:347: while (true) {
Is there a reasonable cap on number of decode iterations we should attempt
before giving up and failing here?

https://codereview.chromium.org/239363003/diff/20001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:350: if
(player_.GetCurrentTime().InMilliseconds() > 0)
I think a delta check not just > 0 here would be good. This would allow this
method to be used when initial time was already > 0.

[qinmin, 2014-04-15 21:53:04]

https://codereview.chromium.org/239363003/diff/20001/media/base/android/media...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/20001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:347: while (true) {
It takes about 5-7 frames for the AudioTrack to start rendering frames. Putting
10 as a cap here.

On 2014/04/15 20:40:22, wolenetz wrote:
> Is there a reasonable cap on number of decode iterations we should attempt
> before giving up and failing here?

https://codereview.chromium.org/239363003/diff/20001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:350: if
(player_.GetCurrentTime().InMilliseconds() > 0)
On 2014/04/15 20:40:22, wolenetz wrote:
> I think a delta check not just > 0 here would be good. This would allow this
> method to be used when initial time was already > 0.

Done.

[wolenetz, 2014-04-15 22:17:34]

lgtm % nits. Note I haven't tested this CL myself.

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:353: if
((player_.GetCurrentTime() - start_timestamp).InMilliseconds() > 0)
nit: Please add a check to ensure player current time doesn't ever go backwards
here.

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:1101:
player_.OnDemuxerDataAvailable(CreateReadFromDemuxerAckForAudio(3));
Curiousity nit: Must we feed more data prior to triggering starvation / why was
this moved prior to the trigger?

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:2106: for (int i = 0; i < 4;
++i) {
nit: DecodeAudioDataUntilAudioBufferBecomesFull() here now that it uses time
delta, not just > 0?

[qinmin, 2014-04-15 22:43:42]

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:353: if
((player_.GetCurrentTime() - start_timestamp).InMilliseconds() > 0)
On 2014/04/15 22:17:34, wolenetz wrote:
> nit: Please add a check to ensure player current time doesn't ever go
backwards
> here.

Done.

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:1101:
player_.OnDemuxerDataAvailable(CreateReadFromDemuxerAckForAudio(3));
The issue is that when AudioTrack's buffer become full, it will block the write.
Therefore, it is possible that MSP is already starved due to the block writing.
Since the starvation here is triggered purposely, it wouldn't happen in real
world if MSP is in the middle of handling a previous starvation. 


On 2014/04/15 22:17:34, wolenetz wrote:
> Curiousity nit: Must we feed more data prior to triggering starvation / why
was
> this moved prior to the trigger?

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:2106: for (int i = 0; i < 4;
++i) {
On 2014/04/15 22:17:34, wolenetz wrote:
> nit: DecodeAudioDataUntilAudioBufferBecomesFull() here now that it uses time
> delta, not just > 0?

Done.

[wolenetz, 2014-04-15 23:48:58]

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:1101:
player_.OnDemuxerDataAvailable(CreateReadFromDemuxerAckForAudio(3));
On 2014/04/15 22:43:42, qinmin wrote:
> The issue is that when AudioTrack's buffer become full, it will block the
write.
> Therefore, it is possible that MSP is already starved due to the block
writing.
> Since the starvation here is triggered purposely, it wouldn't happen in real
> world if MSP is in the middle of handling a previous starvation. 
> 
> 
> On 2014/04/15 22:17:34, wolenetz wrote:
> > Curiousity nit: Must we feed more data prior to triggering starvation / why
> was
> > this moved prior to the trigger?
> 

Hmm. Starvation could come from two directions:
One is the decoder job just being slow or blocked as you describe. The other is
that the renderer's MediaSourceDelegate/ChunkDemuxer is late in delivering
requested new data. I believe the previous sequencing was to simulate the second
source of starvation, rather than slow MediaDecoderJob. Does it matter?

[qinmin, 2014-04-16 01:48:24]

After running the test many times on a slow device, i can still sometimes see
the flakiness in CurrentTimeUpdatedWhileDecoderStarved() with PS#3.
So I am creating PS#4 to address that.

The issue is that sometimes in MSP::UpdateTimestamps(), the
current_presentation_timestamp is 0. However, when we call getCurrentTime() in
DecodeAudioDataUntilAudioBufferBecomesFull(), the returned value is larger than
0. This is possibly because message_loop_.RunUntilIdle() is not very predictable
when we call WaitForAudioDecodeDone().

Since the test only test whether MSP::UpdateTimestamps() is called after decoder
starvation, so i am modifying the test to just check whether that function is
invoked.

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/80001/media/base/android/media...
media/base/android/media_source_player_unittest.cc:1101:
player_.OnDemuxerDataAvailable(CreateReadFromDemuxerAckForAudio(3));
In the new code:
A. if DecodeAudioDataUntilAudioBufferBecomesFull() triggers a starvation
1. MSP will handle the starvation by calling MDJ::Prefetch() before reaching
OnDemuxerDataAvailable().
2. OnDemuxerDataAvailable() will finish the prefetch().
3. OnPrefetchDone() called, MSP now starts to decode new data.
4. MSP got starved again from TriggerPlayerStarvation(), however, this
starvation won't be processed until the decode completes.

B. if DecodeAudioDataUntilAudioBufferBecomesFull() does not trigger a starvation
1. OnDemuxerDataAvailable() is called first.
2. MSP got starved from TriggerPlayerStarvation();
3. OnPrefetchDone() called, MSP starts to decode new data.

In the old code:
1. MSP got starved from TriggerPlayerStarvation();
2. OnDemuxerDataAvailable() is called.
3. OnPrefetchDone() called, MSP starts to decode new data.

So the difference between case A and the old code is step 4. I think we can do a
check there to see if there is a pending prefetch_done event pending. In that
case, case A and old code should be the same.
The difference between B and the old code is that whether MDJ holds the data
before starvation happens. However, MSP should never worry about the timing when
MDJ receives the data.


On 2014/04/15 23:48:58, wolenetz wrote:
> On 2014/04/15 22:43:42, qinmin wrote:
> > The issue is that when AudioTrack's buffer become full, it will block the
> write.
> > Therefore, it is possible that MSP is already starved due to the block
> writing.
> > Since the starvation here is triggered purposely, it wouldn't happen in real
> > world if MSP is in the middle of handling a previous starvation. 
> > 
> > 
> > On 2014/04/15 22:17:34, wolenetz wrote:
> > > Curiousity nit: Must we feed more data prior to triggering starvation /
why
> > was
> > > this moved prior to the trigger?
> > 
> 
> Hmm. Starvation could come from two directions:
> One is the decoder job just being slow or blocked as you describe. The other
is
> that the renderer's MediaSourceDelegate/ChunkDemuxer is late in delivering
> requested new data. I believe the previous sequencing was to simulate the
second
> source of starvation, rather than slow MediaDecoderJob. Does it matter?

[qinmin, 2014-04-16 02:46:25]

Sorry, not PS#4, but PS#5.
in PS#5, i renamed DecodeAudioDataUntilAudioBufferBecomesFull() because it
doesn't work properly due to the above issue i mentioned. 
The function might return too early if getCurrentTime() > 0 although we pass 0
to updateTimestamps().
So now the function returns when the first time we saw the timestamp is updated
(whenever MDJ returns MEDIA_CODEC_OK)


On 2014/04/16 01:48:24, qinmin wrote:
> After running the test many times on a slow device, i can still sometimes see
> the flakiness in CurrentTimeUpdatedWhileDecoderStarved() with PS#3.
> So I am creating PS#4 to address that.
> 
> The issue is that sometimes in MSP::UpdateTimestamps(), the
> current_presentation_timestamp is 0. However, when we call getCurrentTime() in
> DecodeAudioDataUntilAudioBufferBecomesFull(), the returned value is larger
than
> 0. This is possibly because message_loop_.RunUntilIdle() is not very
predictable
> when we call WaitForAudioDecodeDone().
> 
> Since the test only test whether MSP::UpdateTimestamps() is called after
decoder
> starvation, so i am modifying the test to just check whether that function is
> invoked.

[wolenetz, 2014-04-17 21:35:27]

Thanks for helping clarify offline why there was the second source of flakiness.

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
File media/base/android/media_decoder_job.h (right):

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
media/base/android/media_decoder_job.h:34: // job skipped rendering of the
decoded output and the callback target should
This comment seems out-of-line with current MSP::MediaDecoderCallback
interpretation of current_presentation_time and kNoTimestamp(), or maybe it is
just confusing me. Please clarify whether or not MSP does (or should do) any
clock update if current_presentation_time is kNoTimestamp(). Also, does this
comment apply similarly to ReleaseOutputCompletionCB?

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
media/base/android/media_source_player_unittest.cc:369: if
(manager_.timestamp_updated())
Please also include the time delta check here. Only consider audio frames output
iff both the timestamp was updated AND new_current_time > old current time.
IIUC, the latter was previously insufficient because the clock could advance a
little even if MSP::updatetimestamp wasn't called (due to just test delays on
slower devices while waiting for successful decode with some output). But the
latter is still a requirement.

[qinmin, 2014-04-17 23:03:35]

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
File media/base/android/media_decoder_job.h (right):

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
media/base/android/media_decoder_job.h:34: // job skipped rendering of the
decoded output and the callback target should
Updated the comments.
MSP should ignore the timestsamps if kNoTimestamp is returned.
For example, if MSP's current_time is 10ms, and max_time is 30 ms, then MSP
should know that there are 20 ms seconds of audio in the audio track. If a
kNoTimestamp is returned at that moment, then MSP's internal clock should still
progress since the AudioTrack is still rendering. So MSP can just ignore the
callback.

On 2014/04/17 21:35:28, wolenetz wrote:
> This comment seems out-of-line with current MSP::MediaDecoderCallback
> interpretation of current_presentation_time and kNoTimestamp(), or maybe it is
> just confusing me. Please clarify whether or not MSP does (or should do) any
> clock update if current_presentation_time is kNoTimestamp(). Also, does this
> comment apply similarly to ReleaseOutputCompletionCB?

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
File media/base/android/media_source_player_unittest.cc (right):

https://codereview.chromium.org/239363003/diff/140001/media/base/android/medi...
media/base/android/media_source_player_unittest.cc:369: if
(manager_.timestamp_updated())
On 2014/04/17 21:35:28, wolenetz wrote:
> Please also include the time delta check here. Only consider audio frames
output
> iff both the timestamp was updated AND new_current_time > old current time.
> IIUC, the latter was previously insufficient because the clock could advance a
> little even if MSP::updatetimestamp wasn't called (due to just test delays on
> slower devices while waiting for successful decode with some output). But the
> latter is still a requirement.

Done.

[wolenetz, 2014-04-17 23:11:09]

lgtm

[qinmin, 2014-04-17 23:39:32]

The CQ bit was checked by qinmin@chromium.org

[commit-bot: I haz the power, 2014-04-17 23:40:27]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/qinmin@chromium.org/239363003/160001

[commit-bot: I haz the power, 2014-04-18 05:26:55]

Change committed as 264744