1041374 - Seeking on YouTube demo player feelings_vp9 example fails intermittently with audio working

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[cajbir (:cajbir)]

YouTube demo player playing the 'feelings_vp9' sample fails to seek.

Steps to reproduce:

1) With mse enabled
2) Visit http://cd.pn/mse/ytdemo/dash-player.html?url=http://cd.pn/mse/ytdemo/feelings_vp9-20130806-manifest.mpd.
3) Seek somewhere once it starts playing.

Expected result:

4) Seek works

Actual result:

5) Seek fails and error displayed is "Video can't be played because the file is corrupt"

The other VP9 demo files work fine. This could be related to 'feelings_vp9' having an audio track.

Comment 1

[cajbir (:cajbir)]

Attachment: Fix

Handle active audio stream being discarded during seek by switching to new audio stream with correct time range. This fixes the issue and allows the video in URL to work.

Comment 2

[Matthew Gregan [:kinetik]]

Comment on attachment 8466863 [details] [diff] [review]
Fix

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

::: content/media/mediasource/MediaSourceDecoder.cpp
@@ +203,5 @@
>      SWITCH_OPTIONAL,
>      SWITCH_FORCED
>    };
>  
>    bool SwitchVideoReaders(SwitchType aType) {

Rename this to SwitchReaders and add a way to signal which readers changed (e.g. for OnVideoEOS), and add the same code to OnAudioEOS.

@@ +224,5 @@
> +          mDropVideoBeforeThreshold = true;
> +          switched = true;
> +          MSE_DEBUG("%p MSR::SwitchVideoReaders(%d) switching to video %d", this, aType, mActiveVideoDecoder);
> +        }
> +        if (decoder->GetReader()->GetMediaInfo().HasAudio()) {

Check that the rate and channels of the new audio reader match the current one before switching to it, and add a comment/log message for the unhandled case of a mismatch.

Comment 3

[Matthew Gregan [:kinetik]]

Attachment: Handle audio decoder resets from a SourceBuffer by switching to the new audio decoder.

I ended up rebasing this while testing and debugging.  Apologies for stealing your bug!

Comment 4

[cajbir (:cajbir)]

Comment on attachment 8474959 [details] [diff] [review]
Handle audio decoder resets from a SourceBuffer by switching to the new audio decoder.

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

Previous review comment requested that SwitchReaders "add a way to signal which readers changed". I don't see this in this patch. 

Video still does not seek with this patch or my equivalent rebased patch which is why I hadn't uploaded it. To get seeking working on the example URL I also need to revert bug 1052239 and bug 1049327. Bug 1052239 fixed the thread assertion and allowed playback in the single stream case but not for multiple streams. The patch in this bug used to work until bug 1049327 landed but unfortunately still does not work with bug 1052239.

::: content/media/mediasource/MediaSourceReader.cpp
@@ +195,5 @@
> +      if (readerInfo.HasAudio() &&
> +          audioInfo.mRate == readerInfo.mAudio.mRate &&
> +          audioInfo.mChannels == readerInfo.mAudio.mChannels &&
> +          reader != GetAudioReader()) {
> +        GetAudioReader()->SetIdle();

The GetVideoReader() call below has a null check. Does GetAudioReader() here need one?

Comment 5

[cajbir (:cajbir)]

With this patch and patch in bug 1054970 applied the crash I get the following when seeking, intermittently:

1) Audio seeks and continues but video freezes.
2) Crash in assertion MediaDataDecodedListener.h line 30 (aTaskQueue is null)

Comment 6

[Matthew Gregan [:kinetik]]

