1062055 - MSE does not recover from source decoder EOF

Status: RESOLVED WORKSFORME

(Core :: Audio/Video, defect)

Description

[cajbir (:cajbir)]

When a source decoder reaches EOF, either video or audio, there are times when the reader is switched to a new reader containing data but the RequestAudioData and RequestVideoData are no longer called. This means the new reader doesn't get data and ultimately the playback stops waiting for more.

This most often happens when seeking but can happen on other reader switches. Viewing the list of decoders in the MediaSourceReader shows there is a reader containing new data but the EOS for the old reader seems to prevent further decoding.

Comment 1

[cajbir (:cajbir)]

Here is an example from logs of what is happening. After a seek we have these buffers.

Active video reader=7f29f3f6b800
decodeTarget=79.712988

Video decoders listed in SwitchReaders were:

decoder=1 discarded=1 reader=7f29fddab000 ranges=[(0.000000, 5.006000)]
decoder=2 discarded=1 reader=7f29f33da800 ranges=[(5.005000, 10.011000)]
decoder=3 discarded=1 reader=7f29f33f2800 ranges=[(10.010000, 15.016000)]
decoder=4 discarded=1 reader=7f29f3316000 ranges=[(15.015000, 20.021000)]
decoder=6 discarded=1 reader=7f29f3f6b800 ranges=[(75.075000, 80.081000)]
decoder=7 discarded=1 reader=7f29fd0cf800 ranges=[(80.080000, 85.086000)]
decoder=8 discarded=0 reader=7f29fce16000 ranges=[(85.085000, 90.091000)]

We had just received an OnVideoEOS:

MediaSourceReader(7f29fcfb8c00)::OnVideoEOS reader=7f29f3f6b800 (readers=9)

This was due to hitting the end of decoder 6. We should then switch to decoder 7 but we can't because our decodeTarget is 79.712988 which is below the range of that decoder. decodeTarget is mTimeThreshold set on VideoDataRequested. This is never called again as we are end of stream and haven't switched.

decodeTarget would seem to be the wrong time to be using based on offline discussion with k18t and kinetik. This is behind our real decoding time. Need to investigate how to get the correct value here.

Comment 2

[Matthew Gregan [:kinetik]]

In bug 1059058, I added mLast{Audio,Video}Time, which is set to aSample->mTime + aSample->mDuration in On{Audio,Video}Decoded.  That's a pretty simple standalone change you could try without depending on all of 1059058.

Comment 3

[Matthew Gregan [:kinetik]]

There's also a potential issue where the WebMReader drops the last frame when it's trying to calculate the frame duration (possibly not hit since you implemented GetMediaEndTime).

Another possibility is to pass the end buffered range of the EOSed reader to SwitchReaders.

Comment 4

[cajbir (:cajbir)]

Raised bug 1062101 for the mSample->mDuration being wrong.

Comment 5

[cajbir (:cajbir)]

Attachment: Use end time of EOS'd decoded for switching readers

WIP patch. This uses the end time of the decoded that just reached the end of stream as the time code for switching readers. This gets past the 20s stall point in this video:

http://www.youtube.com/watch?v=3V7wWemZ_cs

And also gets past other EOS stalls that happened in the past.

Comment 6

[cajbir (:cajbir)]

Testing shows this fixes the case of where we already have a stream to that has buffered data for the new time. There are still issues where we don't have a stream to switch to and wait for data to arrive. In that case the data is appended but the RequestVideoData/OnVideoDEcded functions are never restarted. 

Investigating firing tasks to start these if we are switching away from a stream that is EOS.

Comment 7

[cajbir (:cajbir)]

Raised bug 1063323 for an issue that came up while writing tests to trigger this bug.

Comment 8

[cajbir (:cajbir)]

Comment on attachment 8483922 [details] [diff] [review]
Use end time of EOS'd decoded for switching readers

Review of attachment 8483922 [details] [diff] [review]:
-----------------------------------------------------------------

This fixes the issue where we have hit EOS on a reader but the current decoding time for switching the reader is not at the point where it can switch to a new stream. It uses the approach suggested in comment 3 to switch to the end time of the reader that hit EOS.

This allows [1] to playback completely whereas before it was getting stuck after about 20 seconds of normal playback. There are still some other EOS issues which need tracking down and debugging. I'll raise separate bugs for those.

Comment 9

[cajbir (:cajbir)]

[1] referred to in comment 8 is video in URL field.

Comment 10

[Matthew Gregan [:kinetik]]

I think this change is okay as a temporary fix, but it feels like it may be hiding a deeper bug.  A buffered range for a given decoder should report the same range that can actually be decoded, by which I mean the end time of the decoder's buffered range should be identical to the end time of the last frame decoded before reaching EOS.  Do you know why that's not the case here?

Comment 11

[cajbir (:cajbir)]

When a decode hits EOF it doesn't call the media decoder state machines On{Video,Audio}EOS method if the media stream is not endOfStream. As a result hte media decode state machines mVideoRequestPending flag is not set to false. This prevents further video/audio frames from being decoded as it things are request is still pending.

Comment 12

[Matthew Gregan [:kinetik]]

Comment on attachment 8483922 [details] [diff] [review]
Use end time of EOS'd decoded for switching readers

Clearing r? because I think bug 1064705 and bug 1064699 cover this.  We'll still need to address comment 11 somehow (either by avoiding EOS and removing the switching code from the EOS callback, or by recovering from the EOS/m{Audio,Video}RequestPending state).

Comment 13

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

Is this still an issue?

Comment 14

[cajbir (:cajbir)]

I have not seen it for some time. I'll close and we can reopen if it comes up again.