(In reply to cajbir (:cajbir) from comment #4)
> Previous review comment requested that SwitchReaders "add a way to signal
> which readers changed". I don't see this in this patch. 

It's not needed for now, so I decided not to do it.

> Video still does not seek with this patch or my equivalent rebased patch
> which is why I hadn't uploaded it.

It doesn't claim to fix all seeking isues, just handle picking up the correct audio decoder after a SourceBuffer reset, which is what the original bug/patch was about as far as I understood.  Is that not the case?

> The GetVideoReader() call below has a null check. Does GetAudioReader() here
> need one?

Yes.

Comment 7

[Matthew Gregan [:kinetik]]

(In reply to cajbir (:cajbir) from comment #5)
> 2) Crash in assertion MediaDataDecodedListener.h line 30 (aTaskQueue is null)

File a new bug with a stack please.

Comment 8

[cajbir (:cajbir)]

(In reply to Matthew Gregan [:kinetik] from comment #7)
> 
> File a new bug with a stack please.

I will next time it happens.

> which is what the original bug/patch was about as far as I understood.

Original bug is to fix the STR. Fixing the audio switch originally fixed the bug but now it does not. We are close though. Currently I'm tracking down why the video stops after the seek but the audio continues. All the video tracks are discarded.

If you prefer we can spin off a separate bug for the switching of the audio to land the patch.

Comment 9

[cajbir (:cajbir)]

(In reply to cajbir (:cajbir) from comment #8)
> Currently I'm tracking down
> why the video stops after the seek but the audio continues. All the video
> tracks are discarded.

It looks like this is due to some race condition involving ReadMetadata in the InitializePendingDecoders method of MediaSourceReader. The video doesn't resume play because InitializePendingDecoders seems to hang when processing the pending video decoder. If I add debug printf to this method the timing changes and playback works.

Comment 10

[cajbir (:cajbir)]

Comment on attachment 8474959 [details] [diff] [review]
Handle audio decoder resets from a SourceBuffer by switching to the new audio decoder.

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

::: content/media/mediasource/MediaSourceReader.cpp
@@ +60,3 @@
>      return;
>    }
>    GetAudioReader()->RequestAudioData();

Do we need a SwitchReaders call before this like we have for RequestVideoData?

Comment 11

[Matthew Gregan [:kinetik]]

(In reply to cajbir (:cajbir) from comment #8)
> I will next time it happens.

I've found it via code inspection, I'll file and post a patch soon.

(In reply to cajbir (:cajbir) from comment #9)
> It looks like this is due to some race condition involving ReadMetadata in
> the InitializePendingDecoders method of MediaSourceReader. The video doesn't
> resume play because InitializePendingDecoders seems to hang when processing
> the pending video decoder. If I add debug printf to this method the timing
> changes and playback works.

That might be the same bug Karl is working on in bug 1041396.

(In reply to cajbir (:cajbir) from comment #10)
> Do we need a SwitchReaders call before this like we have for
> RequestVideoData?

Yep, good catch.

Comment 12

[Matthew Gregan [:kinetik]]

(In reply to cajbir (:cajbir) from comment #8)
> If you prefer we can spin off a separate bug for the switching of the audio
> to land the patch.

Bug 1055899.

Comment 13

[cajbir (:cajbir)]

With bug 1055899 applied I've changed this bug to the new behaviour which is that after the seek completes the audio will continues from the seek point while the video playback stops. Occasionally the video will work so this seems to be some intermittent condition. This may be caused by bug 1041396. 

The same issue happens when seeking on a YouTube WebM video. If I disable the audio track code then YouTube video seeks fine so I'm thinking this is the main cause of YouTube not seeking at the moment.

Comment 14

[cajbir (:cajbir)]

Comparing logs of a run where the seek worked and video played vs where one didn't showed that the latter had OnVideoEOS called.

It appears that when  the seek completes sometimes the resource containing the video ends and is detected as being end of stream by MediaDecoderReader::RequestVideoData before the new SourceBuffer containing the new video stream is processed. This results in MediaDecoderReader tearing down the video decoding side of things and there is no capability for it to be restarted. This is why the video freezes.

Unfortunately the code that detects and handles the end of stream is not overrideable that I can see so will need to make changes to the current decoding engine.

I will investigate more tomorrow.

Comment 15

[cajbir (:cajbir)]

Raised bug 1058364 for the issue mentioned in comment 14.

Comment 16

[cajbir (:cajbir)]

With the fix in bug 1058364 we get a hang when seeking in SourceBufferResource::Read due to a mon.Wait() for more data.

This is caused by the new stream only having 234 bytes of data. In MediaSourceReader::initializePendingDecoders we call ReadMetadata on the reader. This gets libnestegg to read the metadata and blocks as in that Read call as nestegg reads beyond the 234 bytes to get additional data other than the metadata.

If I change WebMReader::ReadMetadata so that the maximum offset passed to nestegg's init function is 234 bytes then the 'feelings9' version of the YouTube demo play seeks and plays. This seems to indicate that the blocking here is the final issue in getting seeking to work.

The question is why does the block in the SourceBufferResource::Read call prevent additional data from being appended thus freeing up the mon.Wait(). Investigating that now.

Comment 17

[cajbir (:cajbir)]

The deadlock is occurring due to:

a) SourceBuffer::AppendData schedules the state machine. This waits on the media decoder monitor thus block the main thread. This occurs before it notifies the SourceBufferResources that are waiting on data that the data has arrived.

b) SourceBufferResource::Read waits on the monitor for more data. But the thread it is waiting on has the media decoder monitor held. It will never receive the notification as the thread it is waiting on is blocked.

The thread in (b) has the media decoder monitor held through calling MediaSourceReader::SwitchReaders. This then calls MediaSourceReader::InitializePendingDecoders which holds the lock a second time. Later in that method it uses ReentrantMonitorAutoExit to release the lock and call ReadMetadata which ends up in the Read call in (b). It seems that if the monitor is recursively held more than once then usage of ReentrantMonitorAutoExit only exits the one hold on the lock. The lock is in fact still held in this case.

If I place the lock attempt in SwitchReaders after the call to InitializePendingDecoders then the deadlock no longer occurs and seeking works in the youtube demo app with feelings_vp9.

Comment 18

[cajbir (:cajbir)]

Attachment: Fix deadlock in MSE reading vs data adding

Comment 19

[cajbir (:cajbir)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2fc1d14dee3e

Comment 20

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/2fc1d14dee3e

Comment 21

[cajbir (:cajbir)]

Reopened as it requires fixes to be completed in bug 1044498 to work. The patches landed here were tested by reverting those in that bug that have already landed.

Comment 22

[cajbir (:cajbir)]

See bug 1040552 comment 9 for the bugs that fix this.

Comment 23

[Matthew Gregan [:kinetik]]

I think this can be closed now that the set of changes listed in bug 1040552 comment 9 has landed, ni? cajbir to double check.

Comment 24

[cajbir (:cajbir)]

Yes, can be closed.

Comment 25

[vasilicamihasca]

This bug is still reproducible on Nightly 35.0a1 (2014-10-07) using Ubuntu 12.04 x64.

[bugday-20141008]

Comment 26

[Matthew Gregan [:kinetik]]

(In reply to vasilicamihasca from comment #25)
> This bug is still reproducible on Nightly 35.0a1 (2014-10-07) using Ubuntu
> 12.04 x64.
> 
> [bugday-20141008]

You're possibly seeing bug 1078118, a recent regression for which a fix was pushed just now and should be in the next nightly.

Comment 27

[vasilicamihasca]

(In reply to Matthew Gregan [:kinetik] from comment #26)
> (In reply to vasilicamihasca from comment #25)
> > This bug is still reproducible on Nightly 35.0a1 (2014-10-07) using Ubuntu
> > 12.04 x64.
> > 
> > [bugday-20141008]
> 
> You're possibly seeing bug 1078118, a recent regression for which a fix was
> pushed just now and should be in the next nightly.

I'm not quite sure what should be fixed in which bug. Maybe these two scenarios I used to reproduce the bug will clear things out a bit:

1. Move the seek bar forward and back for a few times within buffered zone -->  Audio playback will continue from the seek point while the video stops.
2. Play the video without interacting in any other way with the controls --> The movie will have temporary break at 00:00:29 and will permanently stop at the minute 00:01:50.

As previously mentioned, testing was performed across all platforms, this time using Nightly 35.0a1 (2014-10-09).